Flashback query and cursor: pin S wait on X

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:

`1`	`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:

`1`	`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:

1BEGIN {
2        @cnt = 0;
3        @sum = 0;
4}
5uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kkscsCheckCursor+2 /pid == $1/ {
6        printf("\t\tChecking cursor, %d\n", @cnt);
7        @cnt++;
8}
9uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kkscsSearchChildList+2 /pid == $1/ {
10        printf("\tSearching Child List of a cursor\n");
11}
12uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:qksctxAddPlanHashValue+2 /pid == $1/ {
13        printf("\t\t\tAdd Hash value for a plan\n");
14}
15uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kglHandleInitialize+2 /pid == $1/ {
16        printf("\t\t\tInitialize cursor handle\n");
17}
18uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kksParseCursor+2 /pid == $1/ {
19        @sum += @cnt;
20        @cnt = 0;
21        printf("Parsing cursor: %s\n", str(arg1));
22}
23uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kksLoadChild+2 /pid == $1/ {
24        if (arg4 !=0) {
25                printf("\t\tLoading new incomplete child at address %x\n", arg4);
26        } else {
27                printf("\t\tFinnishing child load\n");
28        }
29}
30END {
31  printf("Checked %d cursors\n", @cnt);
32}

Each time I execute the above query, my simple script shows the following output:

1[root@dbVictim ~]# bpftrace kkscsCheckCursor.bpftrace 365150
2Attaching 8 probes...
3Parsing cursor: select /*TEST1*/ count(1) from hr.employees as of timestamp sys
4    Searching Child List of a cursor
5        Checking cursor, 0
6        Checking cursor, 1
7        Checking cursor, 2
8        Checking cursor, 3
9        Checking cursor, 4
10        Checking cursor, 5
11        Loading new incomplete child at address 8f6f7588
12            Initialize cursor handle
13            Initialize cursor handle
14        Finnishing child load
15            Initialize cursor handle
16            Add Hash value for a plan
17Parsing cursor: select max(time_mp) from smon_scn_time
18Parsing cursor: select time_mp, scn, num_mappings, tim_scn_map    from smon_scn
19    Searching Child List of a cursor
20        Checking cursor, 0
21Parsing cursor: select /*TEST1*/ count(1) from hr.employees as of timestamp sys
22    Searching Child List of a cursor
23        Checking cursor, 0
24        Checking cursor, 1
25        Checking cursor, 2
26        Checking cursor, 3
27        Checking cursor, 4
28        Checking cursor, 5
29        Checking cursor, 6
30        Loading new incomplete child at address 934b8310
31            Initialize cursor handle
32            Initialize cursor handle
33        Finnishing child load
34            Initialize cursor handle
35            Add Hash value for a plan
36Parsing cursor: select max(time_mp) from smon_scn_time
37Parsing cursor: select /*TEST1*/ count(1) from hr.employees as of timestamp sys
38    Searching Child List of a cursor
39        Checking cursor, 0
40        Checking cursor, 1
41        Checking cursor, 2
42        Checking cursor, 3
43        Checking cursor, 4
44        Checking cursor, 5
45        Checking cursor, 6
46        Checking cursor, 7
47        Loading new incomplete child at address 919a04c0
48            Initialize cursor handle
49            Initialize cursor handle
50        Finnishing child load
51            Initialize cursor handle
52            Add Hash value for a plan
53Parsing 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:

1BEGIN {
2    @cnt = 0;
3    @sum = 0;
4}
5uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kkscsCheckCursor+2 /pid == $1/ {
6        printf("\t\tChecking cursor, %d\n", @cnt);
7        @cnt++;
8}
9uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kkscsSearchChildList+2 /pid == $1/ {
10    printf("\tSearching Child List of a cursor\n");
11}
12uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:qksctxAddPlanHashValue+2 /pid == $1/ {
13    printf("\t\t\tAdd Hash value for a plan\n");
14}
15uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kglHandleInitialize+2 /pid == $1/ {
16    printf("\t\t\tInitialize cursor handle\n");
17}
18uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kgxExclusive+2 /pid == $1/ {
19    printf("\t\t\t\tSetitng exclusive mutex: %x\n", arg1);
20}
21uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kglReleaseMutex+2 /pid == $1/ {
22    printf("\t\t\t\tRelease mutex\t\t:%x\n", arg1);
23}
24uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kksParseCursor+2 /pid == $1/ {
25    @sum += @cnt;
26    @cnt = 0;
27    printf("Parsing cursor: %s\n", str(arg1));
28}
29uprobe:/opt/oracle/product/19c/dbhome_1/bin/oracle:kksLoadChild+2 /pid == $1/ {
30    if (arg4 !=0) {
31        printf("\t\tLoading new incomplete child at address %x\n", arg4);
32    } else {
33        printf("\t\tFinnishing child load\n");
34    }
35}
36END {
37  printf("Checked %d cursors\n", @cnt);
38}

And now we can understand a bit more about complexity of work that is going on under the hood:

1[root@dbVictim ~]# bpftrace kkscsCheckCursor.bpftrace 365150
2Attaching 10 probes...
3                Setitng exclusive mutex: 9ee5d650
4                Release mutex       :9ee5d650
5                Setitng exclusive mutex: 9ee5d650
6                Release mutex       :9ee5d650
7Parsing cursor: select /*TEST1*/ count(1) from hr.employees as of timestamp sys
8                Setitng exclusive mutex: a3f391c8
9                Release mutex       :a3f391c8
10                Setitng exclusive mutex: 9ee5d650
11                Release mutex       :a3f391c8
12                Release mutex       :9ee5d650
13                Release mutex       :9ee5d650
14                Release mutex       :9ee5d650
15    Searching Child List of a cursor
16        Checking cursor, 0
17                Setitng exclusive mutex: 9ee5d650
18                Release mutex       :9ee5d650
19                Release mutex       :9ee5d650
20                Setitng exclusive mutex: 64cf6d08
21                Setitng exclusive mutex: 9ee5d650
22                Release mutex       :9ee5d650
23        Checking cursor, 1
24        Checking cursor, 2
25        Checking cursor, 3
26        Checking cursor, 4
27        Checking cursor, 5
28        Checking cursor, 6
29        Checking cursor, 7
30        Checking cursor, 8
31        Checking cursor, 9
32        Checking cursor, 10
33        Checking cursor, 11
34        Checking cursor, 12
35        Checking cursor, 13
36        Checking cursor, 14
37        Checking cursor, 15
38        Checking cursor, 16
39        Checking cursor, 17
40        Checking cursor, 18
41        Checking cursor, 19
42        Checking cursor, 20
43        Checking cursor, 21
44        Checking cursor, 22
45        Checking cursor, 23
46        Checking cursor, 24
47        Checking cursor, 25
48        Checking cursor, 26
49        Checking cursor, 27
50        Checking cursor, 28
51        Checking cursor, 29
52        Checking cursor, 30
53        Checking cursor, 31
54        Checking cursor, 32
55        Checking cursor, 33
56        Checking cursor, 34
57        Checking cursor, 35
58        Checking cursor, 36
59        Checking cursor, 37
60        Checking cursor, 38
61        Checking cursor, 39
62        Checking cursor, 40
63        Checking cursor, 41
64        Checking cursor, 42
65        Checking cursor, 43
66        Checking cursor, 44
67        Checking cursor, 45
68        Checking cursor, 46
69        Checking cursor, 47
70        Checking cursor, 48
71        Checking cursor, 49
72        Checking cursor, 50
73        Checking cursor, 51
74        Checking cursor, 52
75        Checking cursor, 53
76        Checking cursor, 54
77        Checking cursor, 55
78        Checking cursor, 56
79                Setitng exclusive mutex: a2499a40
80                Release mutex       :a2499a40
81                Setitng exclusive mutex: 9b52ed98
82                Release mutex       :a2499a40
83                Release mutex       :9b52ed98
84                Release mutex       :9b52ed98
85                Setitng exclusive mutex: 9b52ed98
86                Release mutex       :9b52ed98
87                Setitng exclusive mutex: 64cf6d08
88                Setitng exclusive mutex: 64cf7108
89                Setitng exclusive mutex: 9ee5d650
90                Release mutex       :9ee5d650
91                Release mutex       :9ee5d650
92                Setitng exclusive mutex: 9ee5d650
93                Release mutex       :9ee5d650
94                Setitng exclusive mutex: 9ee5d650
95                Release mutex       :9ee5d650
96                Setitng exclusive mutex: a23eb3f0
97                Setitng exclusive mutex: a07750b8
98                Release mutex       :a23eb3f0
99                Release mutex       :a07750b8
100                Release mutex       :a07750b8
101                Release mutex       :a07750b8
102                Setitng exclusive mutex: a220a068
103                Setitng exclusive mutex: 9bde46c0
104                Release mutex       :a220a068
105                Release mutex       :9bde46c0
106                Release mutex       :9bde46c0
107                Release mutex       :9bde46c0
108        Loading new incomplete child at address 6f613d68
109                Setitng exclusive mutex: 64cf6d08
110                Setitng exclusive mutex: a21ca558
111                Setitng exclusive mutex: 84cf8658
112                Release mutex       :a21ca558
113                Release mutex       :84cf8658
114                Release mutex       :84cf8658
115                Release mutex       :84cf8658
116                Setitng exclusive mutex: 84cf8658
117                Release mutex       :84cf8658
118                Setitng exclusive mutex: 84cf8658
119                Release mutex       :84cf8658
120            Initialize cursor handle
121                Setitng exclusive mutex: 84cf8658
122                Release mutex       :84cf8658
123                Setitng exclusive mutex: 84cf8658
124                Release mutex       :84cf8658
125                Release mutex       :84cf8658
126                Setitng exclusive mutex: 84cf8658
127                Setitng exclusive mutex: 84cf85b8
128                Release mutex       :84cf85b8
129                Release mutex       :84cf8658
130                Setitng exclusive mutex: 9ee5d650
131                Setitng exclusive mutex: 9ee5d5b0
132                Release mutex       :9ee5d5b0
133                Release mutex       :9ee5d650
134                Setitng exclusive mutex: 84cf8658
135                Release mutex       :84cf8658
136                Setitng exclusive mutex: 84cf8658
137                Release mutex       :84cf8658
138            Initialize cursor handle
139                Setitng exclusive mutex: 9ee5d650
140                Release mutex       :9ee5d650
141                Setitng exclusive mutex: 9ee5d650
142                Release mutex       :9ee5d650
143                Setitng exclusive mutex: 9bde46c0
144                Release mutex       :9bde46c0
145                Setitng exclusive mutex: a07750b8
146                Release mutex       :a07750b8
147                Setitng exclusive mutex: 9ee5d650
148                Release mutex       :9ee5d650
149                Release mutex       :9ee5d650
150                Setitng exclusive mutex: 9ee5d650
151                Release mutex       :9ee5d650
152        Finnishing child load
153                Setitng exclusive mutex: 64cf6d08
154            Initialize cursor handle
155                Setitng exclusive mutex: 9ee5d650
156                Release mutex       :9ee5d650
157                Setitng exclusive mutex: a23eb3f0
158                Setitng exclusive mutex: a07750b8
159                Release mutex       :a23eb3f0
160                Release mutex       :a07750b8
161                Release mutex       :a07750b8
162                Release mutex       :a07750b8
163                Setitng exclusive mutex: a220a068
164                Setitng exclusive mutex: 9bde46c0
165                Release mutex       :a220a068
166                Release mutex       :9bde46c0
167                Release mutex       :9bde46c0
168                Release mutex       :9bde46c0
169                Setitng exclusive mutex: 64cf6d08
170                Setitng exclusive mutex: 64cf6d08
171                Setitng exclusive mutex: a2455bd8
172                Release mutex       :a2455bd8
173                Setitng exclusive mutex: 9675db10
174                Release mutex       :a2455bd8
175                Release mutex       :9675db10
176                Release mutex       :9675db10
177                Release mutex       :9675db10
178                Setitng exclusive mutex: 9675db10
179                Release mutex       :9675db10
180                Setitng exclusive mutex: 9675db10
181                Release mutex       :9675db10
182                Release mutex       :9675db10
183                Setitng exclusive mutex: 9675db10
184                Setitng exclusive mutex: 9675da70
185                Release mutex       :9675da70
186                Release mutex       :9675db10
187                Setitng exclusive mutex: 9675db10
188                Release mutex       :9675db10
189                Setitng exclusive mutex: a46878f8
190                Setitng exclusive mutex: 96da8380
191                Setitng exclusive mutex: 96da8380
192                Setitng exclusive mutex: a4750eb8
193                Setitng exclusive mutex: 8cde26f8
194                Setitng exclusive mutex: 8cde26f8
195                Setitng exclusive mutex: a4750eb8
196                Setitng exclusive mutex: 8cde26f8
197                Setitng exclusive mutex: 8cde26f8
198                Setitng exclusive mutex: a4750eb8
199                Setitng exclusive mutex: 8cde26f8
200                Setitng exclusive mutex: 8cde26f8
201                Setitng exclusive mutex: a4750eb8
202                Setitng exclusive mutex: 8cde26f8
203                Setitng exclusive mutex: 8cde26f8
204                Setitng exclusive mutex: a4750eb8
205                Setitng exclusive mutex: 8cde26f8
206                Setitng exclusive mutex: 8cde26f8
207                Setitng exclusive mutex: a4750eb8
208                Setitng exclusive mutex: 8cde26f8
209                Setitng exclusive mutex: 8cde26f8
210                Setitng exclusive mutex: a4750eb8
211                Setitng exclusive mutex: 8cde26f8
212                Setitng exclusive mutex: 8cde26f8
213                Setitng exclusive mutex: a4750eb8
214                Setitng exclusive mutex: 8cde26f8
215                Setitng exclusive mutex: 8cde26f8
216                Setitng exclusive mutex: a4750eb8
217                Setitng exclusive mutex: 8cde26f8
218                Setitng exclusive mutex: 8cde26f8
219                Setitng exclusive mutex: a4750eb8
220                Setitng exclusive mutex: 8cde26f8
221                Setitng exclusive mutex: 8cde26f8
222                Setitng exclusive mutex: a478f870
223                Setitng exclusive mutex: 8cde26f8
224                Setitng exclusive mutex: 8cde26f8
225                Setitng exclusive mutex: a4750eb8
226                Setitng exclusive mutex: 8cde26f8
227                Setitng exclusive mutex: 8cde26f8
228                Setitng exclusive mutex: a4750eb8
229                Setitng exclusive mutex: 8cde26f8
230                Setitng exclusive mutex: 8cde26f8
231                Setitng exclusive mutex: a4750eb8
232                Setitng exclusive mutex: 8cde26f8
233                Setitng exclusive mutex: 8cde26f8
234                Setitng exclusive mutex: a4750eb8
235                Setitng exclusive mutex: 8cde26f8
236                Setitng exclusive mutex: 8cde26f8
237                Setitng exclusive mutex: a4750eb8
238                Setitng exclusive mutex: 8cde26f8
239                Setitng exclusive mutex: 8cde26f8
240                Setitng exclusive mutex: a4750eb8
241                Setitng exclusive mutex: 8cde26f8
242                Setitng exclusive mutex: 8cde26f8
243                Setitng exclusive mutex: a4750eb8
244                Setitng exclusive mutex: 8cde26f8
245                Setitng exclusive mutex: 8cde26f8
246                Setitng exclusive mutex: a4750eb8
247                Setitng exclusive mutex: 8cde26f8
248                Setitng exclusive mutex: 8cde26f8
249                Setitng exclusive mutex: a4750eb8
250                Setitng exclusive mutex: 8cde26f8
251                Setitng exclusive mutex: 8cde26f8
252                Setitng exclusive mutex: a4750eb8
253                Setitng exclusive mutex: 8cde26f8
254                Setitng exclusive mutex: 8cde26f8
255                Setitng exclusive mutex: a478f870
256                Setitng exclusive mutex: 8cde26f8
257                Setitng exclusive mutex: 8cde26f8
258                Setitng exclusive mutex: 9675db10
259                Release mutex       :9675db10
260                Setitng exclusive mutex: 9675db10
261                Release mutex       :9675db10
262                Release mutex       :9675db10
263                Setitng exclusive mutex: 9675db10
264                Release mutex       :9675db10
265                Release mutex       :9675db10
266                Setitng exclusive mutex: a4ce25b0
267                Release mutex       :a4ce25b0
268                Setitng exclusive mutex: 9dae8590
269                Release mutex       :a4ce25b0
270                Release mutex       :9dae8590
271                Release mutex       :9dae8590
272                Release mutex       :9dae8590
273                Setitng exclusive mutex: 9dae8590
274                Release mutex       :9dae8590
275                Setitng exclusive mutex: 9dae8590
276                Release mutex       :9dae8590
277                Release mutex       :9dae8590
278                Setitng exclusive mutex: 9dae8590
279                Release mutex       :9dae8590
280                Setitng exclusive mutex: 9dae8590
281                Release mutex       :9dae8590
282                Setitng exclusive mutex: a48e28e8
283                Setitng exclusive mutex: 9b68ea08
284                Setitng exclusive mutex: 9b68ea08
285                Setitng exclusive mutex: a489e710
286                Setitng exclusive mutex: 9de12258
287                Setitng exclusive mutex: 9de12258
288                Setitng exclusive mutex: a48bcb30
289                Setitng exclusive mutex: 9b17b278
290                Setitng exclusive mutex: 9b17b278
291                Setitng exclusive mutex: a491d208
292                Setitng exclusive mutex: 8a9d89a8
293                Setitng exclusive mutex: 8a9d89a8
294                Setitng exclusive mutex: a491d220
295                Setitng exclusive mutex: 9b127980
296                Setitng exclusive mutex: 9b127980
297                Setitng exclusive mutex: a4945240
298                Setitng exclusive mutex: 843bf2b0
299                Setitng exclusive mutex: 843bf2b0
300                Setitng exclusive mutex: a48e28e8
301                Setitng exclusive mutex: 9b68ea08
302                Setitng exclusive mutex: 9b68ea08
303                Setitng exclusive mutex: a48a0f78
304                Setitng exclusive mutex: 734abeb8
305                Setitng exclusive mutex: a4750eb8
306                Setitng exclusive mutex: 8cde26f8
307                Setitng exclusive mutex: 8cde26f8
308                Setitng exclusive mutex: 734abeb8
309                Setitng exclusive mutex: a48a0f78
310                Setitng exclusive mutex: 734abeb8
311                Setitng exclusive mutex: a4750eb8
312                Setitng exclusive mutex: 8cde26f8
313                Setitng exclusive mutex: 8cde26f8
314                Setitng exclusive mutex: 734abeb8
315                Setitng exclusive mutex: 9675db10
316                Release mutex       :9675db10
317                Release mutex       :9675db10
318                Setitng exclusive mutex: a48e28e8
319                Setitng exclusive mutex: 9b68ea08
320                Setitng exclusive mutex: a4750eb8
321                Setitng exclusive mutex: 8cde26f8
322                Setitng exclusive mutex: 8cde26f8
323                Setitng exclusive mutex: 9b68ea08
324            Add Hash value for a plan
325                Setitng exclusive mutex: a48a0f78
326                Setitng exclusive mutex: 734abeb8
327                Setitng exclusive mutex: a4750eb8
328                Setitng exclusive mutex: 8cde26f8
329                Setitng exclusive mutex: 8cde26f8
330                Setitng exclusive mutex: 734abeb8
331                Setitng exclusive mutex: 9675db10
332                Release mutex       :9675db10
333                Release mutex       :9675db10
334                Setitng exclusive mutex: 9675db10
335                Release mutex       :9675db10
336                Setitng exclusive mutex: 9675db10
337                Release mutex       :9675db10
338                Setitng exclusive mutex: 9675db10
339                Release mutex       :9675db10
340                Setitng exclusive mutex: 9bde46c0
341                Release mutex       :9bde46c0
342                Setitng exclusive mutex: a07750b8
343                Release mutex       :a07750b8
344                Setitng exclusive mutex: 64cf6d08
345                Setitng exclusive mutex: 64cf6d08
346                Setitng exclusive mutex: 64cf7108
347                Setitng exclusive mutex: 64cf6e08
348                Setitng exclusive mutex: 9b52ed98
349                Release mutex       :9b52ed98
350                Setitng exclusive mutex: 64cf6d08
351Parsing 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:

1(gdb) b kksLoadChild
2Breakpoint 1 at 0x321d330
3(gdb) c
4Continuing.
5 
6Breakpoint 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.

Flashback query and cursor: pin S wait on X

Search:

RICO3 – as a tool for thief

JAS-MIN

When security drives you crazy! (CBFUK)

How checkpoint queue actually works (the basic scenario)

[SOLVED!] ORA-39405: Oracle Data Pump does not support importing from a source database with TSTZ

Binary patching/hacking VM process

Last resort data recovery

Hacking database writer