Check out those charts:
During my last performance tuning audit I found out that database is consuming big amounts of CPU on parsing. One of the queries that took significant amount of time was rather a small DELETE looking something like this:
delete hr.tab_sessions where id=:B1;
Funny story tho – the table is usually empty but during the hot period, session could wait on that small delete even a few seconds.
It was pretty obvious that the problem was not with a DELETE itself, but there had to be something more. The problem was associated with a set of triggers and the triggers were producing queries with AS OF SCN clause.
The problem is that since database version 11.2.0.4 flashback queries have a very strange behavior – according to MOS Using the Flashback Query Feature Results in a High Number of Child Cursors (Doc ID 2192862.1)
This behavior is expected and by design and confirmed by Oracle Development that flashback query cannot share child cursors. However, this was not enforced until 11.2.0.4 when a fix was introduced to prevent an error condition that could be caused by the sharing.
Let me visualize why this is a problem with a simple query looking like this:
select /*TEST1*/ count(1) from hr.employees as of timestamp systimestamp - interval '10' minute
To understand what is going on, we will use to following eBPF script:
BEGIN {
@cnt = 0;
@sum = 0;
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kkscsCheckCursor+2 /pid == $1/ {
printf("\t\tChecking cursor, %d\n", @cnt);
@cnt++;
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kkscsSearchChildList+2 /pid == $1/ {
printf("\tSearching Child List of a cursor\n");
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:qksctxAddPlanHashValue+2 /pid == $1/ {
printf("\t\t\tAdd Hash value for a plan\n");
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kglHandleInitialize+2 /pid == $1/ {
printf("\t\t\tInitialize cursor handle\n");
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kksParseCursor+2 /pid == $1/ {
@sum += @cnt;
@cnt = 0;
printf("Parsing cursor: %s\n", str(arg1));
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kksLoadChild+2 /pid == $1/ {
if (arg4 !=0) {
printf("\t\tLoading new incomplete child at address %x\n", arg4);
} else {
printf("\t\tFinnishing child load\n");
}
}
END {
printf("Checked %d cursors\n", @cnt);
}
Each time I execute the above query, my simple script shows the following output:
[root@dbVictim ~]# bpftrace kkscsCheckCursor.bpftrace 365150 Attaching 8 probes... Parsing cursor: select /*TEST1*/ count(1) from hr.employees as of timestamp sys Searching Child List of a cursor Checking cursor, 0 Checking cursor, 1 Checking cursor, 2 Checking cursor, 3 Checking cursor, 4 Checking cursor, 5 Loading new incomplete child at address 8f6f7588 Initialize cursor handle Initialize cursor handle Finnishing child load Initialize cursor handle Add Hash value for a plan Parsing cursor: select max(time_mp) from smon_scn_time Parsing cursor: select time_mp, scn, num_mappings, tim_scn_map from smon_scn Searching Child List of a cursor Checking cursor, 0 Parsing cursor: select /*TEST1*/ count(1) from hr.employees as of timestamp sys Searching Child List of a cursor Checking cursor, 0 Checking cursor, 1 Checking cursor, 2 Checking cursor, 3 Checking cursor, 4 Checking cursor, 5 Checking cursor, 6 Loading new incomplete child at address 934b8310 Initialize cursor handle Initialize cursor handle Finnishing child load Initialize cursor handle Add Hash value for a plan Parsing cursor: select max(time_mp) from smon_scn_time Parsing cursor: select /*TEST1*/ count(1) from hr.employees as of timestamp sys Searching Child List of a cursor Checking cursor, 0 Checking cursor, 1 Checking cursor, 2 Checking cursor, 3 Checking cursor, 4 Checking cursor, 5 Checking cursor, 6 Checking cursor, 7 Loading new incomplete child at address 919a04c0 Initialize cursor handle Initialize cursor handle Finnishing child load Initialize cursor handle Add Hash value for a plan Parsing cursor: select max(time_mp) from smon_scn_time
It means that each time you execute a flashback query, the function kkscsSearchChildList has to call kkscsCheckCursor for each child cursor that exists in the Library Cache. Since a flashback query can’t share child cursors, at the end of the child list a kksLoadChild has to be executed to initialize a new child and associate an execution plan with this new child.
Loading a new child requires an exclusive mutex. We can modify our eBPF trace script to show the amount of exclusive mutexes:
BEGIN {
@cnt = 0;
@sum = 0;
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kkscsCheckCursor+2 /pid == $1/ {
printf("\t\tChecking cursor, %d\n", @cnt);
@cnt++;
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kkscsSearchChildList+2 /pid == $1/ {
printf("\tSearching Child List of a cursor\n");
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:qksctxAddPlanHashValue+2 /pid == $1/ {
printf("\t\t\tAdd Hash value for a plan\n");
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kglHandleInitialize+2 /pid == $1/ {
printf("\t\t\tInitialize cursor handle\n");
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kgxExclusive+2 /pid == $1/ {
printf("\t\t\t\tSetitng exclusive mutex: %x\n", arg1);
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kglReleaseMutex+2 /pid == $1/ {
printf("\t\t\t\tRelease mutex\t\t:%x\n", arg1);
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kksParseCursor+2 /pid == $1/ {
@sum += @cnt;
@cnt = 0;
printf("Parsing cursor: %s\n", str(arg1));
}
uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kksLoadChild+2 /pid == $1/ {
if (arg4 !=0) {
printf("\t\tLoading new incomplete child at address %x\n", arg4);
} else {
printf("\t\tFinnishing child load\n");
}
}
END {
printf("Checked %d cursors\n", @cnt);
}
And now we can understand a bit more about complexity of work that is going on under the hood:
[root@dbVictim ~]# bpftrace kkscsCheckCursor.bpftrace 365150 Attaching 10 probes... Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Parsing cursor: select /*TEST1*/ count(1) from hr.employees as of timestamp sys Setitng exclusive mutex: a3f391c8 Release mutex :a3f391c8 Setitng exclusive mutex: 9ee5d650 Release mutex :a3f391c8 Release mutex :9ee5d650 Release mutex :9ee5d650 Release mutex :9ee5d650 Searching Child List of a cursor Checking cursor, 0 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: 64cf6d08 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Checking cursor, 1 Checking cursor, 2 Checking cursor, 3 Checking cursor, 4 Checking cursor, 5 Checking cursor, 6 Checking cursor, 7 Checking cursor, 8 Checking cursor, 9 Checking cursor, 10 Checking cursor, 11 Checking cursor, 12 Checking cursor, 13 Checking cursor, 14 Checking cursor, 15 Checking cursor, 16 Checking cursor, 17 Checking cursor, 18 Checking cursor, 19 Checking cursor, 20 Checking cursor, 21 Checking cursor, 22 Checking cursor, 23 Checking cursor, 24 Checking cursor, 25 Checking cursor, 26 Checking cursor, 27 Checking cursor, 28 Checking cursor, 29 Checking cursor, 30 Checking cursor, 31 Checking cursor, 32 Checking cursor, 33 Checking cursor, 34 Checking cursor, 35 Checking cursor, 36 Checking cursor, 37 Checking cursor, 38 Checking cursor, 39 Checking cursor, 40 Checking cursor, 41 Checking cursor, 42 Checking cursor, 43 Checking cursor, 44 Checking cursor, 45 Checking cursor, 46 Checking cursor, 47 Checking cursor, 48 Checking cursor, 49 Checking cursor, 50 Checking cursor, 51 Checking cursor, 52 Checking cursor, 53 Checking cursor, 54 Checking cursor, 55 Checking cursor, 56 Setitng exclusive mutex: a2499a40 Release mutex :a2499a40 Setitng exclusive mutex: 9b52ed98 Release mutex :a2499a40 Release mutex :9b52ed98 Release mutex :9b52ed98 Setitng exclusive mutex: 9b52ed98 Release mutex :9b52ed98 Setitng exclusive mutex: 64cf6d08 Setitng exclusive mutex: 64cf7108 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: a23eb3f0 Setitng exclusive mutex: a07750b8 Release mutex :a23eb3f0 Release mutex :a07750b8 Release mutex :a07750b8 Release mutex :a07750b8 Setitng exclusive mutex: a220a068 Setitng exclusive mutex: 9bde46c0 Release mutex :a220a068 Release mutex :9bde46c0 Release mutex :9bde46c0 Release mutex :9bde46c0 Loading new incomplete child at address 6f613d68 Setitng exclusive mutex: 64cf6d08 Setitng exclusive mutex: a21ca558 Setitng exclusive mutex: 84cf8658 Release mutex :a21ca558 Release mutex :84cf8658 Release mutex :84cf8658 Release mutex :84cf8658 Setitng exclusive mutex: 84cf8658 Release mutex :84cf8658 Setitng exclusive mutex: 84cf8658 Release mutex :84cf8658 Initialize cursor handle Setitng exclusive mutex: 84cf8658 Release mutex :84cf8658 Setitng exclusive mutex: 84cf8658 Release mutex :84cf8658 Release mutex :84cf8658 Setitng exclusive mutex: 84cf8658 Setitng exclusive mutex: 84cf85b8 Release mutex :84cf85b8 Release mutex :84cf8658 Setitng exclusive mutex: 9ee5d650 Setitng exclusive mutex: 9ee5d5b0 Release mutex :9ee5d5b0 Release mutex :9ee5d650 Setitng exclusive mutex: 84cf8658 Release mutex :84cf8658 Setitng exclusive mutex: 84cf8658 Release mutex :84cf8658 Initialize cursor handle Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: 9bde46c0 Release mutex :9bde46c0 Setitng exclusive mutex: a07750b8 Release mutex :a07750b8 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Finnishing child load Setitng exclusive mutex: 64cf6d08 Initialize cursor handle Setitng exclusive mutex: 9ee5d650 Release mutex :9ee5d650 Setitng exclusive mutex: a23eb3f0 Setitng exclusive mutex: a07750b8 Release mutex :a23eb3f0 Release mutex :a07750b8 Release mutex :a07750b8 Release mutex :a07750b8 Setitng exclusive mutex: a220a068 Setitng exclusive mutex: 9bde46c0 Release mutex :a220a068 Release mutex :9bde46c0 Release mutex :9bde46c0 Release mutex :9bde46c0 Setitng exclusive mutex: 64cf6d08 Setitng exclusive mutex: 64cf6d08 Setitng exclusive mutex: a2455bd8 Release mutex :a2455bd8 Setitng exclusive mutex: 9675db10 Release mutex :a2455bd8 Release mutex :9675db10 Release mutex :9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Setitng exclusive mutex: 9675da70 Release mutex :9675da70 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Setitng exclusive mutex: a46878f8 Setitng exclusive mutex: 96da8380 Setitng exclusive mutex: 96da8380 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a478f870 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: a478f870 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Release mutex :9675db10 Setitng exclusive mutex: a4ce25b0 Release mutex :a4ce25b0 Setitng exclusive mutex: 9dae8590 Release mutex :a4ce25b0 Release mutex :9dae8590 Release mutex :9dae8590 Release mutex :9dae8590 Setitng exclusive mutex: 9dae8590 Release mutex :9dae8590 Setitng exclusive mutex: 9dae8590 Release mutex :9dae8590 Release mutex :9dae8590 Setitng exclusive mutex: 9dae8590 Release mutex :9dae8590 Setitng exclusive mutex: 9dae8590 Release mutex :9dae8590 Setitng exclusive mutex: a48e28e8 Setitng exclusive mutex: 9b68ea08 Setitng exclusive mutex: 9b68ea08 Setitng exclusive mutex: a489e710 Setitng exclusive mutex: 9de12258 Setitng exclusive mutex: 9de12258 Setitng exclusive mutex: a48bcb30 Setitng exclusive mutex: 9b17b278 Setitng exclusive mutex: 9b17b278 Setitng exclusive mutex: a491d208 Setitng exclusive mutex: 8a9d89a8 Setitng exclusive mutex: 8a9d89a8 Setitng exclusive mutex: a491d220 Setitng exclusive mutex: 9b127980 Setitng exclusive mutex: 9b127980 Setitng exclusive mutex: a4945240 Setitng exclusive mutex: 843bf2b0 Setitng exclusive mutex: 843bf2b0 Setitng exclusive mutex: a48e28e8 Setitng exclusive mutex: 9b68ea08 Setitng exclusive mutex: 9b68ea08 Setitng exclusive mutex: a48a0f78 Setitng exclusive mutex: 734abeb8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 734abeb8 Setitng exclusive mutex: a48a0f78 Setitng exclusive mutex: 734abeb8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 734abeb8 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Release mutex :9675db10 Setitng exclusive mutex: a48e28e8 Setitng exclusive mutex: 9b68ea08 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 9b68ea08 Add Hash value for a plan Setitng exclusive mutex: a48a0f78 Setitng exclusive mutex: 734abeb8 Setitng exclusive mutex: a4750eb8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 8cde26f8 Setitng exclusive mutex: 734abeb8 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9675db10 Release mutex :9675db10 Setitng exclusive mutex: 9bde46c0 Release mutex :9bde46c0 Setitng exclusive mutex: a07750b8 Release mutex :a07750b8 Setitng exclusive mutex: 64cf6d08 Setitng exclusive mutex: 64cf6d08 Setitng exclusive mutex: 64cf7108 Setitng exclusive mutex: 64cf6e08 Setitng exclusive mutex: 9b52ed98 Release mutex :9b52ed98 Setitng exclusive mutex: 64cf6d08 Parsing cursor: select max(time_mp) from smon_scn_time
Something like this happens each time the query is being executed. When the amount of sessions executing the flashback query rises, we can hit some serious contention in the Concurrency wait event class.
Let’s simulate this behavior by setting a breakpoint on kksLoadChild function:
(gdb) b kksLoadChild Breakpoint 1 at 0x321d330 (gdb) c Continuing. Breakpoint 1, 0x000000000321d330 in kksLoadChild ()
After this first hit, we know that the whole child list has been scanned and the new cursor handle is being initialized.
The session that tries to execute the same query will be waiting on kksfbc child completion until the child has been prepared. When we hit the second breakpoint in kksLoadChild the session will change wait event to cursor: pin S wait on X because the newest child is also not suitable for sharing and now this session wants to create a new child (exclusive mutex has to be set to do that operation), but the previous session didn’t release the mutex yet.
If you understand the complexity of the job now, imagine that you have 10 such cursors using flashback query mechanism, being executed houndred thousand of times and each having 30 000 child cursors in Library Cache, summing up to ~1GB of Sharable Memory for each cursor.
No wonder that this instance in burning CPU on parsing and waiting in Concurrency wait class.
If you are wondering if having a table in a flashback archive changes anything – it doesn’t.
So the conclusion is simple – do not use the flashback queries in your application logic if you know that those SQLs will be heavily executed by hundreds of concurrent sessions.