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.