Search

Top 60 Oracle Blogs

Recent comments

Oakies Blog Aggregator

Where does the log writer spend its time on?

The Oracle database log writer is the process that fundamentally influences database change performance. Under normal circumstances the log writer must persist the changes made to the blocks before the actual change is committed. Therefore, it’s vitally important to understand what the log writer is exactly doing. This is widely known by the Oracle database community.

The traditional method for looking at log writer performance is looking at the wait event ‘log file parallel write’ and the CPU time, and comparing that to the ‘log file sync’ alias “commit wait time”. If ‘log file parallel write’ and ‘log file sync’ roughly match, a commit is waiting on the log writer IO latency, if it isn’t then it’s unclear, and things get vague.

Now we get to the gist of this blogpost: since Oracle 12, there are additional statistics in V$SESSTAT and v$SYSSTAT that describe where the log writer spending it’s time on. However, and sadly, these are not documented by Oracle. The statistics are:

– redo write gather time
– redo write schedule time
– redo write finish time
– redo write time (usec)
– redo write total time

Probably ‘redo write time (usec)’ doesn’t belong to these statistics because the timing is as good as the same as ‘redo write finish time’. Also the statistic ‘redo write time (usec)’ is updated by ‘kcrfw_postprocess_write’ right after the main writing function (kcrfw_do_write), whilst the other redo write timing statistics are updated/made visible by ksu_dispatch_tac outside of the actual writing functions, at the approximate rate of every 3 seconds.

All these statistics contain cumulative timing figure in microseconds (usec).

All these timings start at the start of the function kcrfw_redo_write_driver. This is the main function that handles all the redo writing, including investigating the fixed area structure (kcrfs_) and the shared pool structures (made visible using X$KCRFSTRAND) to see if there are changes.

1. redo write gather time.
This times reading the structures that control allocation of the redo structures, validating foreground processes are done writing the change vectors and applying these to the blocks, updating the LWN SCN. Part of this also happens when there is nothing to write, but then the time is not added to this statistic, only if it found something to write.

2. redo write schedule time.
This includes the time of 1, but now it found something to write, entered the writing function (kcrfw_do_write), and updated the ksfd IO related structures for writing.

3. redo write finish time.
This includes the time of 1 and 2, but this additionally times all the IO related functions for writing the changes it found in the public redo strands, as indicated by the shared pool and fixed area structures.

4. redo write time (usec).
This probably is not part of this group of statistics, but it works in exactly the same way: it’s a cumulative figure, it counts time since the start of the kcrfw_redo_write_driver and includes a tiny bit more code, it times until it has left the kcrfw_do_write function and enters the kcrfw_postprocess_write function.

5. redo write total time.
This includes the time of 1, 2 and 3, but additionally times the kcrfw_post function, which performs the signalling of the foreground processes that have committed and wait for a semop() signal.

This means that the Oracle database since Oracle 12 provides the timing information to see where the log writer is spending it’s time on. This can prevent a lot of guesswork.

push_having_to_gby()

I came across an interesting new hint recently when checking the Outline Data for an execution plan: /*+ push_having_to_gby() */  It’s an example of a “small” change designed to reduce CPU usage by reducing the volume of data that passes through the layers of calls that an execution plan represents. The hint appeared in 18.3 but I’ve run the following on 19.3 as a demonstration of what it does and why it’s a good thing:

rem
rem     Script:         push_having.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Dec 2019
rem     Purpose:        
rem
rem     Last tested 
rem             19.3.0.0
rem
rem     Notes:
rem     New (18c) push_having_to_gby() hint
rem     Avoids one pipeline (group by to filter) in
rem     execution plans.
rem

create table t1
nologging
as
with generator as (
        select 
                rownum id
        from dual 
        connect by 
                level <= 1e4 -- > comment to avoid WordPress format issue
)
select
        rownum                          id,
        lpad(rownum,10,'0')             v1,
        lpad('x',50,'x')                padding
from
        generator       v1,
        generator       v2
where
        rownum <= 1e6 -- > comment to avoid WordPress format issue
;

alter table t1 modify id not null;
create index t1_i1 on t1(id) nologging;

set serveroutput off
alter session set statistics_level = all;

select
        /*+
                qb_name(driver)
        */
        id 
from
        t1
where   id is not null
group by 
        id 
having  
        count(1) > 1
;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

There aren’t very many options for the execution path for this query, and the default path taken on my database was an imdex fast full scan with hash aggregation:


-----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation             | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |       |      1 |        |      0 |00:00:00.68 |    2238 |   2230 |       |       |          |
|*  1 |  HASH GROUP BY        |       |      1 |  50000 |      0 |00:00:00.68 |    2238 |   2230 |    55M|  7913K|   57M (0)|
|   2 |   INDEX FAST FULL SCAN| T1_I1 |      1 |   1000K|   1000K|00:00:00.20 |    2238 |   2230 |       |       |          |
-----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(COUNT(*)>1)

You’ll notice that the query should return no rows – the way I’ve generated the id means it’s unique even though I haven’t declared a unique constraint/index. DId you also notice the common guess (5%) that the optimizer has used for the selectivity of the having clause ? But have you spotted the 18c enhancement yet ? If not, we’ll get to it in a moment.

It just so happens that I know there is a better execution path than this for this specific query with my specific data set, so I’m going to put in a minimalist hint to tell the optimizer about it, just to see what happens. The data is very well organized, so using an index scan with running total will be significantly more efficient than a big hash group by:


select
        /*+
                qb_name(driver)
                index(@driver t1@driver)
        */
        id 
from
        t1
where   id is not null
group by 
        id 
having  
        count(1) > 1
;

----------------------------------------------------------------------------------------
| Id  | Operation            | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |       |      1 |        |      0 |00:00:00.80 |    2228 |
|   1 |  SORT GROUP BY NOSORT|       |      1 |  50000 |      0 |00:00:00.80 |    2228 |
|   2 |   INDEX FULL SCAN    | T1_I1 |      1 |   1000K|   1000K|00:00:00.40 |    2228 |
----------------------------------------------------------------------------------------

Notice how the optimizer has obeyed my /*+ index(t1) */ hint and used an index full scan to walk through the t1_i1 index in order, doing a “sort group by” which doesn’t need to do any sorting, so its effectively using a simple running total to count repetitions. The timing (A-time) difference isn’t really something to trust closely when dealing with brief time periods and rowsource_execution_statistics, but eliminating 57M of PGA allocation for the hash join SQL workarea might be a significant benefit. But there’s something else to be seen in this plan – if you can manage to see the things that aren’t there.

So let’s push this query back to its 12c plan:

select
        /*+
                qb_name(driver)
                index(@driver t1@driver)
                optimizer_features_enable('12.2.0.1')
        */
        id 
from
        t1
where   id is not null
group by 
        id 
having  
        count(1) > 1
;

-----------------------------------------------------------------------------------------
| Id  | Operation             | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |       |      1 |        |      0 |00:00:01.02 |    2228 |
|*  1 |  FILTER               |       |      1 |        |      0 |00:00:01.02 |    2228 |
|   2 |   SORT GROUP BY NOSORT|       |      1 |  50000 |   1000K|00:00:00.93 |    2228 |
|   3 |    INDEX FULL SCAN    | T1_I1 |      1 |   1000K|   1000K|00:00:00.45 |    2228 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(COUNT(*)>1)

Notice the FILTER that appears as operation 1. Oracle generates the aggregate data (which happens to total 1M rows) at the Sort Group By (whether it’s the Nosort option from the index full scan, or the “proper” hash group by from the index fast full scan) and passes the 1M row result set (estimated at 50K rows) up to the parent operation where the filter takes place. In 18c onwards the separate filter operation disappears and the filtering takes place as part of the aggregation. This is probably a good thing but if you ever want to disable it without switching everything back to the 12c optimizer features then there’s a dedicated hint: (no_)push_having_to_gby():


select
        /*+
                qb_name(driver)
                index(@driver t1@driver)
                no_push_having_to_gby(@driver)
        */
        id 
from
        t1
where   id is not null
group by 
        id 
having  
        count(1) > 1
;

-----------------------------------------------------------------------------------------
| Id  | Operation             | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |       |      1 |        |      0 |00:00:01.05 |    2228 |
|*  1 |  FILTER               |       |      1 |        |      0 |00:00:01.05 |    2228 |
|   2 |   SORT GROUP BY NOSORT|       |      1 |  50000 |   1000K|00:00:00.91 |    2228 |
|   3 |    INDEX FULL SCAN    | T1_I1 |      1 |   1000K|   1000K|00:00:00.36 |    2228 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(COUNT(*)>1)

If you were looking very carefully (especially after my comment about “seeing things that aren’t there”) you may have noticed that there’s an odd detail in the example where I’ve hinted the index without blocking the push. There’s no Predicate Information section in that execution plan – and that wasn’t a mistake on my part – it simply doesn’t exist – and you’ll note that there’s no asterisk by any of the Operation lines to remind you that there should be should be some Predicate Information! The “count(1) > 1” just doesn’t get reported (even though it does get reported if you use dbms_xplan.display() after a call to explain plan). Fortunately, however, when I modified the model to duplicate one of the rows I did get the correct result – so even though the predicate is not reported it is still applied.  [Side Note: did you notice that my original count(1) changes to count(*) when it gets to the Predicate Information. People still ask which is faster, count(1) or count(*) – the argument should have died back in Oracle 7 days.]

Summary

18c introduced a new optimisation that pushes a “having” predicate down into a group by operation. This reduces CPU usage by eliminating the need to pass a potentially large result from a child operation up to a parent filter operation. Unfortunately you may find that the predicate becomes invisible when you pull the execution plan from memory.

In the unlikely event that you manage to find a case where this optimisation is used when it would have been better to bypass it then there is a hint /*+ no_push_having_to_gby(@qbname) */ to block it, and if it doesn’t appear when you think it should then the opposite hint /*+ push_having_to_gby(@qbname) */ is available.

 

 

Oracle REST Data Services (ORDS) 19.4 : A quick life update…

https://oracle-base.com/blog/wp-content/uploads/2019/12/ords-2-258x300.png 258w" sizes="(max-width: 238px) 85vw, 238px" />

Almost 2 weeks ago I wrote about the release of Oracle REST Data Services (ORDS), SQLcl, SQL Developer and SQL Developer Data Modeler 19.4.

I spent the holidays playing around with ORDS quite a bit, so I came back to work today and pushed it out across all Dev and Test installations.

As I’ve mentioned before, at work we run ORDS on Tomcat inside Docker containers. The build we use is very similar to this one I put on GitHub, but with some extra work-related bits added.

What did I have to do for this update?

Two things:

  • Build a new version of our ORDS Docker image with version 19.4 of the ORDS and SQLcl software.
  • Remove all the containers based on this image and fire up new containers.

How long did it take to deploy this to all Dev and Test instances?

The build of the new Docker image took about 5 minutes. It’s mostly just unzipping the software. This can be done before we touch any running containers, so there is no downtime associated with this.

The removal and creation of all the containers took about 5 minutes as well. Each container is created in a second, but the first run with a new version of ORDS has to do the ORDS upgrade in the database, which takes a few minutes sometimes. If there were no ORDS upgrade, the containers start really quickly.

So effectively, in 5 minutes we replaced all the “kit” and ran the ORDS upgrade across everything. I could have done production in that same 5 minute span too, but I’m not allowed to yet. </p />
</p></div>

    	  	<div class=

VirtualBox 6.1 : No compatible version of Vagrant yet! (or is there?)

VirtualBox 6.1 was released on the 11th of December and I totally missed it.

The downloads and changelog are in the usual places.

I spotted it this morning, downloaded it and installed in straight away. I had no installation dramas on Windows 10, macoS Catalina and Oracle Linux 7 hosts.

The problem *for me* was the current version of Vagrant (2.2.6) doesn’t support VirtualBox 6.1 yet. I can’t live without Vagrant these days, so I installed VirtualBOx 6.0.14 again and normal life resumed. See Update.

I’m sure there will be a new release of Vagrant soon that supports VirtualBox 6.1, but for now if you use Vagrant, don’t upgrade to VirtualBox 6.1 yet. I’m sure you won’t have to wait long… See Update.

Cheers

Tim…

Update 1 : A couple of people Peter Wahl and Andrea Cremonesi pointed me at this post by Simon Coter, which contains config changes to allow Vagrant 2.2.6 to run with VirtualBox 6.1.

Update 2 : I’ve followed Simon’s post and it worked fine. If you are using Windows 10 as the host and have done a default installation of Vagrant, the files he’s discussing are in these directories.

C:\HashiCorp\Vagrant\embedded\gems\2.2.6\gems\vagrant-2.2.6\plugins\providers\virtualbox\driver\

C:\HashiCorp\Vagrant\embedded\gems\2.2.6\gems\vagrant-2.2.6\plugins\providers\virtualbox\

Update 3 : I updated by work PC also. It required a couple of reboots to get things working. I think it may be something to do with the way we do security here. It’s working fine now.


VirtualBox 6.1 : No compatible version of Vagrant yet! (or is there?) was first posted on January 1, 2020 at 1:10 pm.
©2012 "The ORACLE-BASE Blog". Use of this feed is for personal non-commercial use only. If you are not reading this article in your feed reader, then the site is guilty of copyright infringement.

2019 : A Year in Review

https://oracle-base.com/blog/wp-content/uploads/2020/01/2019-2020-rollov... 300w" sizes="(max-width: 324px) 85vw, 324px" />

Well, it seems 2019 was another slightly bizarre year for me.

I just looked back on last year’s review (here) and I’m guessing I had “resting bitch face” while I was reading it…

Conferences

One of the things I mentioned last year was I was taking a year off presenting. I had two events I had already committed to at the start of the year, then dropped off the face of the earth for the rest of the year. I came out of retirement for OpenWorld. I was originally going to pull out of that also, but the wife persuaded me I should go. I’m glad I did.

The reason for not presenting was really to give myself a break. I had been having a lot of trouble travelling, which I suspect is mostly down to being so fat. It was good not to have the hassle of travelling, but I did miss seeing folks. I’ve done some presentations at work during the year, so it’s not like I’ve done nothing…

The problem with not doing conferences was that work was very busy and I didn’t take many holidays, so I was basically swapping one set of stress for another.

I’m thinking I might do a few things this year. I’m not going to go mad and try and speak at loads of events, but I’ve got to get back on the horse. Of course, the first thing is to think of something to present…

If you’ve followed the blog, you’ll know I’ve been going to a few local meetups for Docker, DevOps and Azure. I’m a tourist, rather than a speaker. It’s good to do something different!

Videos

Last year I said I wanted to start doing some videos on my YouTube Channel again. I was “on a break” for a while before that. Well I started at the end of January and I think I’ve done about 44 videos this year. There are a few new playlists, and some additions to existing ones listed here.

I like doing the videos, and it alleviates my guilt at not presenting, but they do take up a lot of time. I know some people have asked for longer, more in-depth videos, but I would estimate that for every minute of the final video, it takes me about 60 minutes of work, so a 5 minute video takes me about 5 hours. With that in mind, the chances of me doing a long-form video are remote.

I know some people can just record themselves talking, but presenting takes a lot of prep for me. For a live presentation I work for days/weeks so I can look casual. For videos it’s a little easier as you can edit stuff and trim it down, but it still takes time…

If you’ve watched my videos, you’ll know I put in little cameos of people saying “.com” to finish my introduction line. I went to put out the latest collection of them (Volume 3) and noticed I had never uploaded Volume 2, so today I posted two short videos. Thanks to everyone who has helped.

I know it’s stupid, but I like it. </p />
</p></div>

    	  	<div class=

The 2019 Year in Review

It’s that time of year where everyone is doing a “Year in Review” post and why not?

https://dbakevlar.com/wp-content/uploads/2019/12/2019_2-300x83.png 300w, https://dbakevlar.com/wp-content/uploads/2019/12/2019_2-768x211.png 768w, https://dbakevlar.com/wp-content/uploads/2019/12/2019_2.png 1203w" sizes="(max-width: 800px) 100vw, 800px" />

It’s good to gain perspective, plan for 2020 and celebrate all that was wonderful about 2019, (outside of politics, that was an utter failure on all fronts, pretty much most countries… :))

The DBAKevlar blog:

  • 46 published posts for 2019
  • Over 800 posts on the site
  • Over 600K in visitors for 2019
  • Daily views have increased steadily, with over 2500 visitors yesterday.
  • Somehow, still awarded top 60 blog sites for Oracle database blogs with all that Microsoft content…:)

Microsoft Employment for 2019:

  • My mobile office worked in 25 states, not even going to count how many locations.
  • Traveled to 37 customer locations
  • Working regularly with over 70 higherEd institutions and a number of K-12 customers on analytics and AI
  • Presented at 3 EdTech conferences
  • Contributed 4 blogs posts to the Microsoft SQL Server/Azure blog
  •  2 role redesigns to make the Oracle work I was doing “official”, (you rock, Denny Ramsey- Thank you for being an awesome boss!)
  • Over 70 projects either migrating Oracle from on-prem to Azure IaaS or part of the Oracle Cloud/Azure partnership.
  • Accepted a new engineering role in Customer Success starting on January 1st, 2020.

Webinars:

Conferences:

I love me a great SQL Saturday and this year I presented at 19 of them!  Its a few down from 2018, when I was an evangelist, but the number is still considerable.  I love getting to present to different audiences, hang out with my #SQLFamily and the opportunity to learn new things.  One of my goals for 2019 at Microsoft was to see if there was interest from the Oracle community in Power BI, so I presented at two Oracle events, RMOUG and KSCOPE to gauge response.  I really enjoyed these sessions, as I got to do something very knew with the technology and also had the opportunity to visit with my Oracle peeps.

I also presented at three sessions at PASS Summit this year.  I love this conference and really appreciate that they’ve let me continue to be an official blogger.  I gave up this year on keeping up with the social events-  there’s just too many and no one has that amount of energy at my age.  I did what I could, seriously.

Publications:

I started my WIT book, “Crushing the IT Gender Bias” in June, 2018.  I had just started at Microsoft, so it was an awesome time to start a book, too, (not.)  As much as I put in it, of course I can now think of so much more that should have been added.  I was really surprised the difference in audience and how often I see it in book stores and libraries.  It’s just very different from my technical books in where it will end up, which results in you feeling proud and vulnerable all at the same time.

I still owe Simple Talk a few more submissions to finish up the Linux series.  The book for Packt came in and stole much of my writing time and at some point, I’ll need to get my content finishes, but luckily, each of the series is stand alone, so everything I add is just gravy to the mashed potatoes posted. </p />
</p></div>

    	  	<div class=

Oracle wait event ‘log file parallel write’ change

This post is about a change in how the time is measured for the event ‘log file parallel write’. This is important for the performance tuning of any change activity in an Oracle database, because with the default commit settings, a foreground session that commits changes waits in the wait event ‘log file sync’, which is a wait on logwriter activity, for which the wait event ‘log file parallel write’ always has been the indicator of the time spend on IO.

Log file sync
First things first: a foreground session normally waits on the wait event ‘log file sync’ when it commits waiting for its change vectors to be written to the online redologfile(s) by the logwriter. It is wrong to always assume a ‘log file sync’ will be present. If, somehow, the logwriter manages to increase the ON DISK SCN to or beyond the foreground session’s commit SCN, there will be no ‘log file sync’ wait event.

I found the absence of the ‘log file sync’ wait event by artificially slowing the committing session down. However, with the improvements in parallelism in the Oracle code, and even more with the improvements on the hardware layer for lowering write latency (especially with persistent memory), this might be a situation that is actually visible in the near future. This is true for at least version 11.2.0.4 and higher (probably earlier too, but these are versions that I verified).

Log file parallel write
However, this post is about the event that in a lot of cases is the culprit for the ‘log file sync’ time: it’s about the ‘log file parallel write’ wait event, which takes place in the logwriter (when the logwriter itself writes, it could delegate that to the logwriter worker processes, LGnn), which normally would be measured by Oracle database tuners to validate logwriter IO latency in case of foreground sessions showing high ‘log file sync’ waits indicating waiting on the logwriter.

I was looking at the logwriter code path using the ‘debug trace’ tool from intel pin tools and used Tanel Poder’s snapper using begin and end snapshots on the logwriter process on Linux, non ASM, Oracle 19.5. I put the logwriter into single logwriter mode (“_use_single_log_writer”=true) and performed redo, which is bound to be picked up by the logwriter.

There I noticed the statistics indicated a write to have been taking place, whilst there was no ‘log file parallel write’ wait event. Weird… So I dug deeper and looked at the functions taking place. These are the functions that I found: https://gitlab.com/snippets/1926207

The important bits are:
– In the function ksfdaio() the IO request is submitted:
ksfdaio>ksfdgo>ksfd_skgfqio>skgfqio>skgfr_lio_listio64>io_submit
– And in the function ksfdblock() the IO request result is read (“reaped”):
ksfdblock>ksfdpoll>ksfdwtio>skgfrwat>skgfrliopo>io_getevents

But no wait event is called *at all!*

This is a clear change from earlier versions, where the logwriter write would always yield a ‘log file parallel write’ wait event. But when did this change happen? To answer that question, I installed version 12.1.0.2 (no patches) to look at the code path and found: https://gitlab.com/snippets/1926211

The important bits are:
– The wait interface is invoked: kslwtbctx()
– In the function ksfdgo() the IO request is submitted:
ksfd_sbio>ksfdgo>ksfd_skgfqio>skgfqio>skgfr_lio_listio64>io_submit
– And in the function ksfdwtio() to IO request result is read (“reaped”):
ksfd_sbio>ksfdwtio>skgfrwat>skgfospo>skgfrliopo>io_getevents
– And the wait interface is ended: kslwtectx()

Ah! So a clear change! So when did this change happen? I installed 12.2.0.1 and found the same ‘waiting’ codepath, then installed 18.3, and found the waiting codepath. So the change probably happened in Oracle 19! So I installed 19.3, and found the waiting codepath once again!! So was it a change in PSU 19.4 or 19.5? I installed 19.5, and found the waiting codepath too.

O.M.G. Why am I seeing different behaviour between two databases on the exact same version? Well, I set some undocumented parameters, so I replicated these in my newly installed database…and it didn’t change.

What else is different? Well…one is a multi-tenant database, and the other isn’t…but surely that doesn’t change the IO codepath?? Of course this is easy to check, so I dropped the non-CDB database and created a CDB one, and…it now showed the same “non waiting” codepath.

So, apparently, using the oracle database in multi-tenant mode changes the IO codepath behaviour. I checked the codepath going down in versions, and it turns out this change appeared in 12.2.0.1.0, so essentially in Oracle 12.2 (Oracle 18 and 19 are actually Oracle 12.2.0.2 and Oracle 12.2.0.3). To be clear on this: I didn’t find this change in 12.1.0.2.

Does this mean the wait events ‘log file parallel write’ does not show up at all? No, if the call io_getevents after io_submit does not return all submitted IOs, it must wait for it, and at that point invoke the wait interface and then go into a blocking io_getevents call, so the actual waiting is timed. This is shown in this snippet: https://gitlab.com/snippets/1926212

This shows ksfdblock>ksfdpoll>ksfdwtio>skgfrwat>skgfrliopo>io_getevents, which returns 0 (what means that it didn’t found any IOs in the completion queue), which then returns up to the ksfdpoll function, invokes the wait interface, kslwtbctx, and then dives to io_getevents again, but now in blocking mode to wait for the IO.

I also replayed the tests on ASM, which shows the exact same (non-)waiting behaviour.

Conclusion
For Oracle versions 12.1.0.2 up to 19.5, the wait event ‘log file parallel write’ includes both the submission of the IO request (io_submit call) and the waiting for the submitted IOs to finish (io_getevents call). This means the waiting time of the event in this case is the total latency of the IO request, including operating system processing.

Starting from version 12.2, only if the multi-tenant option is used, this is changed, and the wait event ‘log file parallel write’ only is shown if the submitted IOs are not available after they are submitted, and thus the logwriter process has to wait for them. If the wait is shown, the time in the event is the actual waiting time for the IOs to finish from the perspective of the logwriter process, not the IO latency time.

Of course if you have multiple log groups on disks with different latencies, this wait event waits for all IOs to finish, which means it times the slowest IO of all submitted IOs.

ADHD and Certification Tests- A Tale of Disaster

I don’t talk too much about my Attention Deficit Hyperactivity Disorder, (ADHD) brain outside of the occasional squirrel joke and more often view it as a super power, but when it is a challenge, I think it’s important to share what we go through.  You can’t solve a problem if you don’t know it is one.

ADHD and Autism

For those that aren’t aware, I was diagnosed with ADHD/on the spectrum for autism back in 2004-2005.  Its not that I wasn’t before this, I just grew up in a very rural area. I fully demonstrated traditional traits for a kid that suffered from both, just no one diagnosed me until one of my own children was diagnosed, (which is quite common.)  At that point in my life, I’d developed numerous, effective, coping mechanisms, but it still created enough challenges that I required medication to address some of the more serious symptoms.

As a kid, I had great difficulty interacting with other children, I became over-stimulated in places with large crowds, bright lights, loud noises and would easily react with tears.  To this day, if I’m not careful, I can become overwhelmed in public and seek out quiet spaces.  I hyper-focus on things I’m interested in and can exhaust those around me on the topic.  I still am quite sensitive to tags, seams and stitching in clothing, making it my mission to dress as comfortable as possible.  You will also notice that when I stand, I often rock back and forth, which is a comforting mechanism I never outgrew.

Do The Thing

In my adult years, I’ve learned how to navigate the world around me and protect the part of me that works a little different than the majority.  It’s happened through extensive trial and error, but it’s because these were situations that I dealt with regularly and was able to figure it out….except for one thing-  taking tests.

Written tests aren’t something you do often once you’re outside of education.  I wasn’t oblivious-  I knew the challenge existed when I would take compliance training at jobs-  which is an annual event at the most.  Where most peers would finish in an hour or two, it would take me five or six hours.  I DREAD annual compliance training not for the training, but if there is a test at the end of it, it will take extensive additional time to get through it.

What’s ADHD Like?

If you don’t have ADHD, it might be difficult to understand what it’s like, so hopefully the following explanation will help.  When an ADHD’r is engaged-  either through interactive experiences or working on something they’re interested in, simply put- the activity levels in the temporal lobes are maintained, allowing them focus and control.  This is why those with ADHD are able to do just fine when they are playing a computer game or another activity their frustrated teachers/parents see as “fun”, when the real term should be “engaging”.  When the situation is the opposite-  tedious or monotonous, activity levels in the temporal lobes decrease, often significantly and we’re no longer able to maintain.  It’s not that we want to pay attention or stand still-  WE HAVE NO CONTROL OVER EITHER.  This is why we’re prescribed stimulants, which can seem very odd when those with ADHD are identified as hyperactive.  These stimulants are designed to increase the activity levels in the temporal lobes, letting us regain focus and self-control, which in turn, let’s us control our emotions, actions and decreases the hyperactivity.

For me, my ADHD when triggered turns most noises, including voices, to sound like  “nails down a chalkboard”.  Those individuals speaking directly to me are drowned out by the distractions, like a bad connection on a conference call, where I receive only half of what they’re saying.   The written word, immediately after read, can’t be recalled-  I simply can’t process the information.  If I have to transition between screens on the computer, the simple act of switching screens causes me to lose track of what I was switching the screen for in the first place.

It can cause a lot of frustration, as most with ADHD have suffered demoralizing misconceptions about how their brain worked as a child, (“If you’d just pay attention”, “You’re not living up to your potential”, “He/She is just lazy”).  We are embarrassed about the condition and try to force ourselves to focus, which often makes it worse.  This creates a domino effect, making us more frustrated, resulting in less focus in our already distracted brain.  It’s obvious to a bystander that my ADHD is effecting me to this level, as my hyperactivity will override my medication, (and FYI- hyperactivity often presents itself differently in men vs. women) which means the speed of my speech will increase, my foot will tap, my skin will seem irritated, especially my ears, nose and scalp and I may fiddle with items in front of me.

Many have asked me how I treat my ADHD and I believe in a combination of nutrition, life structure/routine changes, followed by medication.  I decided I did need medication after an experience that left me quite shaken. I was driving down the street, my children were chattering in the backseat of the car and it was a significant distraction- so distracting that I couldn’t focus long enough to tell you if the traffic light in front of me was red or green.  This type of dangerous situation is definitely an indicator you need medication and needing medication for ADHD isn’t a sign of failure-  Treat ADHD for what makes you successful, don’t treat it for what others deem a success.

Timed Tests, Set Up for Failure

Some of the best steps to successfully working through tedious or monotonous tasks that trigger our ADHD symptoms are:

  1. Streamline the process to remove any added frustration or monotony.
  2. Perform the task, broken up in smaller sections of time, so a 1 hour task we’ll do in four, 15 minute sessions, taking breaks between.
  3. Insert interesting, short distractions in the middle of the tedious task to raise the activity levels in the temporal lobes and regain our focus.
  4. Have something to eat or drink that can help increase focus, (controlled distraction)
  5. Wear headphones and listen to music/podcast while performing the task, (controlled distraction)

So this is where my difficult week came into play.  I have two certifications, comprised of three tests that are part of my yearly goals this year at Microsoft.  As any of you who’ve taken certification tests know, these tests are done under a very controlled environment and have strict rules that must be adhered to:

  1. Complex and poorly designed UI for logging in, scheduling and authorizing the test which enhances frustration.
  2. Timed test- must be performed beginning to end, no break
  3. No outside interaction- no headphones, drinks, food or interruptions.
  4. Test isn’t interactive in any way, built complex to test your knowledge
  5. Due to travel, I was to perform the test at home, (the RV)

I was aware through previous compliance testing, which often took me two to three tries to get through stupid, mundane questions that this would not be easy for me.  It didn’t matter if I knew the material, I would have difficulty “absorbing” the questions, even after reading them 2, 3 or more times and it had less to do with what I knew and more about what I could get through.

Happy Girl

My anxiety has seriously decreased while at Microsoft, to the point that Esme, who is a trained service dog to deal with my sleep anxiety attacks, failed to wake me up this last week.  My anxiety has decreased so much, my service dog is out of service. It surprises me how the little things can take some of us down, not the big things you’d expect.  Job change?  Sell your property, sell 95% of your stuff and move into an RV?  Kids move out?  All four at once?  Handle it with grace and calm.  Give me a certification test to pass?  No sleep for a week!

While preparing for the test, I haven’t slept and had two sleep anxiety attacks, (oh those are lovely, we should talk…) hardly eating and all in all, pretty much a tense freakazoid.  Seriously-  major crisis?  I got this.  Certification test?  I don’t got this. </p />
</p></div>

    	  	<div class=

Scalar Subq Bug

This is an observation that came up on the Oracle Developer Forum a couple of days ago, starting life as the fairly common problem:

I have a “select” that runs quickly  but when I use in a “create as select” it runs very slowly.

In many cases this simply means that the query was a distributed query and the plan changed because the driving site changed from the remote to the local server. There are a couple of other reasons, but distributed DML is the one most commonly seen.

In this example, though, the query was not a distributed query, it was a fully local query. There were three features to the query that were possibly suspect, though:

  • “ANSI” syntax
  • scalar subqueries in the select list
  • redundant “order by” clauses in inline views

The OP had supplied the (horrible) SQL in a text format along with images from the Enterprise Manager SQL Monitor screen showing the two execution plans and two things were  obvious from the plans – first that the simple select had eliminated the scalar subqueries (which were redundant) while the CTAS had kept them in the plan, and secondly most of the elapsed time for the CTAS was spent in kits if executions of the scalar subqueries.

My first thought was that the problem was probably a quirk of how the optimizer translates “ANSI” SQL to Oracle-standard SQL, so I created a model that captured the key features of the problem – starting with 3 tables:

rem
rem     Script:         ctas_scalar_subq.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Dec 2019
rem     Purpose:        
rem
rem     Last tested 
rem             19.3.0.0
rem             12.2.0.1
rem             11.2.0.4
rem

create table t1 as
select * from all_objects
where rownum <= 10000 -- > comment to avoid wordpress format issue
;

alter table t1 add constraint t1_pk primary key(object_id);

create table t2 as
select * from t1
;

alter table t2 add constraint t2_pk primary key(object_id);

create table t3 as
select * from all_objects
where rownum <= 500 -- > comment to avoid wordpress format issue
;

alter table t3 add constraint t3_pk primary key(object_id);

begin
        dbms_stats.gather_table_stats(
                ownname     => null,
                tabname     => 'T1',
                method_opt  => 'for all columns size 1'
        );

        dbms_stats.gather_table_stats(
                ownname     => null,
                tabname     => 'T2',
                method_opt  => 'for all columns size 1'
        );

        dbms_stats.gather_table_stats(
                ownname     => null,
                tabname     => 'T3',
                method_opt  => 'for all columns size 1'
        );
end;
/

I’m going to use the small t3 table as the target for a simple scalar subquery in the select list of a query that selects some columns from t2; then I’m going to use that query as an inline view in a join to t1 and select some columns from the result. Here’s the starting query that’s going to become an inline view:


select 
        t2.*,
        (
        select  t3.object_type 
        from    t3 
        where   t3.object_id = t2.object_id
        )       t3_type
from
        t2
order by
        t2.object_id
;

And here’s how I join the result to t1:


explain plan for
        select
                v2.*
        from    (
                select
                        t1.object_id,
                        t1.object_name  t1_name,
                        v1.object_name  t2_name,
                        t1.object_type  t1_type,
                        v1.object_type  t2_type
                from
                        t1
                join (
                        select 
                                t2.*,
                                (
                                select  t3.object_type 
                                from    t3 
                                where   t3.object_id = t2.object_id
                                )       t3_type
                        from
                                t2
                        order by
                                t2.object_id
                )       v1
                on
                        v1.object_id = t1.object_id
                and     v1.object_type = 'TABLE'
                )       v2
;

select * from table(dbms_xplan.display(null,null,'outline alias'));

The initial t2 query becomes an inline view called v1, and that becomes the second table in a join with t1. I’ve got the table and view in this order because initially the OP had an outer (left) join preserving t1 and I thought that that might be significant, but it turned out that it wasn’t.

Having joined t1 and v1 I’ve selected a small number of columns from the t1 and t2 tables and ignored the column that was generated by the inline scalar subquery. (This may seem a little stupid – but the same problem appears when the inline view is replaced with a stored view, which is a more realistic possibility.) Here’s the resulting execution plan (taken from 11.2.0.4 in this case):


-----------------------------------------------------------------------------
| Id  | Operation            | Name | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |   476 | 31416 |    45  (12)| 00:00:01 |
|*  1 |  HASH JOIN           |      |   476 | 31416 |    45  (12)| 00:00:01 |
|   2 |   VIEW               |      |   476 | 15708 |    23  (14)| 00:00:01 |
|   3 |    SORT ORDER BY     |      |   476 | 41888 |    23  (14)| 00:00:01 |
|*  4 |     TABLE ACCESS FULL| T2   |   476 | 41888 |    22  (10)| 00:00:01 |
|   5 |   TABLE ACCESS FULL  | T1   | 10000 |   322K|    21   (5)| 00:00:01 |
-----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("V1"."OBJECT_ID"="T1"."OBJECT_ID")
   4 - filter("T2"."OBJECT_TYPE"='TABLE')

I was a little surprised by this plan as I had expected the optimizer to eliminate the in-line “order by” in view v1 – but even when I changed the code to traditional Oracle join syntax the redundant and wasteful sort at operaton 3 still took place. (You might note that the data will be reported in an order dictated by the order of the data arriving from the t1 tablescan thanks to the mechanism of the hash join, so the sort is a total waste of effort.)

The plus point, of course, is that the optimizer had been smart enough to eliminate the scalar subquery referencing t3. The value returned from t3 is not needed anywhere in the course of the execution, so it simply disappears.

Now we change from a simple select to a Create as Select which I’ve run, with rowsource execution stats enabled, using Oracle 19.3 for this output:

set serveroutput off
set linesize 156
set trimspool on
set pagesize 60

alter session set statistics_level = all;

create table t4 as
        select  
                v2.*
        from    (
                select
                        t1.object_id,
                        t1.object_name  t1_name,
                        v1.object_name  t2_name,
                        t1.object_type  t1_type,
                        v1.object_type  t2_type
                from
                        t1
                join (
                        select 
                                t2.*,
                                (
                                select  t3.object_type 
                                from    t3 
                                where   t3.object_id = t2.object_id
                                )       t3_type
                        from
                                t2
                        order by 
                                t2.object_id
                )       v1
                on
                        v1.object_id = t1.object_id
                and     v1.object_type = 'TABLE'
                )       v2
;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

alter session set statistics_level = typical;

And here’s the run-time execution plan – showing the critical error and statistics to prove that it really happened:

----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Writes |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------
|   0 | CREATE TABLE STATEMENT           |       |      1 |        |      0 |00:00:00.01 |     471 |      3 |       |       |          |
|   1 |  LOAD AS SELECT                  | T4    |      1 |        |      0 |00:00:00.01 |     471 |      3 |  1042K|  1042K| 1042K (0)|
|   2 |   OPTIMIZER STATISTICS GATHERING |       |      1 |    435 |    294 |00:00:00.01 |     414 |      0 |   256K|   256K|  640K (0)|
|*  3 |    HASH JOIN                     |       |      1 |    435 |    294 |00:00:00.01 |     414 |      0 |  1265K|  1265K| 1375K (0)|
|   4 |     VIEW                         |       |      1 |    435 |    294 |00:00:00.01 |     234 |      0 |       |       |          |
|   5 |      TABLE ACCESS BY INDEX ROWID | T3    |    294 |      1 |     50 |00:00:00.01 |      54 |      0 |       |       |          |
|*  6 |       INDEX UNIQUE SCAN          | T3_PK |    294 |      1 |     50 |00:00:00.01 |       4 |      0 |       |       |          |
|   7 |      SORT ORDER BY               |       |      1 |    435 |    294 |00:00:00.01 |     234 |      0 | 80896 | 80896 |71680  (0)|
|*  8 |       TABLE ACCESS FULL          | T2    |      1 |    435 |    294 |00:00:00.01 |     180 |      0 |       |       |          |
|   9 |     TABLE ACCESS FULL            | T1    |      1 |  10000 |  10000 |00:00:00.01 |     180 |      0 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("V1"."OBJECT_ID"="T1"."OBJECT_ID")
   6 - access("T3"."OBJECT_ID"=:B1)
   8 - filter("T2"."OBJECT_TYPE"='TABLE')

You’ll notice that the VIEW at operation 4 reports the inline scalar subquery as operations 5 and 6, and the Starts column show that the scalar subquery executes 294 times – which is the number of rows returned by the scan of table t2. Although my first thought was that this was an artefact of the transformation from ANSI to Oracle syntax it turned out that when I modified the two statements to use traditional Oracle syntax the same difference appeared. Finally I re-ran the CTAS after removing the order by clause in the in-line view and the redundant subquery disappeared from the execution plan.

Tiny Geek bit

It’s not immediately obvious why there should be such a difference between the select and the CTAS in this case, but the 10053 trace files do give a couple of tiny clues the CTAS trace file includes the lines:

ORE: bypassed - Top query block of a DML.
TE: Bypassed: Top query block of a DML.
SQT:    SQT bypassed: in a transaction.

The first two suggest that we should expect some cases where DML statement optimise differently from simple queries. The last one is a further indication that differences may appear. (SQT – might this be subquery transformation, it doesn’t appear in the list of abbreviations in the trace file).

Unfortunately the SELECT trace file also included the line:


SQT:     SQT bypassed: Disabled by parameter.

So “SQT” – whatever that is – being in or out of a transaction may not have anything to do with the difference.

Summary

There are cases where optimising a select statement is not sufficient as a strategy for optimising a CTAS statement. In this case it looks as if an inline view which was non-mergable (thanks to a redundant order by clause) produced the unexpected side-effect that a completely redundant scalar subquery in the select list of the inline view was executed during the CTAS even though it was transformed out of existence for the simple select.

There are some unexpected performance threats in “cut-and-paste” coding. and in re-using stored views if you haven’t checked carefully what they do and how they’re supposed to be used.

 

 

The Shepherd’s Crown


The Shepherd’s Crown is the last book in the Discworld series by Terry Pratchett. I really don’t like the finality of how that sounds, which is probably why I’ve waited a long time to read this book.

Having complained about how the female lead character was used in The Unicorn Project, I figured it was time to read this book and see it done properly again.

I’m not going to include any full-on spoilers, but some things might give the game away, so don’t read this if you’ve not already read the book.

During the first sequence in the book I got a pretty good idea what was coming and I was like, “No. No. Nooooooooo!” I’m not going to say what it was, but it was a major kick in the gonads…

Tiffany Aching is a great character. It would be so easy for a lesser writer to make her a Mary Sue, but Pratchett keeps her multi-dimensional. Sometimes strong, clever, and at times ruthless. Sometimes self-doubting and almost naive.

As you would expect for this part of the disc (world), there are a number of familiar characters. It’s wrong to say any character in Discworld is “my favourite”, as it changes with each book, and sometime several times in a single book. This book contained several of my favourite characters. Some old and some new. </p />
</p></div>

    	  	<div class=