Case 1: time between calls and row-by-row SQL

Case 1 is a 50.8 s session in which 73.6% of the time sits between calls, with no recorded wait, and two recursive statements run 89,112 times each. This page walks through the case 1 report in section order, from the summary to the objects: what each number shows, which hypothesis it supports or rules out and what to check next, up to the likely cause and what to do.

Step 1: summary and warning

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

• Total time: 50.833 s;
• Database calls: 719,114, only 6 of them level-0 calls;
• Waits: 20,320, with 0.166 s between calls;
• Distinct statements: 1,977, with 2 commits.

Almost all calls are recursive SQL, the SQL that runs inside PL/SQL, and not direct requests from the application (recursive SQL). The 20,320 waits show that the trace recorded waits: the unaccounted-for time in this case does not come from a trace without waits. The warning says that some level-0 call started before the file or ends after it.

To find out which one, open Longest depth-0 calls: there are only 6 calls, and the longest takes 0.070 s. It is the PARSE of statement #4, the block BEGIN ROT_0001('***',*** ); END;, which starts 0.068 s from the beginning. In SQL statements, #4 has Exec 0. A call's line is written to the trace only when the call ends (trace lines): the block's EXEC was still running when the excerpt ends. After the PARSE, almost all the time in the case, about 50.7 s, is spent inside that block.

See in the report: Case 1 summary. To read each number: Summary and Longest depth-0 calls.

Step 2: diagnosis

The Diagnosis lists nine findings, in order of severity. Those repeated for #1 and #2 share a single row:

Findings are leads, not conclusions (Diagnosis). The first two describe the same time, 37.419 s. The gaps text suggests tracing turned on and off in the middle of the session, or a process stopped outside the database. Step 1 explains why this time shows up between calls: with the block's EXEC missing from the file, the time the block spends outside the SQL statements falls into no call. The time itself is real: the session spent those 37.419 s inside the routine, between one SQL and the next. The other findings point to the statements it executes: two SELECTs run once per row, each with one PARSE per execution, and INSERTs with literals.

See in the report: Case 1 diagnosis.

Step 3: profile

The Response time profile splits the 50.833 s into components. The largest:

By wait class, Unaccounted-for adds up to 73.7%, CPU 23.8% and User I/O 2.4%. The profile rules out three hypotheses:

• Time in the application. When the application takes time between one request and the next, the session records SQL*Net message from client. Here there are 2 waits and 0.001 s: while the block runs, the application waits for it, not the other way around (session waiting for the application).
• Trace without waits. The trace has 20,320 waits (step 1).
• Slow disk. The whole User I/O class adds up to 2.4%: even if it dropped to zero, total time would fall by that much at most.

What remains is the time inside the block, between one SQL statement and the next: the routine's PL/SQL code working, or the process waiting for its turn on the CPU on a busy server. Divided by the 180,269 executions, it comes to about 0.2 ms between one SQL and the next. The trace does not separate the two, because the block's EXEC line, with its CPU, fell outside the excerpt. The next step shows what the routine executes, and how many times.

See in the report: Case 1 profile and the row unaccounted-for time between calls, whose name opens the card with Where to look. 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 CPU groups show who spent the time the database measured:

• CPU: PARSE dbcalls: #2 with 31.7%, #1 with 30.4% and #3 with 25.7%;
• CPU: FETCH dbcalls: #2 with 50.3% and #1 with 49.2%;
• CPU: EXEC dbcalls: #1 with 41.3% and #2 with 39.5%.

In SQL statements by contribution, #1 and #2 are depth-1 SELECT statements, with 89,112 executions, 89,112 rows and 445,560 logical reads each: one row and 5 logical reads per execution, with no disk reads (PIO 0). Each execution is cheap; the cost is in the count. The three INSERTs with literals into TAB_0001 (#3, #8 and #9) add up to 1,217, 350 and 251 executions, or 1,818, and 89,112 divided by 1,818 is 49: the math suggests that, for each row written to TAB_0001, the routine runs #1 and #2 49 times each.

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

Step 5: statement detail

Open statement #1 from its number in the list or from the View statement #1 link in the Diagnosis. The title carries the badge 49 variants: the statement is a shape that groups 49 texts differing only in their literals. The shape text is:

SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL

The :n marks the place of a number written into the text. The detail shows:

• Variants that cost the most: the listed variants have 7,276 or 7,272 calls, that is, 1,819 or 1,818 executions of four calls each (PARSE, EXEC, FETCH and CLOSE). This matches the 1,818 INSERTs into TAB_0001: each value is queried once per row written. The literals appear as *** because of the mask (variants that cost the most).
• Calls: 89,112 PARSE calls for 89,112 EXEC calls, with 49 Misses: only 49 PARSE calls were hard parses. The others found the cursor in the library cache, but still cost a call and CPU.
• Statement profile: FETCH CPU with 45.3%, PARSE CPU with 31.5% and EXEC CPU with 18.3%, with no waits.

Values in the text, one text per value and one PARSE per execution: the most likely explanation is dynamic SQL built by concatenation inside a loop, with EXECUTE IMMEDIATE or an equivalent. Confirm it in the code of ROT_0001. #3 follows the same pattern: 1,217 INSERTs and 1,217 hard parses, and PARSE CPU is 90.6% of its time. The Shareable texts section groups these shapes, with the SQL IDs hidden by the mask (Shareable texts).

What remains is to find out what TAB_0005 is. #10 is TRUNCATE TABLE TAB_0005, and #16 writes 50 rows into it: it is a work table that the routine empties, fills and then queries 178,224 times. The detail of block #4 confirms step 1: the Calls panel has only the PARSE.

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

Step 6: plan

In the Execution plan of #1, the note says plan written 89115 times, showing the slowest recording. The plan comes from the STAT lines, which the trace writes when the cursor closes (19c tracing guide): a plan written about once per execution is one more sign that the cursor closes and reopens on every use.

The Where the plan spends time panel highlights operation 2, TABLE ACCESS FULL TAB_0005, with 86.5% of the time and 100.0% of the plan's logical reads, and the card suggests checking whether the filter is selective and whether there is an index for it. Read the row before following the suggestion: the operation returns 1 row with 5 logical reads, in 0.000032 s. Reading a 50-row table in full is cheap. An index on COL_0074 would save part of those 5 reads, but not the 178,224 executions or the PARSE calls: here, the plan is not the cause (operation that dominates the plan).

The plan of #7, DELETE FROM TAB_0001, shows a smaller issue: INDEX FULL SCAN IDX_0001 read 1,870 index blocks, and the statement deleted no rows. The table was empty, but the index still occupies those blocks. #7 adds up to 1.023 s, 2.0% of total time.

See in the report: operation 2 of the #1 plan. To read it: Execution plan.

Step 7: waits and latency

The Latency distribution confirms that the disk is not the cause. db file sequential read has 1,962 reads adding up to 1.048 s: 87.3% of them take less than 100 µs, and the 111 that take 1 to 100 ms add up to 92.0% of the event's time. In Reads, the First read and reread of the same block table shows 1,956 distinct blocks and 6 rereads: the cache does not force the same block to be read again. Of the 1,962 reads, 1,870 come from DELETE #7 (step 6).

In Call types, the PARSE row has 180,117 calls and 1,920 Misses: almost all PARSE calls are soft parses, and the hard parses come almost entirely from the texts with literals (many hard parses). The weight is not in the hard parse but in the number of calls: 180,117 PARSE, 180,269 EXEC and 178,460 FETCH calls in 50 s.

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 IDX_0001, with 0.931 s in 1,877 waits, almost all reads by DELETE #7. Next come object 187750, with no name, with 0.165 s in 18,336 direct path read waits, and TAB_0005, with 0.023 s. No object reaches 2% of total time: the time in this case is not spent waiting on an object, and this section only confirms the smaller issue from step 6.

The name comes from the STAT lines of the trace itself, and the unnamed object does not appear in any plan. In the console, the obj# opens the object page, with the queries to identify it in the database (Objects with the most waits).

See in the report: Case 1 objects.

What the excerpt does not show

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

• The end of the routine. The file ends in the middle of block #4. The 50.8 s are the part of the execution that fit in the excerpt, not the duration of the operation; the counts, such as the 89,112 executions, stop there.
• The CPU of the PL/SQL itself. The block's EXEC line would carry its CPU and duration. Without it, the 37.419 s between calls cannot be split between PL/SQL work and waiting for the CPU.
• The contribution of each statement. Without the level-0 call, the Contribution column is incomplete; compare by Inclusive (step 4).
• What comes next. The commit, other phases of the routine and the return to the application are outside the file.

The same applies to a trace of yours turned off before the operation ended, or one that stopped at the file size limit (truncated trace). To measure the whole operation, turn on tracing before it starts and turn it off after it ends (trace cut in the middle).

Likely root cause

The routine ROT_0001, called by block #4, processes row by row. From the math in steps 4 and 5, for each row it writes to TAB_0001, it builds with literals and executes 98 queries against a 50-row work table, 49 of #1 and 49 of #2, plus one INSERT, also with literals. In the excerpt, that comes to about 180,000 SQL executions, almost all with their own PARSE. One by one they are cheap, about 12 s of CPU in total; the larger time, 37.4 s, sits in the PL/SQL between one statement and the next, or in waiting for the CPU.

What is not the cause: the disk (2.4% of the time), the application outside the database (0.001 s of waits) and a missing index on TAB_0005 (5 logical reads per execution).

What to do

In the application

1. Read TAB_0005 once, before the loop, into a PL/SQL collection indexed by the key, and look up the collection inside the loop. This removes the 178,224 queries, their PARSE calls and the PL/SQL spent building and firing each one:

   -- today, most likely: one SQL built with the value in the text, for each key
   execute immediate 'select valor from exemplo_parametros where chave = ' || v_chave
     into v_valor;
   
   -- in memory: the rows read once, before the loop
   declare
     type t_valores is table of exemplo_parametros.valor%type index by pls_integer;
     v_valores t_valores;
   begin
     for r in (select chave, valor from exemplo_parametros) loop
       v_valores(r.chave) := r.valor;
     end loop;
     -- inside the loop, without going to the database: v_valor := v_valores(v_chave);
   end;
   /

2. If possible, replace the whole loop with a single INSERT ... SELECT that joins the source tables with TAB_0005 and writes all the rows of TAB_0001 at once (row by row in PL/SQL).
3. SQL that stays dynamic should receive the values as binds, with USING, and not in the text: one cursor serves all values, and the hard parses drop (literals instead of binds).

In the database

1. Check the server's CPU load during the trace period, from the sar history or from monitoring. If there was CPU queueing, it explains part of the 37.4 s, and the fix also involves the server (unaccounted-for time within calls).
2. Measure the routine with the PL/SQL hierarchical profiler (DBMS_HPROF), which separates SQL time from PL/SQL time by subprogram (profiler documentation). It shows which part of the code holds the 37.4 s.
3. Until the code changes, CURSOR_SHARING=FORCE in the routine's session reduces the 1,920 hard parses. It is a stopgap, it can change plans and it does not remove the executions or the PARSE calls: here, the gain is small (literals instead of binds).
4. When there is time, look at DELETE #7: check the size of IDX_0001 on the object page. If the table is emptied on every execution, consider with whoever maintains the routine replacing the DELETE with TRUNCATE, which also empties the table's indexes. TRUNCATE is DDL: it commits the open transaction and cannot be undone with ROLLBACK (TRUNCATE TABLE).

How to confirm

Turn on tracing with waits before the routine is called and turn it off after it ends, before and after the change (turn on tracing with DBMS_MONITOR). With the whole trace, the block's EXEC line goes into the file, and the time that now appears between calls moves to the block: into CPU: EXEC dbcalls if it is PL/SQL work, or into unaccounted-for time within calls if it is waiting for the CPU. After the change, Database calls and Total time should drop, and the row-by-row and PARSE-per-execution findings should disappear. Compare the analyses by the Total time column in History (the method).