Case 2: session dominated by I/O waits

Case 2 is a 17 min 9 s session in which the User I/O class adds up to 51.4% of the time and the 323,268 single-block reads to 35.6%. This page walks through the case 2 report in section order, from the summary to the objects, up to the likely cause and what to do. The case shows why to find the statement before speeding up the disk, and what to do when the heaviest statement has no plan in the trace.

Step 1: summary and warning

Before the Summary, the report shows the warning 299276 recursive calls without a matching level-0 call (trace started or cut in the middle of a call). The Summary shows:

• Total time: 1,029.051 s, or 17 min 9 s;
• Database calls: 305,623, 180 of them level-0 calls;
• Waits: 341,608, with 75.177 s between calls;
• Distinct statements: 185, with 65 commits.

Almost all the work is recursive SQL (recursive SQL), and the trace recorded waits. In Longest depth-0 calls, the longest takes 0.044 s: no application call explains 17 minutes. In the same table, 74.823 s from the beginning, there is the PARSE of statement #53, an anonymous PL/SQL block (DECLARE ... BEGIN ... END;) that calls package routines. In the detail of #53, the Calls panel has only that PARSE: the block's EXEC is not in the file, because it was still running when the excerpt ends (trace lines).

The trace therefore has two phases: about 75 s of short application calls and about 954 s inside block #53, up to the end of the file.

See in the report: Case 2 summary. To read it: Summary and Longest depth-0 calls.

Step 2: diagnosis

The Diagnosis lists four findings:

The first finding asks you to look at the plan before the disk, and the View latency distribution link leads to the evidence (step 7). The loop of #1 and #2 exists, but the two add up to 1.3% of the time: fixing them now does not change the case. The findings do not say which statement does the reads: the one that costs the most, #5, has no plan in the excerpt, and without a plan there is no plan finding for it (step 6). The profile and the statements show the size of each thing.

See in the report: Case 2 diagnosis. To read it: Diagnosis.

Step 3: profile

The Response time profile splits the 1,029.051 s into components. The largest:

By wait class, User I/O adds up to 51.4%, Unaccounted-for 23.0%, CPU 18.3% and Idle 7.3%. What the profile supports and what it rules out:

• Slow disk: ruled out as the main cause. The average is 1.132 ms per read: the storage responds fast, and the time comes from the count, 323,268 reads (slow reads). Step 7 confirms it with the distribution.
• Time in the application: only in the first phase. The 74.696 s of SQL*Net message from client fit within the 74.8 s before block #53. It is time outside the database, which SQL tuning does not reduce, and it is not the slow part of the case (session waiting for the application).
• One heavy call, not many. The maximum of 104.206 s of CPU in a single EXEC call shows that one statement concentrates the work. Step 4 says which one.
• Unaccounted-for time: check the server. The 149.483 s within calls are time in which the session was neither on the CPU nor in a recorded wait, and a common cause is CPU queueing (within calls). The 87.678 s between calls are, as in case 1, time in the block between one SQL and another (between calls).

See in the report: Case 2 profile, with the rows db file sequential read and SQL*Net message from client. To read it: Response time profile and Wait classes and recursive SQL.

Step 4: top statements

In Top statements by component and by class, the same statement appears at the top of almost every group: #5, a SELECT that starts with WITH TAB_0082 AS (SELECT DISTINCT.

Second is #7, DELETE FROM TAB_0049 A WHERE A.COL_0086 = :B1, with 55.010 s of EXEC CPU (32.3% of the component) and 41.699 s of unaccounted-for time within calls (27.9%).

In SQL statements by contribution, #5 has a contribution of 0.587 s, but an Inclusive time of 740.853 s: 72.0% of total time in a single statement. The list sorts by contribution, so it sits behind four statements that together add up to less than 21 s inclusive. #5 has depth 2, Exec 1, Fetch 126 and 63,000 rows, with 7,669,408 logical reads (LIO) and 3,528,057 blocks read from disk (PIO). #7 has an Inclusive time of 102.905 s, 10.0% of the total, and deleted 2,953,545 rows in one execution. As in case 1, contribution does not work for ranking: block #53 does not close in the file, and Time not attributed to any statement adds up to 1,017.699 s. Compare by inclusive time.

See in the report: Case 2 statements by component and Case 2 SQL statements. To read them: Statements by component and SQL statements by contribution.

Step 5: statement detail

In the detail of #5, Share of total time is 0.587 s and Inclusive is 740.853 s, with Depth 2, Recursive SQL: the statement runs to serve a depth-1 SQL, inside the block. The Calls panel shows where the time is:

Almost all the time is in the single EXEC call: 688.659 s before the first FETCH returns rows. The 63,000 rows come out in 126 FETCH calls, 500 per FETCH on average: the routine already fetches rows in batches. That is about 122 logical reads and 56 disk blocks for each row returned: the query reads far more than it returns.

The Statement profile adds up to 364.191 s of db file sequential read in 322,865 reads, 104.206 s of EXEC CPU, 98.163 s of unaccounted-for time, 82.616 s of direct path read and 62.222 s of reads and writes in TEMP. These are three kinds of work: block-by-block reads, typical of index and ROWID access; direct reads of a large segment; and a sort or hash that did not fit in memory.

See in the report: statement #5 detail. To read it: Statement detail.

Step 6: plan

The detail of #5 has no Execution plan block, and the Calls panel has no CLOSE: the cursor was still open at the end of the excerpt. The plan comes from the STAT lines, which the trace writes when the cursor closes (19c tracing guide). Without the CLOSE, the STAT lines of #5 never reached the file.

Get the plan from the database, while the cursor is still in the cursor cache, with the sql_id from the detail title (in case 2, d7sadnr6zu6k9):

select *
  from table(dbms_xplan.display_cursor('&sql_id', null, 'ALLSTATS LAST'));

The actual rows and reads of each operation appear only if the execution gathered plan statistics, with the GATHER_PLAN_STATISTICS hint or with STATISTICS_LEVEL set to ALL in the session; without that, the plan shows only the estimates (DBMS_XPLAN reference). In the plan, look for the operation with the most reads and check how many times it executes and how many rows it returns, as in the report plan.

The plan of #7 is in the excerpt. Operation 1, DELETE TAB_0049, has 98.1% of the plan's time and the highlight Wrote 66,842 blocks to TEMP: the PGA workarea was not enough. Operation 2, INDEX RANGE SCAN IDX_0034, returned 2,953,545 rows against 2,943,270 estimated: the estimate is right, so the problem is not statistics (wrong row estimate). In the Calls panel, the single EXEC takes 102.905 s, with 55.010 s of CPU and 13,153,243 reads in Current (CU), the mode used to change data (cu). The cost is in deleting almost 3 million rows, not in finding them: the index took 1.952 s.

See in the report: operation 1 of the #7 plan. To read it: operation that dominates the plan.

Step 7: waits and latency

In Latency distribution, db file sequential read shows 271,109 reads under 1 ms (83.9%), adding up to 99.938 s; 47,699 from 1 to 10 ms, with 186.767 s; and 4,460 above 10 ms, with 79.162 s. Most reads are fast, and the fast part alone adds up to 99.9 s: reducing the count pays off more than speeding up the disk. The tail above 10 ms is worth taking to the storage team, as a secondary item.

In Reads, the First read and reread of the same block table shows 323,225 distinct blocks and only 43 rereads. This is not a small buffer cache forcing the same block to be read again: it is the plan visiting 323,000 different blocks, one at a time.

In Call types, there are 394 PARSE calls for 102,658 EXEC calls: unlike case 1, the routine keeps its cursors open, and parsing is not a problem here.

See in the report: db file sequential read latency, Reads and Call types. To read them: Latency distribution, Reads and Call types.

Step 8: objects

Objects with the most wait time starts with object 192892, with no name, with 404.790 s in 290,860 waits, 39.3% of total time. Next come 202849, with 66.670 s in 33,428 single-block reads, and 192893, with 15.837 s. From step 4, these are objects that #5 reads: it has 99.5% of the db file sequential read time and all of the direct path read.

They have no name because the name comes from the STAT lines, and #5 has none of its own in the excerpt. Identify the objects in the trace's database by object_id:

select owner, object_name, subobject_name, object_type
  from dba_objects
 where object_id in (192892, 202849, 192893);

In the console, the obj# opens the object page, with this query and the ones for columns, indexes and statistics (object page). With the names of the objects and the plan from step 6, you know which table or index #5 reads block by block.

See in the report: Case 2 objects.

What the excerpt does not show

The 2,000,000-line excerpt covers 17 min 9 s of this session. What is left out:

• The end of the routine. Block #53 does not end in the file: the 17 min 9 s are about 75 s before the block and about 954 s inside it, and the duration of the whole routine remains unknown.
• The plan of #5 and the names of the objects. The STAT lines of the heaviest statement never reached the file (steps 6 and 8).
• The rest of the rewrite. #7 deleted 2,953,545 rows from TAB_0049, and #4 wrote 52,500 rows into the same table in 35 executions. If the routine rewrites what it deleted, the excerpt shows only the start of that phase, and the whole routine takes much longer.
• The contribution of each statement. With the block still open, compare by Inclusive (step 4).

To measure the whole routine, turn on tracing before the call and turn it off after it ends, with no size limit on the file (trace cut in the middle). The other limits of a trace are in what WaitScope does not do.

Likely root cause

The routine that block #53 calls spends 72.0% of the excerpt on one query, #5, executed once. To return 63,000 rows, it reads 3,528,057 blocks from disk: 322,865 one at a time, fast, in access typical of an index and ROWID, plus direct reads of a large segment and sorts that spill to TEMP. The disk responds fast; the problem is the volume the plan reads. The second item is #7, which deletes 2,953,545 rows in one execution and takes 10.0% of the time. The loop of #1 and #2 exists, but weighs 1.3%.

What is not the cause: slow disk (average of 1.132 ms per read), a small buffer cache (43 rereads), parsing (394 PARSE calls) and a wrong estimate in the DELETE (2,953,545 rows against 2,943,270 estimated).

What to do

In the database

1. Get the plan of #5 with DBMS_XPLAN.DISPLAY_CURSOR (step 6) and identify objects 192892, 202849 and 192893 (step 8).
2. On each object's page, in the console, check the indexes and statistics of the tables the plan reads block by block: an index that does not serve the filter, or stale statistics that lead the optimizer to access many rows by index (many reads).
3. Check the server's CPU load during the period: the 149.483 s unaccounted for within calls, almost all in #5 and #7, may be CPU queueing (unaccounted-for time within calls).
4. If, with fewer rows reaching the sorts, #5 and #7 still write to TEMP, review the workarea memory through pga_aggregate_target (operation that dominates the plan).
5. Take the 4,460 reads above 10 ms to the storage team, as a secondary item.

In the application

1. With the plan in hand, rewrite #5 to reach the 63,000 rows without visiting millions of blocks: the most selective filter first, with an index that serves it, and HASH JOIN instead of NESTED LOOPS if the plan shows index access over many rows.
2. Review the DELETE and INSERT pair on TAB_0049. If most of the 2,953,545 rows do not change from one execution to the next, change only what changed, for example with MERGE, instead of deleting and writing everything again.
3. After the main fix, merge queries #1 and #2, with 44,591 and 44,590 executions, into the SQL that feeds them, instead of one query per row (row by row in PL/SQL).

How to confirm

Generate a trace of the whole routine, with waits, before and after the change (turn on tracing with DBMS_MONITOR). Compare the Total time, the Occurrences of db file sequential read in the profile and the PIO column of the statement in SQL statements; the many-reads finding should disappear. On the first execution after the change, some blocks may come from disk because they are not yet in the cache: compare measurements taken under the same conditions (the method).