Buggy overhead of SQL Plan Baseline Capture

There’s at least one bug related to the performance overhead of SQL Baseline Capture and ASH is less than clear with recursive SQL

First up – apologies, I’ve not got a reproducible test case because I flushed the shared pool between tests and the whole performance degradation scenario disappeared. I should have known when one of the Metalink notes talked about the problem disappearing when bouncing the instance that I shouldn’t have touched the shared pool. Now I can’t reproduce. I’m going to keep trying, but for now, let me tell you what I’ve got (I am trying to be more precise in my blogging but yet again it’s something woolly or nothing).

With that out the way, we’re in the initial stages of an upgrade from 9.2.0.8 on 32-bit Solaris to 11.2.0.2 on 64-bit Linux, a one-step all-or-nothing change-everything at once upgrade.

Plan was to run with optimizer_features_enable set to 9.2.0, various other parameters set to current production settings and to capture 9i plans into a baseline.

Initial runs of “The Batch” started, all processes reported as slow. The initial major contributor turns out to be recursive SQL related to SQL Plan Baseline Capture (see bug#11600319, also bug #11719151 and doc id 1295054.1 – thanks to Timur Akhmadeev for the pointers)

I haven’t yet raised this with Oracle Support because a) I can’t face the wait for a response and b) local red tape means that patches need to be approved by the DB Engineering team and approval for non-production environments is difficult (I’m not going there, not now).

Bug # 11719151 – “RECURSIVE MERGE WHEN optimizer_capture_sql_plan_baseline=true DOING FTS” – is certainly relevant.
The MERGE statement into SQLOBJ$AUXDATA does use a FULL TABLE SCAN. But if I were to show you the AWR reports then you’d see the MERGE statement into SQLOBJ$DATA was the bigger problem and the MERGE statement into SQLOBJ$ also not insignificant.

 

Pick a metric, any metric:
3 out of the top 10 by Elapsed Time, 2 out of the top 5, 1 of the top 1.

1 2 3 4 5 6 7 8 9 10 11

Elapsed                  Elapsed Time         Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id ---------------- -------------- ------------- ------ ------ ------ -------------          6,481.5        242,111          0.03   43.2   22.6   56.1 1vxm21mhmgy07 MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE            2,403.4        242,108          0.01   16.0   95.4    3.9 44z7snw61qx9x MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,              898.7        242,111          0.00    6.0   98.6     .1 7xm5j53mxbtpn MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,

By CPU Time:

1 2 3 4 5 6 7 8 9 10 11 12

CPU                   CPU per           Elapsed   Time (s)  Executions    Exec (s) %Total   Time (s)   %CPU    %IO    SQL Id ---------- ------------ ---------- ------ ---------- ------ ------ -------------    2,292.8      242,108       0.01   39.9    2,403.4   95.4    3.9 44z7snw61qx9x MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,        1,464.0      242,111       0.01   25.5    6,481.5   22.6   56.1 1vxm21mhmgy07 MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE        885.7      242,111       0.00   15.4      898.7   98.6     .1 7xm5j53mxbtpn MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,

By Gets:

1 2 3 4 5 6 7 8 9 10 11

Buffer                 Gets              Elapsed       Gets   Executions   per Exec   %Total   Time (s)   %CPU    %IO    SQL Id ----------- ----------- ------------ ------ ---------- ------ ------ -----------  49,599,141     242,108        204.9   46.9    2,403.4   95.4    3.9 44z7snw61qx MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,    29,107,449     242,111        120.2   27.5    6,481.5   22.6   56.1 1vxm21mhmgy MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE    16,671,818     242,111         68.9   15.7      898.7   98.6     .1 7xm5j53mxbt MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,

By executions:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15

Executions   Rows Processed  Rows per Exec   Time (s)   %CPU    %IO    SQL Id ------------ --------------- -------------- ---------- ------ ------ -----------      242,111         242,111            1.0    6,481.5   22.6   56.1 1vxm21mhmgy MERGE INTO sqlobj$data USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET comp_data = :2 WHERE        242,111         242,111            1.0      898.7   98.6     .1 7xm5j53mxbt MERGE INTO sqlobj$ USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET name = :2,          242,111         242,074            1.0       34.6   95.7     .2 9zr2sbbp1d4 SELECT /*+ INDEX(sqlobj$ (name obj_type)) */ signature, category FROM sqlobj$ WHERE name = :1 AND obj_type = :2        242,108         242,108            1.0    2,403.4   95.4    3.9 44z7snw61qx MERGE INTO sqlobj$auxdata USING dual ON (:1 IS NULL) WHEN MATCHED THEN UPDATE SET description = :2,

So, you get the message.

Furthermore, at the top of every Segment Statistic by X Metric, it’s either one of the LOBs or the LOB Index related to these three tables.

By the way, what’s in these SQLOBJ$ tables – no surprises it’s the baseline data.
See also:
Kerry Osborne – Do SQL Baselines Use Hints/
Christian Antognini – SQL Profiles in the Data Dictionary
Christian Antognini – Troubleshooting Oracle Performance

If I move over to the ASH data and give an example of what that was showing, then we can go and look at those SQLOBJ$ tables for the SQL concerned.

The ASH data – probably my most favorite feature of the last few years – I’m only displaying a little bit of in terms of height and width. But it illustrates the second point I wanted to highlight – that recursive SQL is not properly reported. Whilst the SQL_ID column differs from the TOP_LEVEL_SQL_ID (which I’ve omitted to keep it slim), this is still the SQL Id of a nested lookup, not the SQL Id of the recursive MERGE which you might have expected – I can see pros and cons of both I suppose.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67

1  select to_char(sample_time,'HH24:MI:SS') sample_time, session_id, sql_id   2  ,      sql_plan_operation, event   3  from   v$active_session_history   4  where  session_id      = 1388   5  and    session_serial# = 147   6  and    sample_id between 14596749 and 14596800   7* order by sample_id SQL> /   SAMPLE_T SESSION_ID SQL_ID        SQL_PLAN_OPERATION             EVENT -------- ---------- ------------- ------------------------------ ----------------------------------- 10:57:04       1388 d99anrdgbb4jf SELECT STATEMENT 10:57:05       1388                                              log file sync 10:57:06       1388 d99anrdgbb4jf 10:57:07       1388 d99anrdgbb4jf MERGE                          direct path write 10:57:08       1388 d99anrdgbb4jf MERGE                          flashback log file sync 10:57:09       1388 d99anrdgbb4jf                                direct path read 10:57:10       1388 d99anrdgbb4jf MERGE                          buffer busy waits 10:57:11       1388 d99anrdgbb4jf SELECT STATEMENT               latch: shared pool 10:57:12       1388 d99anrdgbb4jf MERGE                          direct path read 10:57:13       1388 d99anrdgbb4jf TABLE ACCESS 10:57:14       1388 d99anrdgbb4jf INDEX 10:57:15       1388 d99anrdgbb4jf MERGE                          direct path write 10:57:16       1388 d99anrdgbb4jf TABLE ACCESS 10:57:17       1388 d99anrdgbb4jf TABLE ACCESS 10:57:18       1388 d99anrdgbb4jf                                direct path read 10:57:19       1388 d99anrdgbb4jf TABLE ACCESS 10:57:20       1388 d99anrdgbb4jf MERGE 10:57:21       1388                                              log file sync 10:57:22       1388                                              log file sync 10:57:23       1388 d99anrdgbb4jf MERGE                          direct path write 10:57:24       1388 d99anrdgbb4jf MERGE                          direct path write 10:57:25       1388 d99anrdgbb4jf TABLE ACCESS 10:57:26       1388 d99anrdgbb4jf                                direct path read 10:57:27       1388 d99anrdgbb4jf                                direct path read 10:57:28       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:29       1388 d99anrdgbb4jf MERGE 10:57:30       1388                                              log file sync 10:57:31       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:32       1388 d99anrdgbb4jf MERGE 10:57:33       1388 d99anrdgbb4jf INDEX 10:57:34       1388 d99anrdgbb4jf MERGE                          buffer busy waits 10:57:35       1388 d99anrdgbb4jf MERGE                          buffer busy waits 10:57:36       1388 d99anrdgbb4jf MERGE                          flashback log file sync 10:57:37       1388 d99anrdgbb4jf MERGE                          direct path write 10:57:38       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:39       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:40       1388 d99anrdgbb4jf MERGE                          buffer busy waits 10:57:41       1388 d99anrdgbb4jf MERGE                          enq: TX - index contention 10:57:42       1388 d99anrdgbb4jf MERGE                          buffer busy waits 10:57:43       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:44       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:45       1388                                              log file sync 10:57:46       1388 d99anrdgbb4jf TABLE ACCESS 10:57:47       1388 d99anrdgbb4jf MERGE                          flashback log file sync 10:57:48       1388 d99anrdgbb4jf MERGE JOIN 10:57:49       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:50       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:51       1388 d99anrdgbb4jf TABLE ACCESS 10:57:52       1388 d99anrdgbb4jf MERGE                          direct path write 10:57:53       1388 d99anrdgbb4jf TABLE ACCESS 10:57:54       1388 d99anrdgbb4jf MERGE                          db file sequential read 10:57:55       1388 d99anrdgbb4jf SELECT STATEMENT   52 rows selected.   SQL>

By the way, I was also a little surprised to see the direct path read/write operations in the ASH data but these SQLOBJ$ tables that we’re constantly MERGING into recursively have LOBS and further investigation revealed these events to be associated with those LOB segments.

As you can see from above, lots of MERGE operations which have nothing directly to do with SQL_ID d99anrdgbb4jf which looks like the statement below. By the time I’ve got to some of this data for the purposes of this, it’s gone from V$SQL so I’m fetched it from AWR.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25

SQL> select * from table(dbms_xplan.display_awr('d99anrdgbb4jf'));   PLAN_TABLE_OUTPUT ----------------------------------------------------------------------------------- SQL_ID d99anrdgbb4jf -------------------- SELECT XXXX_XXX FROM XXXX_XXXX WHERE XXXX_XXXX = 'MSD' AND XXXX_XXXX =:B1   Plan hash value: 878181930   ------------------------------------------------------------------------------- | Id  | Operation                   | Name            | Rows  | Bytes | Cost  | ------------------------------------------------------------------------------- |   0 | SELECT STATEMENT            |                 |       |       |     2 | |   1 |  TABLE ACCESS BY INDEX ROWID| XXXX_XXXX       |     1 |    18 |     2 | |   2 |   INDEX RANGE SCAN          | XXXX_XXXX_IDX_1 |     1 |       |     2 | -------------------------------------------------------------------------------   Note -----    - cpu costing is off (consider enabling it)   19 rows selected.   SQL>

Baselines are stored according to signature. SQL statements have hash_values, sql ids and also exact/force matching signatures. By the way, the latter can be translated from the text of the sql statement using DBMS_SQLTUNE.SQLTEXT_TO_SIGNATURE using the FORCE_MATCH parameter for either the exact or force matching signature.

In AWR, we’ve only got the FORCE_MATCHING_SIGNATURE of this sql statement sql_id ‘d99anrdgbb4jf’ but take it was the same as the EXACT_MATCHING_SIGNATURE.

1 2 3 4 5 6 7 8 9

SQL> select distinct sql_id, force_matching_signature, to_char(force_matching_signature)   2  from dba_hist_sqlstat   3  where sql_id = 'd99anrdgbb4jf';   SQL_ID        FORCE_MATCHING_SIGNATURE TO_CHAR(FORCE_MATCHING_SIGNATURE) ------------- ------------------------ ---------------------------------------- d99anrdgbb4jf               3.9882E+17 398819076860959259   SQL>

I used this signature to see what was happening with the baseline data.

There’s not much point in me pasting the outputs of those tables. I could see that the SYS.SQLOBJ$.LAST_EXECUTED, SYS.SQLOBJ$AUXDATA.CREATED (!?!) and SYS.SQLOBJ$AUXDATA.LAST_MODIFIED were being updated although not the additional metrics like BUFFER_GETS, EXECUTIONS, etc in SYS.SQLOBJ$DATA.

But then I flushed the cache and like that … the performance degradation was gone and not reproducible… for now.

That’s all there is really.

Oh, by the way, I did trace one session while it was reproducing. Below are some of the relevant bits.
I was using a simple slow-by-slow lookup because I was then going to use concurrent sessions which initially were causing me problems with SMO rowcache lock contention – quite possibly related again to the baselines, but I never got that far into the investigation before we flashed it all back and turned off capture.
Also, looping lookups were relevant to one of the bug notes above and are very much representative of some of the legacy Pro*C codebase.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582 583 584 585 586 587 588 589 590 591 592 593 594 595 596 597 598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614 615 616 617 618 619 620 621 622 623 624 625 626 627 628 629 630 631 632 633 634 635 636 637 638 639 640 641 642 643 644 645 646 647 648 649 650 651 652 653 654 655 656 657 658 659 660 661 662 663 664 665 666 667 668 669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691 692 693 694 695 696 697 698

... BEGIN  DBMS_OUTPUT.DISABLE;  FOR r IN (SELECT * FROM t1)  LOOP      FOR x IN (SELECT id FROM t1 WHERE code = r.code)      LOOP        DBMS_OUTPUT.PUT_LINE(x.id);      END LOOP;  END LOOP; END;   call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.01       0.01          0          0          0           0 Execute      1      1.07       1.10          0          0          0           0 Fetch        0      0.00       0.00          0          0          0           0 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        2      1.08       1.11          0          0          0           0   Misses in library cache during parse: 1 Optimizer mode: CHOOSE Parsing user id: 4106    Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   SQL*Net break/reset to client                   2        0.00          0.00   SQL*Net message to client                       1        0.00          0.00   SQL*Net message from client                     1        0.00          0.00   log file sync                                   1        0.06          0.06 ********************************************************************************   ....   SQL ID: 0jjc60pmrntdv Plan Hash: 3617692013 SELECT * FROM  T1     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.00       0.00          0          0          1           0 Execute      1      0.00       0.00          0          0          0           0 Fetch       66      0.01       0.01          0        279          0        6600 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total       68      0.01       0.02          0        279          1        6600   Misses in library cache during parse: 1 Optimizer mode: CHOOSE Parsing user id: 4106     (recursive depth: 1)   Rows     Row Source Operation -------  ---------------------------------------------------    6600  TABLE ACCESS FULL T1 (cr=279 pr=0 pw=0 time=13232 us cost=498 size=22700000 card=100000)   ********************************************************************************   SQL ID: 33kddu0j5ykq6 Plan Hash: 2946553998 SELECT ID FROM  T1 WHERE CODE = :B1     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.00       0.00          0          0          0           0 Execute   6507     18.15      37.59       6504      54980       6523           0 Fetch     6506      0.28       0.28          0      26024          0        6506 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total    13014     18.43      37.88       6504      81004       6523        6506   Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: CHOOSE Parsing user id: 4106     (recursive depth: 1)   Rows     Row Source Operation -------  ---------------------------------------------------       1  TABLE ACCESS BY INDEX ROWID T1 (cr=4 pr=0 pw=0 time=233 us cost=2 size=26 card=1)       1   INDEX UNIQUE SCAN I1 (cr=3 pr=0 pw=0 time=211 us cost=1 size=0 card=1)(object id 97386)     Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   latch: cache buffers chains                    22        0.00          0.00   library cache: mutex X                          4        0.00          0.00   latch: shared pool                              8        0.00          0.00 ********************************************************************************   SQL ID: 9zr2sbbp1d4fs Plan Hash: 2462756431 SELECT /*+ INDEX(sqlobj$ (name obj_type)) */ signature, category              FROM  sqlobj$                                                                    WHERE name = :1                                                                       AND obj_type = :2     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse      435      0.01       0.01          0          0          0           0 Execute    435      0.06       0.06          0          0          0           0 Fetch      435      0.01       0.02          1        871          0         434 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total     1305      0.09       0.10          1        871          0         434   Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       0  INDEX RANGE SCAN I_SQLOBJ$NAME_TYPE (cr=3 pr=1 pw=0 time=10195 us cost=1 size=54 card=1)(object id 199)     Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   Disk file operations I/O                        1        0.00          0.00   db file sequential read                         1        0.00          0.00 ********************************************************************************   SQL ID: 47y3mqvyhpkvs Plan Hash: 1888265482 SELECT obj_type, plan_id, name, flags, last_executed                          FROM  sqlobj$                                                                    WHERE signature = :1                                                                  AND category = :2     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.00       0.00          0          0          0           0 Execute      1      0.00       0.00          0          0          0           0 Fetch        1      0.00       0.00          0          2          0           0 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        3      0.00       0.00          0          2          0           0   Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       0  INDEX RANGE SCAN SQLOBJ$_PKEY (cr=2 pr=0 pw=0 time=51 us cost=1 size=74 card=1)(object id 198)   ********************************************************************************   ....   SQL ID: 7xm5j53mxbtpn Plan Hash: 2110601055 MERGE INTO sqlobj$                                                              USING dual ON (:1 IS NULL)                                                      WHEN MATCHED THEN                                                                 UPDATE SET name = :2,                                                                      flags = :3,                                                                     last_executed = :4                                                   WHERE signature = :5                                                                  AND category = :6                                                               AND obj_type = :7                                                               AND plan_id = :8                                                        WHEN NOT MATCHED THEN                                                             INSERT (signature, category, obj_type, plan_id, name,                                   flags, last_executed)                                                   VALUES (:9, :10, :11, :12, :13, :14, :15)     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse     6505      0.35       0.37          0          0          0           0 Execute   6505     29.78      31.78         52     430259      13126        6505 Fetch        0      0.00       0.00          0          0          0           0 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total    13010     30.13      32.16         52     430259      13126        6505   Misses in library cache during parse: 1 Misses in library cache during execute: 2 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       0  MERGE  SQLOBJ$ (cr=2 pr=0 pw=0 time=748 us)       1   VIEW  (cr=2 pr=0 pw=0 time=202 us)       1    MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=198 us cost=7 size=162488 card=2138)       1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=169 us cost=2 size=2 card=1)       0     VIEW  (cr=0 pr=0 pw=0 time=7 us cost=5 size=158212 card=2138)       0      FILTER  (cr=0 pr=0 pw=0 time=3 us)       0       INDEX FAST FULL SCAN SQLOBJ$_PKEY (cr=0 pr=0 pw=0 time=0 us cost=9 size=158212 card=2138)(object id 198)     Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   latch: cache buffers chains                    23        0.00          0.00   db file sequential read                        52        0.89          1.03   buffer busy waits                              65        0.00          0.00   log file switch completion                      4        0.24          0.44   library cache: mutex X                          2        0.00          0.00 ********************************************************************************   SQL ID: 44z7snw61qx9x Plan Hash: 1133963577 MERGE INTO sqlobj$auxdata                                                       USING dual ON (:1 IS NULL)                                                      WHEN MATCHED THEN                                                                 UPDATE SET description = :2,                                                               creator = nvl(:3, creator),                                                     origin = :4,                                                                    version = :5,                                                                   created = :6,                                                                   last_modified = :7,                                                             last_verified = nvl(:8, last_verified),                                         parse_cpu_time = null,                                                          optimizer_cost = nvl(:9, optimizer_cost),                                       module = nvl(:10, module),                                                      action = nvl(:11, action),                                                      priority = nvl(:12, priority),                                                  optimizer_env = nvl(:13,   optimizer_env),                                      bind_data = nvl(:14,   bind_data),                                                parsing_schema_name = nvl(:15, parsing_schema_name),                            executions = nvl(:16, executions),                                              elapsed_time = nvl(:17, elapsed_time),                                          cpu_time = nvl(:18, cpu_time),                                                  buffer_gets = nvl(:19, buffer_gets),                                            disk_reads = nvl(:20, disk_reads),                                              direct_writes = nvl(:21, direct_writes),                                        rows_processed = nvl(:22, rows_processed),                                      fetches = nvl(:23, fetches),                                                    end_of_fetch_count = nvl(:24, end_of_fetch_count),                              task_id = nvl(:25, task_id),                                                    task_exec_name = nvl(:26, task_exec_name),                                      task_obj_id = nvl(:27, task_obj_id),                                            task_fnd_id = nvl(:28, task_fnd_id),                                            task_rec_id = nvl(:29, task_rec_id),                                            flags = 0,                                                                      spare1 = null,                                                                  spare2 = null                                                        WHERE signature = :30                                                                 AND category = :31                                                              AND obj_type = :32                                                              AND plan_id = :33                                                       WHEN NOT MATCHED THEN                                                             INSERT (signature, category, obj_type,   plan_id,                                       description, creator, origin,    version,                                        created, last_modified,   last_verified, parse_cpu_time,                        optimizer_cost,   module, action, priority,                                     optimizer_env,    bind_data, parsing_schema_name, executions,                      elapsed_time, cpu_time, buffer_gets, disk_reads,                                direct_writes, rows_processed, fetches,end_of_fetch_count,                      task_id, task_exec_name, task_obj_id, task_fnd_id,                              task_rec_id, flags, spare1, spare2)                                     VALUES (:34, :35, :36, :37,                                                             :38, :39, :40, :41,                                                             :42, :43, null, null,                                                           :44, :45, :46, :47,                                                             :48, :49, :50, :51,                                                             :52, :53, :54, :55,                                                             :56, :57, :58, :59,                                                             :60, :61, :62, :63,                                                             :64, 0, null, null)     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse     6504      0.47       0.49          0          0          0           0 Execute   6504     66.69      70.05        429    1631914      14302        6504 Fetch        0      0.00       0.00          0          0          0           0 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total    13008     67.16      70.55        429    1631914      14302        6504   Misses in library cache during parse: 1 Misses in library cache during execute: 2 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       0  MERGE  SQLOBJ$AUXDATA (cr=3 pr=0 pw=0 time=810 us)       1   VIEW  (cr=2 pr=0 pw=0 time=134 us)       1    MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=122 us cost=18 size=784646 card=2138)       1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=91 us cost=2 size=2 card=1)       0     VIEW  (cr=0 pr=0 pw=0 time=15 us cost=16 size=780370 card=2138)       0      FILTER  (cr=0 pr=0 pw=0 time=2 us)       0       TABLE ACCESS FULL SQLOBJ$AUXDATA (cr=0 pr=0 pw=0 time=0 us cost=20 size=780370 card=2138)     Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   Disk file operations I/O                        2        0.00          0.00   db file sequential read                       429        0.29          2.56   buffer busy waits                              58        0.00          0.00   latch: cache buffers chains                    25        0.00          0.00   log file switch completion                      1        0.05          0.05   latch: object queue header operation            1        0.00          0.00   library cache: mutex X                          2        0.00          0.00 ********************************************************************************   SQL ID: 1vxm21mhmgy07 Plan Hash: 984916430 MERGE INTO sqlobj$data                                                          USING dual ON (:1 IS NULL)                                                      WHEN MATCHED THEN                                                                 UPDATE SET comp_data = :2                                                       WHERE signature = :3                                                                  AND category = :4                                                               AND obj_type = :5                                                               AND plan_id = :6                                                        WHEN NOT MATCHED THEN                                                             INSERT (signature, category, obj_type, plan_id, comp_data,                               spare1, spare2)                                                         VALUES (:7, :8, :9, :10, :11, null, null)     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse     6053      0.35       0.36          0          0          0           0 Execute   6053     38.42     192.12      14420     500403     235414        6053 Fetch        0      0.00       0.00          0          0          0           0 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total    12106     38.78     192.48      14420     500403     235414        6053   Misses in library cache during parse: 1 Misses in library cache during execute: 2 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       0  MERGE  SQLOBJ$DATA (cr=43 pr=2 pw=1 time=8478 us)       1   VIEW  (cr=2 pr=0 pw=0 time=140 us)       1    MERGE JOIN OUTER (cr=2 pr=0 pw=0 time=131 us cost=9 size=303596 card=2138)       1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=109 us cost=2 size=2 card=1)       0     VIEW  (cr=0 pr=0 pw=0 time=5 us cost=7 size=299320 card=2138)       0      FILTER  (cr=0 pr=0 pw=0 time=3 us)       0       INDEX FAST FULL SCAN SQLOBJ$DATA_PKEY (cr=0 pr=0 pw=0 time=0 us cost=6 size=299320 card=2138)(object id 205)     Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   db file sequential read                      8367        1.04         43.76   flashback log file sync                      7828        0.26         25.34   direct path write                            6052        0.47         36.62   direct path read                             6045        0.42         16.34   enq: HW - contention                         1138        0.89         24.42   Disk file operations I/O                       12        0.00          0.00   latch: cache buffers chains                   860        0.00          0.03   buffer busy waits                             764        1.00          6.00   read by other session                          24        0.03          0.34   latch: enqueue hash chains                      2        0.00          0.00   enq: TX - index contention                     57        0.05          0.21   buffer deadlock                                11        0.00          0.00   latch free                                      2        0.00          0.00   library cache: mutex X                          8        0.00          0.00   latch: cache buffers lru chain                  4        0.00          0.00   log file switch (checkpoint incomplete)         3        0.14          0.28   enq: TX - allocate ITL entry                    1        0.00          0.00   latch: undo global data                         1        0.00          0.00   .....     SQL ID: 1zatw56z32vcg Plan Hash: 1469453527 SELECT obj_type, plan_id, description, creator, origin,                                created, last_modified                                                     FROM  sqlobj$auxdata                                                             WHERE signature = :1                                                                  AND category = :2     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse     6505      0.10       0.12          0          0          0           0 Execute   6505      0.91       0.96          0          0          0           0 Fetch    13010      0.30       0.29          0      26020          0        6505 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total    26020      1.32       1.38          0      26020          0        6505   Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       1  TABLE ACCESS BY INDEX ROWID SQLOBJ$AUXDATA (cr=4 pr=0 pw=0 time=87 us cost=2 size=315 card=1)       1   INDEX RANGE SCAN I_SQLOBJ$AUXDATA_PKEY (cr=3 pr=0 pw=0 time=51 us cost=1 size=0 card=1)(object id 209)     Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   latch: cache buffers chains                     5        0.00          0.00 ********************************************************************************   SQL ID: bt51szvfrcdpn Plan Hash: 1876815449 SELECT obj_type, plan_id, comp_data                                           FROM  sqlobj$data                                                                WHERE signature = :1                                                                  AND category = :2     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse     6504      0.13       0.12          0          0          0           0 Execute   6504      0.82       0.82          0          0          0           0 Fetch    13008      0.28       0.32          0      19516          0        6504 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total    26016      1.24       1.27          0      19516          0        6504   Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       1  INDEX RANGE SCAN SQLOBJ$DATA_PKEY (cr=3 pr=0 pw=0 time=89 us cost=1 size=140 card=1)(object id 205)     Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   latch: cache buffers chains                    17        0.00          0.00 ********************************************************************************   SQL ID: 1vxm21mhmgy07 Plan Hash: 2462756431 MERGE INTO sqlobj$data                                                          USING dual ON (:1 IS NULL)                                                      WHEN MATCHED THEN                                                                 UPDATE SET comp_data = :2                                                       WHERE signature = :3                                                                  AND category = :4                                                               AND obj_type = :5                                                               AND plan_id = :6                                                        WHEN NOT MATCHED THEN                                                             INSERT (signature, category, obj_type, plan_id, comp_data,                               spare1, spare2)                                                         VALUES (:7, :8, :9, :10, :11, null, null)     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse     6523      0.18       0.19          0          0          0           0 Execute   6523      3.15       8.90       1059      34474      17486         452 Fetch     6071      0.22       0.20          0      12142          0        6071 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total    19117      3.55       9.30       1059      46616      17486        6523   Misses in library cache during parse: 0 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       0  MERGE  SQLOBJ$DATA (cr=79 pr=3 pw=1 time=16359 us)    2440   VIEW  (cr=43 pr=0 pw=0 time=15141 us)    2440    MERGE JOIN OUTER (cr=43 pr=0 pw=0 time=13065 us cost=9 size=303596 card=2138)       1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=59 us cost=2 size=2 card=1)    2440     VIEW  (cr=41 pr=0 pw=0 time=7394 us cost=7 size=299320 card=2138)    2440      FILTER  (cr=41 pr=0 pw=0 time=6050 us)    2440       INDEX FAST FULL SCAN SQLOBJ$DATA_PKEY (cr=41 pr=0 pw=0 time=3971 us cost=6 size=299320 card=2138)(object id 205)     Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   db file sequential read                       607        0.09          1.96   direct path read                              450        0.03          0.51   flashback log file sync                       592        0.01          1.51   direct path write                             452        0.02          1.02   latch: cache buffers chains                    72        0.00          0.00   buffer busy waits                              54        0.00          0.01   enq: HW - contention                           70        0.04          0.61   enq: TX - index contention                      8        0.00          0.00   read by other session                           1        0.01          0.01 ********************************************************************************   SQL ID: 44z7snw61qx9x Plan Hash: 1133963577   *** 2011-03-01 11:38:27.933 MERGE INTO sqlobj$auxdata                                                       USING dual ON (:1 IS NULL)                                                      WHEN MATCHED THEN                                                                 UPDATE SET description = :2,                                                               creator = nvl(:3, creator),                                                     origin = :4,                                                                    version = :5,                                                                   created = :6,                                                                   last_modified = :7,                                                             last_verified =   nvl(:8, last_verified),                                         parse_cpu_time = null,                                                          optimizer_cost = nvl(:9, optimizer_cost),                                       module = nvl(:10, module),                                                      action = nvl(:11, action),                                                      priority = nvl(:12, priority),                                                  optimizer_env = nvl(:13, optimizer_env),                                        bind_data = nvl(:14, bind_data),                                                parsing_schema_name = nvl(:15, parsing_schema_name),                            executions = nvl(:16, executions),                                              elapsed_time = nvl(:17, elapsed_time),                                          cpu_time = nvl(:18, cpu_time),                                                  buffer_gets = nvl(:19, buffer_gets),                                            disk_reads = nvl(:20, disk_reads),                                              direct_writes = nvl(:21, direct_writes),                                        rows_processed = nvl(:22, rows_processed),                                      fetches = nvl(:23, fetches),                                                    end_of_fetch_count = nvl(:24,   end_of_fetch_count),                            task_id = nvl(:25, task_id),                                                     task_exec_name = nvl(:26,   task_exec_name),                                    task_obj_id = nvl(:27,   task_obj_id),                                          task_fnd_id =   nvl(:28, task_fnd_id),                                          task_rec_id   = nvl(:29, task_rec_id),                                          flags = 0,                                                                       spare1 =    null,                                                                  spare2 = null                                                      WHERE   signature = :30                                                                 AND category = :31                                                              AND obj_type = :32                                                              AND plan_id = :33                                                       WHEN NOT MATCHED THEN                                                             INSERT (signature, category, obj_type, plan_id,                                         description, creator, origin, version,                                          created, last_modified, last_verified, parse_cpu_time,                          optimizer_cost, module, action, priority,                                       optimizer_env, bind_data, parsing_schema_name,   executions,                    elapsed_time, cpu_time, buffer_gets,   disk_reads,                              direct_writes, rows_processed,   fetches,end_of_fetch_count,                    task_id, task_exec_name,   task_obj_id, task_fnd_id,                            task_rec_id, flags,   spare1, spare2)                                   VALUES (:34, :35, :36,   :37,                                                           :38, :39,   :40, :41,                                                           :42,   :43, null, null,                                                           :44, :45, :46, :47,                                                             :48, :49, :50, :51,                                                             :52, :53, :54, :55,                                                             :56, :57, :58, :59,                                                             :60, :61, :62, :63,                                                             :64   call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.00       0.00          0          0          0           0 Execute      1      0.00       0.00          0        252          2           1 Fetch        0      0.00       0.00          0          0          0           0 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        2      0.00       0.00          0        252          2           1   Misses in library cache during parse: 0 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 2)   Rows     Row Source Operation -------  ---------------------------------------------------       0  MERGE  SQLOBJ$AUXDATA (cr=252 pr=0 pw=0 time=4892 us)    2440   VIEW  (cr=252 pr=0 pw=0 time=7181 us)    2440    MERGE JOIN OUTER (cr=252 pr=0 pw=0 time=5835 us cost=18 size=784646 card=2138)       1     TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=71 us cost=2 size=2 card=1)    2440     VIEW  (cr=250 pr=0 pw=0 time=4912 us cost=16 size=780370 card=2138)    2440      FILTER  (cr=250 pr=0 pw=0 time=3808 us)    2440       TABLE ACCESS FULL SQLOBJ$AUXDATA (cr=250 pr=0 pw=0 time=2953 us cost=20 size=780370 card=2138)   ********************************************************************************   SQL ID: bsa0wjtftg3uw Plan Hash: 2020579421 select file# from  file$ where ts#=:1     call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.00       0.00          0          0          0           0 Execute      1      0.00       0.00          0          0          0           0 Fetch       15      0.00       0.00          0         29          0          14 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total       17      0.00       0.00          0         29          0          14   Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: CHOOSE Parsing user id: SYS   (recursive depth: 3)   Rows     Row Source Operation -------  ---------------------------------------------------      14  TABLE ACCESS BY INDEX ROWID FILE$ (cr=29 pr=0 pw=0 time=88 us cost=1 size=35 card=5)      14   INDEX RANGE SCAN I_FILE2 (cr=15 pr=0 pw=0 time=151 us cost=1 size=0 card=5)(object id 44)         ********************************************************************************   OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS   call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        2      0.01       0.01          0          0          0           0 Execute      2      1.08       1.14          0          0          1           0 Fetch        0      0.00       0.00          0          0          0           0 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        4      1.09       1.15          0          0          1           0   Misses in library cache during parse: 1   Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   log file sync                                   3        0.06          0.07   SQL*Net message to client                       6        0.00          0.00   SQL*Net message from client                     6       27.68         47.53   reliable message                                1        0.00          0.00   Disk file operations I/O                        3        0.00          0.00   Parameter File I/O                              8        0.01          0.02   SQL*Net break/reset to client                   2        0.00          0.00   direct path read                             6503        0.75         18.96   latch: cache buffers chains                    78        0.00          0.00   buffer busy waits                             103        0.00          0.00   library cache: mutex X                         17        0.00          0.00     OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS   call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse    39047      1.64       1.70          0          0          1           0 Execute  45549    158.03     342.53      22465    2652285     286877       19521 Fetch    39115      1.12       1.16          1      84889          0       32634 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total   123711    160.80     345.40      22466    2737174     286878       52155   Misses in library cache during parse: 21 Misses in library cache during execute: 17   Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   Disk file operations I/O                       15        0.00          0.00   db file sequential read                      9457        1.04         49.35   flashback log file sync                      8420        0.26         26.86   direct path write                            6504        0.47         37.64   direct path read                             6495        0.42         16.86   enq: HW - contention                         1208        0.89         25.03   latch: cache buffers chains                  1024        0.00          0.04   buffer busy waits                             941        1.00          6.02   read by other session                          25        0.03          0.36   latch: enqueue hash chains                      2        0.00          0.00   library cache: mutex X                         16        0.00          0.00   enq: TX - index contention                     65        0.05          0.21   buffer deadlock                                11        0.00          0.00   log file switch completion                      5        0.24          0.50   latch free                                      2        0.00          0.00   latch: shared pool                              8        0.00          0.00   latch: object queue header operation            1        0.00          0.00   latch: cache buffers lru chain                  4        0.00          0.00   log file switch (checkpoint incomplete)         3        0.14          0.28   enq: TX - allocate ITL entry                    1        0.00          0.00   latch: undo global data                         1        0.00          0.00       4  user  SQL statements in session. 19540  internal SQL statements in session. 19544  SQL statements in session. ********************************************************************************     ....          1  session in tracefile.        4  user  SQL statements in trace file.    19540  internal SQL statements in trace file.    19544  SQL statements in trace file.       20  unique SQL statements in trace file.  3288358  lines in trace file.      394  elapsed seconds in trace file.