Case 1: time between calls and row-by-row SQL. Sample report, generated by WaitScope from an anonymized excerpt of a real trace. View case 2 Back to the WaitScope page

caso-1.trc

Analyzed on 2026-10-29 10:19:46 · 174.0 MiB · 1,997,223 lines · up to 10 statements per list

718792 recursive calls without a matching level-0 call (trace started or cut in the middle of a call)

Total time

50.833 s

50.8 s

Period

2015-01-16 19:36:52

to 19:37:43

Database calls

719,114

6 at depth 0

Waits

20,320

0.166 s between calls

Distinct statements

1,977

2 commits · 0 rollbacks

Session and environment

Database: Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
Instance: INST_01
Server: MAQ_01 · Linux · x86_64
Session: 151.464 · pid 79628
Service: SYS$USERS
Module: MOD_01
Action
Time unit: microseconds
File on server: caso1.trc

Diagnosis

Patterns that often explain what the trace shows, in order of severity. They are leads for the analysis, not conclusions.

medium unaccounted-for time between calls dominates response time 73.6% of total time

73.6% of the total time (37.419 s) comes from a single component. That is where the analysis starts. View in profile

medium Time gaps between calls 73.6% of total time

Time between level-0 calls with no recorded wait. The trace may have been turned on and off mid-session, or the process was stalled outside the database. View in profile

medium Statement #1 executed 89,112 times 9.7% of total time

Recursive SQL executed once per row, typical of a PL/SQL loop. Set-based processing (a single SQL or FORALL) usually cuts the time a lot. View statement #1

medium Statement #2 executed 89,112 times 9.5% of total time

Recursive SQL executed once per row, typical of a PL/SQL loop. Set-based processing (a single SQL or FORALL) usually cuts the time a lot. View statement #2

low Statement #1: plan operation 2 accounts for 100.0% of logical reads 9.7% of total time

Operation TABLE ACCESS FULL TAB_0005. Reads the whole object: check whether the filter is selective and has an index. The operations are highlighted in the plan, in the statement detail. View in the plan of statement #1

low Statement #2: plan operation 2 accounts for 100.0% of logical reads 9.5% of total time

low Statement #1: one PARSE per execution (89,112 PARSE, 89,112 EXEC) 3.1% of total time

The cursor is opened and closed on every use. Keeping the cursor open in the application (driver statement cache) or session_cached_cursors avoids the repeated PARSE. View statement #1

low Statement #2: one PARSE per execution (89,112 PARSE, 89,112 EXEC) 3.1% of total time

The cursor is opened and closed on every use. Keeping the cursor open in the application (driver statement cache) or session_cached_cursors avoids the repeated PARSE. View statement #2

low Statement #3: 1,217 variants of the same SQL, differing only in literals 2.5% of total time

The application writes the values into the SQL text instead of using bind variables, so each different value becomes a new statement for the database. The variants' 1,217 PARSE calls, 1,217 of them hard parses, took 1.295 s (2.5% of the total time); with all 3,651 calls and the recursive SQL, the variants add up to 1.451 s. The fix is to use bind variables in the application. CURSOR_SHARING=FORCE in the database reduces hard parses while the application does not change, but it is only a stopgap. View statement #3

Response time profile

Each row is a share of the total time; added up, they make 100%. Click a component or class name to see what that time means, when it is normal, when it points to a problem and where to check in the report. Unaccounted-for time is what the trace does not explain by CPU or by waits: inside calls, it is usually CPU queueing or code without instrumentation; a negative value comes from the granularity of the CPU measurement.

Component	Duration (s)	% of total	Occurrences	Avg (s)	Min (s)	Max (s)
unaccounted-for	37.419211	73.6
cpu	5.125233	10.1	180,117	0.000028	0.000000	0.008999
cpu	4.550304	9.0	178,460	0.000025	0.000000	0.008999
cpu	2.189671	4.3	180,269	0.000012	0.000000	0.124981
User I/O	1.047610	2.1	1,962	0.000534	0.000005	0.035303
cpu	0.255954	0.5	180,268	0.000001	0.000000	0.001999
User I/O	0.165164	0.3	18,337	0.000009	0.000003	0.018484
unaccounted-for	0.055133	0.1	719,114	0.000000
Application	0.014392	0.0	1	0.014392	0.014392	0.014392
User I/O	0.008094	0.0	3	0.002698	0.001960	0.003773
Idle	0.001212	0.0	2	0.000606	0.000489	0.000723
Other	0.000616	0.0	3	0.000205	0.000005	0.000385
User I/O	0.000524	0.0	10	0.000052	0.000023	0.000082
Network	0.000007	0.0	2	0.000003	0.000003	0.000004
Total	50.833125	100.0

By wait class

The same components grouped by Oracle wait class (wait_class), with CPU and unaccounted-for time shown separately. The sum is also the total time.

Duration (s)	% of total	Occurrences	Top components
37.474344	73.7		unaccounted-for time between calls · unaccounted-for time within calls
12.121162	23.8	719,114	CPU: PARSE dbcalls · CPU: FETCH dbcalls · CPU: EXEC dbcalls · CPU: CLOSE dbcalls
1.221392	2.4	20,312	db file sequential read · direct path read · local write wait · Disk file operations I/O
0.014392	0.0	1	enq: RO - fast object reuse
0.001212	0.0	2	SQL*Net message from client
0.000616	0.0	3	reliable message
0.000007	0.0	2	SQL*Net message to client

Top statements by component and by class

How much each statement spent in each profile component and each wait class, based on the statement's exclusive profile (without the recursive SQL it triggers). Up to 10 statements per list: change it at the top of the page.

By profile component

CPU: PARSE dbcalls cpu5.125 s · 10.1% of total time · 10 statements

#	Time (s)	% of total	SQL ID	Text
2	1.626753	31.7		49 variants SELECT (SELECT COL_0075 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0075 FROM DUAL
1	1.558749	30.4		49 variants SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
3	1.314810	25.7		1,217 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,:s,NULL,NULL,NULL,NULL…
8	0.352953	6.9		350 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … :s,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL…
9	0.253971	5.0		251 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,…
10	0.008999	0.2	9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005
4	0.004999	0.1	9sxjs1fk1qc9g	BEGIN ROT_0001('*',* ); END;
22	0.002000	0.0	dsn1ksdx81jd4	LOCK TABLE "TAB_0005" IN EXCLUSIVE MODE NOWAIT
54	0.001000	0.0	7umwgdhcjkfap	BEGIN ROT_0005(COL_0056, COL_0057, COL_0058); END;
50	0.000999	0.0	gpynzftxc4j44	select sys.dbms_standard.dictionary_obj_owner from dual

CPU: FETCH dbcalls cpu4.550 s · 9.0% of total time · 10 of 12 statements

#	Time (s)	% of total	SQL ID	Text
2	2.287639	50.3		49 variants SELECT (SELECT COL_0075 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0075 FROM DUAL
1	2.239668	49.2		49 variants SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
11	0.009998	0.2	2vb5a3dnk45pj	SELECT COL_0066 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
17	0.003999	0.1	c1wyt1vcbz2vv	SELECT COL_0068 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
13	0.002000	0.0	6q9x9bmh733r2	select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.cl…
12	0.001000	0.0	5tp7ar1mxbgph	select /+ index(idl_char$ i_idl_char1) +/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
15	0.001000	0.0	0myxy09ts0my0	select /+ index(idl_ub2$ i_idl_ub21) +/ piece#,length,piece from idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
19	0.001000	0.0	7hbqw62s604un	select /+ index(idl_sb4$ i_idl_sb41) +/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
39	0.001000	0.0	da3h6n1cgu01b	SELECT COL_0065 FROM TAB_0002 WHERE COL_0002 = :B3 AND TO_NUMBER(COL_0003) = :B2 AND COL_0001 = :B1
43	0.001000	0.0	88y5z3gq72cmq	SELECT REPLACE(TO_CHAR(COL_0065), :B3 , '*') FROM TAB_0002 WHERE COL_0002 = :B2 AND TO_NUMBER(COL_0003) = :B1 AND COL_0001 = * AND COL_0004 = ***

2 more statements spent time here; raise the number at the top of the page to see them.

CPU: EXEC dbcalls cpu2.190 s · 4.3% of total time · 10 of 29 statements

#	Time (s)	% of total	SQL ID	Text
1	0.903868	41.3		49 variants SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
2	0.864872	39.5		49 variants SELECT (SELECT COL_0075 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0075 FROM DUAL
3	0.152976	7.0		1,217 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,:s,NULL,NULL,NULL,NULL…
7	0.130980	6.0	42q0kx6suxhw2	DELETE FROM TAB_0001
8	0.040994	1.9		350 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … :s,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL…
9	0.034992	1.6		251 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,…
11	0.010998	0.5	2vb5a3dnk45pj	SELECT COL_0066 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
10	0.008998	0.4	9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005
16	0.007998	0.4	0uhffuxsqpvcn	INSERT INTO TAB_0005 VALUES (:COL_0069, :COL_0070, :COL_0071, :COL_0072)
17	0.006999	0.3	c1wyt1vcbz2vv	SELECT COL_0068 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1

19 more statements spent time here; raise the number at the top of the page to see them.

db file sequential read wait1.048 s · 2.1% of total time · 10 of 23 statements

#	Time (s)	% of total	SQL ID	Text
7	0.930878	88.9	42q0kx6suxhw2	DELETE FROM TAB_0001
12	0.023874	2.3	5tp7ar1mxbgph	select /+ index(idl_char$ i_idl_char1) +/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
14	0.016134	1.5	7d78xc7z6vr4f	select o.owner#, o.name, o.namespace, o.obj#, d.COL_0051, nvl(d.property,***), o.type#, o.subname, d.d_attrs from dependency$ d, obj$ o where d.COL_0052=:1 and …
15	0.015738	1.5	0myxy09ts0my0	select /+ index(idl_ub2$ i_idl_ub21) +/ piece#,length,piece from idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
13	0.015645	1.5	6q9x9bmh733r2	select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.cl…
11	0.015414	1.5	2vb5a3dnk45pj	SELECT COL_0066 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
18	0.011204	1.1	1vybmzupqw75h	select /+ index(idl_ub1$ i_idl_ub11) +/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
19	0.009431	0.9	7hbqw62s604un	select /+ index(idl_sb4$ i_idl_sb41) +/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
23	0.002974	0.3	0w81pyhzu3vfj	select COL_0042, COL_0043 from sys.mon_mods_all$ where obj# = :COL_0044
8	0.002529	0.2		350 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … :s,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL…

13 more statements spent time here; raise the number at the top of the page to see them.

CPU: CLOSE dbcalls cpu0.256 s · 0.5% of total time · 3 statements

#	Time (s)	% of total	Text
2	0.130972	51.2	49 variants SELECT (SELECT COL_0075 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0075 FROM DUAL
1	0.123982	48.4	49 variants SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
8	0.001000	0.4	350 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … :s,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL…

direct path read wait0.165 s · 0.3% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
4	0.066395	40.2		9sxjs1fk1qc9g	BEGIN ROT_0001('*',* ); END;

unaccounted-for time within calls unaccounted-for0.055 s · 0.1% of total time · 10 of 41 statements

#	Time (s)	% of total	SQL ID	Text
1	0.114630	207.9		49 variants SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
5	0.037654	68.3	68ngguy15jsj7	alter session set events='***'
6	0.024934	45.2		#140548883950424
16	0.006013	10.9	0uhffuxsqpvcn	INSERT INTO TAB_0005 VALUES (:COL_0069, :COL_0070, :COL_0071, :COL_0072)
20	0.005163	9.4	45zgfwwy872t3	SELECT COUNT(COL_0001) FROM TAB_0002 WHERE COL_0002 = :B2 AND TO_NUMBER(COL_0003) = :B1 AND COL_0001 <> ***
17	0.002849	5.2	c1wyt1vcbz2vv	SELECT COL_0068 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
4	0.001996	3.6	9sxjs1fk1qc9g	BEGIN ROT_0001('*',* ); END;
24	0.000989	1.8	6tamjm552vths	declare TYPE COL_0021 IS REF CURSOR; … ); COL_0029 varchar2(*); COL_0030 varchar2(*); COL_0031 NUMBER; CO…
31	0.000829	1.5	1yjwr52wkx13w	select name,intcol#,segcol#,type#,length,nvl(COL_0014,*),decode(type#,,nvl(scale,-*/MAXSB1MINAL/),,scale,,scale,,scale,,scale,,scale,*…
32	0.000762	1.4	bgv44n2yyz7yq	SELECT /+ ALL_ROWS / COUNT() FROM DBA_POLICIES V WHERE V.COL_0018 = :B3 AND V.COL_0019 = :B2 AND (V.COL_0020 LIKE '' OR V.COL_0020 LIKE '*') AND V.FUNCT…

31 more statements spent time here; raise the number at the top of the page to see them.

enq: RO - fast object reuse wait0.014 s · 0.0% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
10	0.014392	100.0		9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005

local write wait wait0.008 s · 0.0% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
10	0.008094	100.0		9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005

SQL*Net message from client wait0.001 s · 0.0% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
6	0.000723	59.7			#140548883950424
5	0.000489	40.3		68ngguy15jsj7	alter session set events='***'

By wait class

Unaccounted-for37.474 s · 73.7% of total time · 10 of 41 statements

#	Time (s)	% of total	SQL ID	Text
1	0.114630	0.3		49 variants SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
5	0.037654	0.1	68ngguy15jsj7	alter session set events='***'
6	0.024934	0.1		#140548883950424
16	0.006013	0.0	0uhffuxsqpvcn	INSERT INTO TAB_0005 VALUES (:COL_0069, :COL_0070, :COL_0071, :COL_0072)
20	0.005163	0.0	45zgfwwy872t3	SELECT COUNT(COL_0001) FROM TAB_0002 WHERE COL_0002 = :B2 AND TO_NUMBER(COL_0003) = :B1 AND COL_0001 <> ***
17	0.002849	0.0	c1wyt1vcbz2vv	SELECT COL_0068 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
4	0.001996	0.0	9sxjs1fk1qc9g	BEGIN ROT_0001('*',* ); END;
24	0.000989	0.0	6tamjm552vths	declare TYPE COL_0021 IS REF CURSOR; … ); COL_0029 varchar2(*); COL_0030 varchar2(*); COL_0031 NUMBER; CO…
31	0.000829	0.0	1yjwr52wkx13w	select name,intcol#,segcol#,type#,length,nvl(COL_0014,*),decode(type#,,nvl(scale,-*/MAXSB1MINAL/),,scale,,scale,,scale,,scale,,scale,*…
32	0.000762	0.0	bgv44n2yyz7yq	SELECT /+ ALL_ROWS / COUNT() FROM DBA_POLICIES V WHERE V.COL_0018 = :B3 AND V.COL_0019 = :B2 AND (V.COL_0020 LIKE '' OR V.COL_0020 LIKE '*') AND V.FUNCT…

31 more statements spent time here; raise the number at the top of the page to see them.

CPU12.121 s · 23.8% of total time · 10 of 38 statements

#	Time (s)	% of total	SQL ID	Text
2	4.910236	40.5		49 variants SELECT (SELECT COL_0075 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0075 FROM DUAL
1	4.826267	39.8		49 variants SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
3	1.467786	12.1		1,217 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,:s,NULL,NULL,NULL,NULL…
8	0.394947	3.3		350 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … :s,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL…
9	0.288963	2.4		251 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,…
7	0.130980	1.1	42q0kx6suxhw2	DELETE FROM TAB_0001
11	0.020996	0.2	2vb5a3dnk45pj	SELECT COL_0066 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
10	0.017997	0.1	9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005
17	0.010998	0.1	c1wyt1vcbz2vv	SELECT COL_0068 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
16	0.007998	0.1	0uhffuxsqpvcn	INSERT INTO TAB_0005 VALUES (:COL_0069, :COL_0070, :COL_0071, :COL_0072)

28 more statements spent time here; raise the number at the top of the page to see them.

User I/O1.221 s · 2.4% of total time · 10 of 24 statements

#	Time (s)	% of total	SQL ID	Text
7	0.931232	76.2	42q0kx6suxhw2	DELETE FROM TAB_0001
4	0.066395	5.4	9sxjs1fk1qc9g	BEGIN ROT_0001('*',* ); END;
12	0.023874	2.0	5tp7ar1mxbgph	select /+ index(idl_char$ i_idl_char1) +/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
14	0.016134	1.3	7d78xc7z6vr4f	select o.owner#, o.name, o.namespace, o.obj#, d.COL_0051, nvl(d.property,***), o.type#, o.subname, d.d_attrs from dependency$ d, obj$ o where d.COL_0052=:1 and …
15	0.015738	1.3	0myxy09ts0my0	select /+ index(idl_ub2$ i_idl_ub21) +/ piece#,length,piece from idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
13	0.015645	1.3	6q9x9bmh733r2	select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.cl…
11	0.015414	1.3	2vb5a3dnk45pj	SELECT COL_0066 FROM ALL_TAB_COLUMNS WHERE OWNER = '***' AND COL_0063 = :B2 AND COL_0067 = :B1
18	0.011204	0.9	1vybmzupqw75h	select /+ index(idl_ub1$ i_idl_ub11) +/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
19	0.009431	0.8	7hbqw62s604un	select /+ index(idl_sb4$ i_idl_sb41) +/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
10	0.008338	0.7	9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005

14 more statements spent time here; raise the number at the top of the page to see them.

Application0.014 s · 0.0% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
10	0.014392	100.0		9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005

Idle0.001 s · 0.0% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
6	0.000723	59.7			#140548883950424
5	0.000489	40.3		68ngguy15jsj7	alter session set events='***'

Other0.001 s · 0.0% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
10	0.000616	100.0		9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005

Network0.000 s · 0.0% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
6	0.000004	57.1			#140548883950424
5	0.000003	42.9		68ngguy15jsj7	alter session set events='***'

SQL statements by contribution

Contribution: duration of the statement's depth-0 calls plus the waits between calls on its cursor. Inclusive: sum of all the statement's calls, at any depth.

#	Contribution (s)	% of total	Inclusive (s)	Type	Depth	Exec	Fetch	Rows	LIO	PIO	SQL ID	Text
1	1.415	2.8	4.941	SELECT	1	89,112	89,112	89,112	445,560	0		49 variants SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
2	1.405	2.8	4.842	SELECT	1	89,112	89,112	89,112	445,560	0		49 variants SELECT (SELECT COL_0075 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0075 FROM DUAL
3	0.623	1.2	1.451	INSERT	1	1,217	0	1,217	8,761	32		1,217 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,:s,NULL,NULL,NULL,NULL…
4	0.137	0.3	0.070	PL/SQL	0	0	0	0	24	8	9sxjs1fk1qc9g	BEGIN ROT_0001('*',* ); END;
5	0.040	0.1	0.040	ALTER SESSION	0	1	0	0	0	0	68ngguy15jsj7	alter session set events='***'
6	0.027	0.1	0.026	?	0	1	0	0	0	0		#140548883950424
7	0.000	0.0	1.023	DELETE	1	2	0	0	3,740	1,870	42q0kx6suxhw2	DELETE FROM TAB_0001
8	0.000	0.0	0.417	INSERT	1	350	0	350	2,590	18		350 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … :s,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL…
9	0.000	0.0	0.288	INSERT	1	251	0	251	1,800	5		251 variants INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,…
10	0.000	0.0	0.082	TRUNCATE TABLE	1	1	0	0	110	17	9y5d9x2wwc9nn	TRUNCATE TABLE TAB_0005

Rows marked with variants add up statements that differ only in literals; in the text, :s and :n take the place of the literals.

Showing 10 of 65 statements; raise the number at the top of the page to see more.

Time not attributed to any statement: 47.186 s.

Call types

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Current (CU)	Rows	Misses
PARSE	180,117	5.140	5.156	19	126	1	0	1,920
FETCH	178,460	4.550	4.726	28	893,297	0	178,432	0
EXEC	180,269	2.212	3.245	1,940	5,703	11,363	1,878	1
CLOSE	180,268	0.256	0.250	0	0	0	0	0

Longest depth-0 calls

Call	Duration (s)	CPU (s)	Start (+s)	Line	LIO	PIO	Statement
PARSE	0.070229	0.010998	0.068	101	24	8	#4 BEGIN ROT_0001('*',* ); END;
EXEC	0.039483	0.002000	0.028	36	0	0	#5 alter session set events='***'
EXEC	0.025924	0.001000	0.000	27	0	0	#6 #140548883950424
PARSE	0.000157	0.000000	0.027	35	0	0	#5 alter session set events='***'
CLOSE	0.000014	0.000000	0.068	39	0	0	#5 alter session set events='***'
CLOSE	0.000010	0.000000	0.027	30	0	0	#6 #140548883950424

Latency distribution

Buckets in powers of 10, by wait event and by call type. Shows whether the time comes from many fast occurrences or a few slow ones.

db file sequential read1,962 occurrences · 1.048 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	921	46.9	0.007373	0.7
10 µs ≤ e < 100 µs	792	40.4	0.013459	1.3
100 µs ≤ e < 1 ms	138	7.0	0.063020	6.0
1 ms ≤ e < 10 ms	81	4.1	0.492727	47.0
10 ms ≤ e < 100 ms	30	1.5	0.471031	45.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

direct path read18,337 occurrences · 0.165 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	15,931	86.9	0.088894	53.8
10 µs ≤ e < 100 µs	2,399	13.1	0.031524	19.1
100 µs ≤ e < 1 ms	3	0.0	0.000871	0.5
1 ms ≤ e < 10 ms	2	0.0	0.012198	7.4
10 ms ≤ e < 100 ms	2	0.0	0.031677	19.2
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

enq: RO - fast object reuse1 occurrences · 0.014 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	0	0.0	0.000000	0.0
10 µs ≤ e < 100 µs	0	0.0	0.000000	0.0
100 µs ≤ e < 1 ms	0	0.0	0.000000	0.0
1 ms ≤ e < 10 ms	0	0.0	0.000000	0.0
10 ms ≤ e < 100 ms	1	100.0	0.014392	100.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

local write wait3 occurrences · 0.008 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	0	0.0	0.000000	0.0
10 µs ≤ e < 100 µs	0	0.0	0.000000	0.0
100 µs ≤ e < 1 ms	0	0.0	0.000000	0.0
1 ms ≤ e < 10 ms	3	100.0	0.008094	100.0
10 ms ≤ e < 100 ms	0	0.0	0.000000	0.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

SQL*Net message from client2 occurrences · 0.001 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	0	0.0	0.000000	0.0
10 µs ≤ e < 100 µs	0	0.0	0.000000	0.0
100 µs ≤ e < 1 ms	2	100.0	0.001212	100.0
1 ms ≤ e < 10 ms	0	0.0	0.000000	0.0
10 ms ≤ e < 100 ms	0	0.0	0.000000	0.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

reliable message3 occurrences · 0.001 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	1	33.3	0.000005	0.8
10 µs ≤ e < 100 µs	0	0.0	0.000000	0.0
100 µs ≤ e < 1 ms	2	66.7	0.000611	99.2
1 ms ≤ e < 10 ms	0	0.0	0.000000	0.0
10 ms ≤ e < 100 ms	0	0.0	0.000000	0.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

Disk file operations I/O10 occurrences · 0.001 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	0	0.0	0.000000	0.0
10 µs ≤ e < 100 µs	10	100.0	0.000524	100.0
100 µs ≤ e < 1 ms	0	0.0	0.000000	0.0
1 ms ≤ e < 10 ms	0	0.0	0.000000	0.0
10 ms ≤ e < 100 ms	0	0.0	0.000000	0.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

SQL*Net message to client2 occurrences · 0.000 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	2	100.0	0.000007	100.0
10 µs ≤ e < 100 µs	0	0.0	0.000000	0.0
100 µs ≤ e < 1 ms	0	0.0	0.000000	0.0
1 ms ≤ e < 10 ms	0	0.0	0.000000	0.0
10 ms ≤ e < 100 ms	0	0.0	0.000000	0.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

PARSE (call duration e)180,117 occurrences · 5.156 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	5	0.0	0.000035	0.0
10 µs ≤ e < 100 µs	178,111	98.9	3.000978	58.2
100 µs ≤ e < 1 ms	1,275	0.7	1.125226	21.8
1 ms ≤ e < 10 ms	722	0.4	0.910699	17.7
10 ms ≤ e < 100 ms	4	0.0	0.118877	2.3
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

FETCH (call duration e)178,460 occurrences · 4.726 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	78	0.0	0.000438	0.0
10 µs ≤ e < 100 µs	178,059	99.8	4.514086	95.5
100 µs ≤ e < 1 ms	303	0.2	0.048463	1.0
1 ms ≤ e < 10 ms	14	0.0	0.062255	1.3
10 ms ≤ e < 100 ms	6	0.0	0.100307	2.1
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

EXEC (call duration e)180,269 occurrences · 3.245 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	118,350	65.7	0.977253	30.1
10 µs ≤ e < 100 µs	59,907	33.2	0.785548	24.2
100 µs ≤ e < 1 ms	1,991	1.1	0.262669	8.1
1 ms ≤ e < 10 ms	16	0.0	0.046673	1.4
10 ms ≤ e < 100 ms	4	0.0	0.155844	4.8
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	1	0.0	1.017115	31.3
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

CLOSE (call duration e)180,268 occurrences · 0.250 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 1 µs	0	0.0	0.000000	0.0
1 µs ≤ e < 10 µs	179,926	99.8	0.240244	96.0
10 µs ≤ e < 100 µs	338	0.2	0.008739	3.5
100 µs ≤ e < 1 ms	4	0.0	0.001227	0.5
1 ms ≤ e < 10 ms	0	0.0	0.000000	0.0
10 ms ≤ e < 100 ms	0	0.0	0.000000	0.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < 10 s	0	0.0	0.000000	0.0
10 s ≤ e < 100 s	0	0.0	0.000000	0.0
100 s ≤ e < 1.000 s	0	0.0	0.000000	0.0
1.000 s ≤ e < ∞	0	0.0	0.000000	0.0

Reads

reads (disk buckets)20,299 occurrences · 1.213 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 5 ms	20,208	99.6	0.269748	22.2
5 ms ≤ e < 10 ms	59	0.3	0.440318	36.3
10 ms ≤ e < 15 ms	17	0.1	0.200554	16.5
15 ms ≤ e < 20 ms	10	0.0	0.171484	14.1
20 ms ≤ e < 25 ms	3	0.0	0.067689	5.6
25 ms ≤ e < 50 ms	2	0.0	0.062981	5.2
50 ms ≤ e < 100 ms	0	0.0	0.000000	0.0
100 ms ≤ e < 1 s	0	0.0	0.000000	0.0
1 s ≤ e < ∞	0	0.0	0.000000	0.0

reads (SSD buckets)20,299 occurrences · 1.213 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 15 µs	19,496	96.0	0.126062	10.4
15 µs ≤ e < 25 µs	295	1.5	0.005464	0.5
25 µs ≤ e < 50 µs	209	1.0	0.006839	0.6
50 µs ≤ e < 100 µs	43	0.2	0.002885	0.2
100 µs ≤ e < 500 µs	93	0.5	0.031763	2.6
500 µs ≤ e < 1 ms	48	0.2	0.032128	2.6
1 ms ≤ e < 10 ms	83	0.4	0.504925	41.6
10 ms ≤ e < ∞	32	0.2	0.502708	41.5

First read and reread of the same block

Frequent rereads of the same block point to a small cache or repeated access to the same data.

Event	Distinct blocks	1st read	1st read (s)	Rereads	Rereads (s)
db file sequential read	1,956	1,956	1.048	6	0.000
local write wait	0	0	0.000	3	0.008

Objects with the most wait time

By the obj# of the waits. The name comes from the STAT lines in the trace itself, when present.

obj#	Name	Wait (s)	Occurrences	Top events
188047	IDX_0001	0.931	1,877	db file sequential read · Disk file operations I/O
187750		0.165	18,336	direct path read
1008999	TAB_0005	0.023	17	enq: RO - fast object reuse · local write wait · reliable message
226	IDL_CHAR$	0.017	1	db file sequential read
107	I_DEPENDENCY2	0.016	1	db file sequential read
227	IDL_UB2$	0.016	1	db file sequential read
427	IDX_0012	0.010	1	db file sequential read
228	IDL_SB4$	0.009	1	db file sequential read
31	CDEF$	0.008	2	db file sequential read
19	IND$	0.008	3	db file sequential read
237	I_IDL_CHAR1	0.007	1	db file sequential read
236	I_IDL_UB11	0.007	1	db file sequential read
187694		0.006	49	db file sequential read
40	I_OBJ5	0.005	1	db file sequential read
225	IDL_UB1$	0.004	1	db file sequential read
464	IDX_0008	0.003	1	db file sequential read
384		0.001	4	SQLNet message from client · SQLNet message to client
650598		0.000	2	db file sequential read · Disk file operations I/O
187749	TAB_0002	0.000	2	db file sequential read
239	I_IDL_SB41	0.000	1	db file sequential read
3	I_OBJ#	0.000	1	db file sequential read
54	I_CDEF2	0.000	2	db file sequential read
18	OBJ$	0.000	2	db file sequential read
187751		0.000	2	db file sequential read · direct path read
462	IDX_0007	0.000	1	db file sequential read
188088	IDX_0002	0.000	1	db file sequential read
39	I_OBJ4	0.000	1	db file sequential read
238	I_IDL_UB21	0.000	1	db file sequential read
9	I_FILE#_BLOCK#	0.000	1	db file sequential read
57	I_CCOL1	0.000	1	db file sequential read

Shareable texts

Statements that differ only in literals. With bind variables, a single cursor would serve them all and hard-parse PARSE calls would drop.

Texts	PARSE	PARSE (s)	Total (s)	SQL IDs	Example
49	89,112	1.568	4.941	hidden by the mask	#1 SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL
49	89,112	1.573	4.842	hidden by the mask	#2 SELECT (SELECT COL_0075 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0075 FROM DUAL
1,217	1,217	1.295	1.451	hidden by the mask	#3 INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,:s,NULL,NULL,NULL,NULL…
350	350	0.373	0.417	hidden by the mask	#8 INSERT INTO TAB_0001 (COL_0076,COL_0077, … :s,:s,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL…
251	251	0.256	0.288	hidden by the mask	#9 INSERT INTO TAB_0001 (COL_0076,COL_0077, … NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,…
2	3	0.000	0.000	hidden by the mask	#60 select SYS_CONTEXT(:s,:s) from dual

Unaccounted-for time between calls

unaccounted-for time between calls

Time between the end of one level-0 call and the start of the next with no recorded wait. It is the difference between the total time and the sum of the calls and the waits between them.

Normal when

Small: fractions of a millisecond per call.

A concern when

It adds up a lot: the trace was turned on or off midway, the process was kept off the CPU (saturated server), the application took long without the client wait showing up, or a collection file is missing.

Where to look

Trace period and large time gaps: Summary, Period
In a collection, whether all files arrived: Collection, files and sessions
Calls separated by gaps: Longest depth-0 calls

CPU in PARSE calls

CPU: PARSE dbcalls

The session's CPU time parsing the SQL. High: hard parses from SQL without binds, or repeated parsing of the same cursor (opened and closed on every execution).

Normal when

It is part of the database's normal work.

A concern when

It dominates the total time: start with the statements that use the most CPU and with their logical reads.

Where to look

Hard parses: Call types, PARSE row: Count and Misses
Statements that differ only in literals: Shareable texts
A PARSE for every EXEC: statement detail, Calls: PARSE against EXEC
Statements that used the most CPU in this call: Top statements by component, this call's group

CPU in FETCH calls

CPU: FETCH dbcalls

The session's CPU time fetching rows. High: too many logical reads (LIO), usually a plan that reads far more blocks than the rows returned call for.

Normal when

It is part of the database's normal work.

A concern when

It dominates the total time: start with the statements that use the most CPU and with their logical reads.

Where to look

CPU by call type: Call types
Statements with the most logical reads: SQL statements, LIO and Rows columns
Statements that used the most CPU in this call: Top statements by component, this call's group
Plan operations with a high self LIO: statement detail, Execution plan: highlighted operations

CPU in EXEC calls

CPU: EXEC dbcalls

The session's CPU time executing: DML, cursor opening and the body of PL/SQL blocks. High in PL/SQL: heavy logic or SQL inside a loop.

Normal when

It is part of the database's normal work.

A concern when

It dominates the total time: start with the statements that use the most CPU and with their logical reads.

Where to look

CPU by call type: Call types
Statements with the most logical reads: SQL statements, LIO and Rows columns
Statements that used the most CPU in this call: Top statements by component, this call's group
Child statements of the PL/SQL blocks: statement detail, Recursive SQL

Single-block read

db file sequential read

Reads one block from disk into the buffer cache: index access, table access by ROWID, undo or segment header.

Normal when

Index access to a few blocks, averaging 0.1 to 1 ms on SSD or flash and 5 to 10 ms on disk.

A concern when

Many reads: the plan reads too many blocks (unselective index, NESTED LOOPS with many rows). High average: slow or contended storage.

Where to look

How many reads and how long each one lasts: Profile, this component's row: Occurrences and Avg (s) columns
Slow reads, or many fast reads: Latency distribution, this event's table
Most-read objects: Objects with the most wait time
Rereads of the same blocks: Reads, first read and reread of the same block
Statements that read the most: Top statements by component, this event's group
Plan operations that read too many blocks: statement detail, Execution plan: highlighted operations

CPU in CLOSE calls

CPU: CLOSE dbcalls

The session's CPU time closing the cursor. Almost always small.

Normal when

It is part of the database's normal work.

A concern when

It dominates the total time: start with the statements that use the most CPU and with their logical reads.

Where to look

CPU by call type: Call types
Statements with the most logical reads: SQL statements, LIO and Rows columns
Statements that used the most CPU in this call: Top statements by component, this call's group
Child statements of the PL/SQL blocks: statement detail, Recursive SQL

Direct read into the PGA

direct path read

Reads blocks from disk straight into session memory, bypassing the buffer cache: large serial full scan or parallel query.

Normal when

Full read of a large table in a batch process.

A concern when

It shows up in a user screen or inside a loop: a large full scan repeated, a whole table read to return a few rows.

Where to look

Statements that read the most: Top statements by component, this event's group
TABLE ACCESS FULL operations and how many times they ran: statement detail, Execution plan: Exec column
Most-read objects: Objects with the most wait time

Unaccounted-for time within calls

unaccounted-for time within calls

The part of the call's duration (e=) that is neither CPU (c=) nor a wait recorded inside it.

Normal when

Small. A negative value comes from the granularity of the CPU measurement, not from a problem.

A concern when

It adds up a lot: CPU queueing (more runnable processes than cores), memory paging (swap) or code without wait instrumentation.

Where to look

Calls where time goes missing (duration well above CPU plus waits): Longest depth-0 calls
Statements that carry the most of this time: Top statements by component, this event's group
Server CPU load and free memory over the period, outside the report

Buffer cleanup (TRUNCATE or DROP)

enq: RO - fast object reuse

TRUNCATE or DROP waiting for the database to discard the object's blocks held in the buffer cache.

Normal when

It adds up to little time.

A concern when

TRUNCATE inside a loop, or a buffer cache too large to sweep.

Where to look

How many occurrences: Profile, this component's row: Occurrences column
Statements that waited the most: Top statements by component, this event's group

User I/O (data reads and writes)

User I/O

Data reads and writes done by the session itself.

Normal when

There is always some I/O, with a low average per read.

A concern when

Too many blocks (the plan reads more than it needs) or high average time per read (slow storage).

Where to look

Which I/O events weigh: By wait class, this class's row: Top components column
Slow reads, or many fast reads: Latency distribution
Most-read objects: Objects with the most wait time
Statements that read the most: Top statements by class, this class's group
Plan operations that read too many blocks: statement detail, Execution plan: highlighted operations

Waiting for the application

SQL*Net message from client

The session finished the previous call and is waiting for the application's next request. It is application, network and user time, not database time.

Normal when

It shows up between every call. Long, isolated waits are the user thinking or the application busy with something else.

A concern when

It dominates the total time with many short waits: the application talks to the database too much (one row per call, SQL inside a loop). With a few long waits, the delay is in the application, and SQL tuning will not fix it.

Where to look

How many round trips there were and how long each one lasts: Profile, this component's row: Occurrences and Avg (s) columns
Many short waits or a few long ones: Latency distribution, this event's table
FETCH calls that bring few rows each: Call types, FETCH row: Count and Rows
Statements that waited the most for the application: Top statements by component, this event's group

Inter-process message

reliable message

The session sent a message to background processes or to other instances and waits for the acknowledgement.

Normal when

It adds up to little time.

A concern when

It adds up a lot: TRUNCATE, result cache or a parameter change in RAC.

Where to look

Statements that waited the most: Top statements by component, this event's group

Opening or closing files

Disk file operations I/O

File operations (open, close, size lookup), not data reads.

Normal when

It adds up to little time.

A concern when

It adds up a lot: many files opened and closed, or a slow file system.

Where to look

How many occurrences and how long each one lasts: Profile, this component's row: Occurrences and Avg (s) columns

Sending the response

SQL*Net message to client

Time to hand a response packet to the operating system. It does not measure the network to the client, only the handoff to the OS.

Normal when

Microseconds per occurrence, one per call.

A concern when

The average rises to milliseconds: the server's network buffer is full or the network is saturated.

Where to look

Average and maximum per wait: Profile, this component's row: Avg (s) and Max (s) columns

Unaccounted-for

Time the trace does not explain by CPU or wait: within calls and between them.

Normal when

Small.

A concern when

CPU queue, paging, gaps in the trace or a file missing from the collection.

Where to look

The two unaccounted-for time components and the card of each one: Response time profile

CPU

CPU time of the database calls (the c= of PARSE, EXEC and FETCH).

Normal when

This is the database's work.

A concern when

It adds up a lot: too many logical reads (plan), too much parsing or heavy PL/SQL.

Where to look

CPU by call type: Call types
Statements with the most logical reads: SQL statements, LIO and Rows columns
Statements that used the most CPU: Top statements by class, this class's group

Application

Waits caused by how the application uses the database: rows and tables locked by another session, application locks, returned errors.

Normal when

It adds up to little time.

A concern when

Session stalled waiting for another: long transactions, same row updated by several sessions, unindexed foreign key.

Where to look

Which events weigh: By wait class, this class's row: Top components column
Contended objects: Objects with the most wait time
Statements that were blocked: Top statements by class, this class's group
Who holds the lock: v$session.blocking_session, in the database

Idle

The session is waiting for work. In a session trace it is almost always SQL*Net message from client: application, network and user time.

Normal when

It shows up between calls.

A concern when

Dominates the total time and the user complains about slowness: the delay is outside the database (application, network, too many round trips).

Where to look

How many round trips there were: Summary, Database calls and Waits
FETCH calls that bring few rows each: Call types, FETCH row: Count and Rows
Statements that waited the most for the application: Top statements by class, this class's group

Other

Internal events with no more specific class.

Normal when

It adds up to little time.

A concern when

It adds up a lot: the event itself points to the cause.

Where to look

Which event weighs: By wait class, this class's row: Top components column

Network

Sending and receiving data over SQL*Net, with the application or with another database over dblink.

Normal when

It adds up to little time.

A concern when

Large results, low arraysize or slow dblink.

Where to look

Which events of the class weigh (more data, dblink): By wait class, this class's row: Top components column
Rows per FETCH: Call types, FETCH row: Count and Rows
Statements that used the network the most: Top statements by class, this class's group

Recursive SQL (child statements)

Time of the calls this statement triggered: SQL inside PL/SQL functions and procedures, triggers and dictionary queries.

Normal when

PL/SQL statement that runs other SQL.

A concern when

It adds up a lot in a plain SELECT or DML: a PL/SQL function called per row, or a heavy trigger.

Where to look

Which child statements and what each one costs: statement detail, Recursive SQL

Calls	Inclusive (s)	Literals
7,276	0.144	*, *
7,272	0.120	*, *
7,276	0.110	*, *
7,272	0.107	*, *
7,276	0.107	*, *

Component	Duration (s)	%	Occurrences
cpu	2.239668	45.3	89,112
cpu	1.558749	31.5	89,112
cpu	0.903868	18.3	89,112
cpu	0.123982	2.5	89,112
unaccounted-for	0.114630	2.3	356,448

Call	Count	CPU (s)	Duration (s)	Consistent (CR)	Rows	Misses
PARSE	89,112	1.558749	1.567573	0	0	49
EXEC	89,112	0.903868	0.922604	0	0	0
FETCH	89,112	2.239668	2.327062	445,560	89,112	0
CLOSE	89,112	0.123982	0.123658	0	0	0

Id	Operation	Rows	Estimated	Self time (s)	% time	Self LIO	% LIO	Time (s)	CR	Cost	obj
1		1		0.000004	10.8	0	0.0	0.000036	5
2	1	1	1	0.000032	86.5	5	100.0	0.000032	5	3	1008999
3	FAST DUAL	1	1	0.000001	2.7	0	0.0	0.000001	0	2

Calls	Inclusive (s)	Literals
7,272	0.109	*, *
7,276	0.106	*, *
7,276	0.103	*, *
7,272	0.103	*, *
7,276	0.102	*, *

Component	Duration (s)	%	Occurrences
cpu	2.287639	47.2	89,112
cpu	1.626753	33.6	89,112
cpu	0.864872	17.9	89,112
cpu	0.130972	2.7	89,112
unaccounted-for	-0.067789	-1.4	356,448

Call	Count	CPU (s)	Duration (s)	Consistent (CR)	Rows	Misses
PARSE	89,112	1.626753	1.573453	0	0	49
EXEC	89,112	0.864872	0.878362	0	0	0
FETCH	89,112	2.287639	2.267754	445,560	89,112	0
CLOSE	89,112	0.130972	0.122878	0	0	0

Id	Operation	Rows	Estimated	Self time (s)	% time	Self LIO	% LIO	Time (s)	CR	Cost	obj
1		1		0.000003	5.8	0	0.0	0.000050	5
2	1	1	1	0.000047	90.4	5	100.0	0.000047	5	3	1008999
3	FAST DUAL	1	1	0.000002	3.8	0	0.0	0.000002	0	2

Calls	Inclusive (s)	Literals
3	0.006	'*', '', '', '', '', '', '', '', '', '', '', '', '**',…
3	0.006	'*', '', '', '', '', '', '', '', '', '', '', '', '**',…
3	0.005	'*', '', '', '', '', '', '', '', '', '', '', '', '**',…
3	0.004	'*', '', '', '', '', '', '', '', '', '', '', '', '**',…
3	0.004	'*', '', '', '', '', '', '', '', '', '', '', '', '**',…

Component	Duration (s)	%	Occurrences
cpu	1.314810	90.6	1,217
cpu	0.152976	10.5	1,217
wait	0.002378	0.2	32
cpu	0.000000	0.0	1,217
unaccounted-for	-0.018753	-1.3	3,651

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Current (CU)	Rows	Misses
PARSE	1,217	1.314810	1.295202	0	0	0	0	1,217
EXEC	1,217	0.152976	0.154230	32	1,249	7,512	1,217	0
CLOSE	1,217	0.000000	0.001979	0	0	0	0	0

WaitScope 1.7.0 · analyzed on the server · report exported on 2026-10-29 10:19:57

Component	Duration (s)	%	Occurrences
wait	0.066395	48.6	5,333
recursive	0.063234	46.3
cpu	0.004999	3.7	1
unaccounted-for	0.001996	1.5	1

#	Duration (s)	Text
12	0.025	select /+ index(idl_char$ i_idl_char1) +/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 …
15	0.016	select /+ index(idl_ub2$ i_idl_ub21) +/ piece#,length,piece from idl_ub2$ where obj#=:1 and part=:2 and version=:3 ord…
18	0.012	select /+ index(idl_ub1$ i_idl_ub11) +/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 ord…
19	0.010	select /+ index(idl_sb4$ i_idl_sb41) +/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 ord…

Component	Duration (s)	%	Occurrences
unaccounted-for	0.037654	93.8	3
cpu	0.002000	5.0	1
wait	0.000489	1.2	1
wait	0.000003	0.0	1
cpu	0.000000	0.0	1
cpu	0.000000	0.0	1

Component	Duration (s)	%	Occurrences
unaccounted-for	0.024934	93.5	2
cpu	0.001000	3.8	1
wait	0.000723	2.7	1
wait	0.000004	0.0	1
cpu	0.000000	0.0	1

Component	Duration (s)	%	Occurrences
wait	0.930878	91.0	1,870
cpu	0.130980	12.8	2
wait	0.000354	0.0	7
cpu	0.000000	0.0	2
cpu	0.000000	0.0	2
unaccounted-for	-0.039494	-3.9	6

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)
PARSE	2	0.000000	0.000138	0	0
EXEC	2	0.130980	1.022574	1,870	3,740
CLOSE	2	0.000000	0.000006	0	0

Id	Operation	Exec.	Rows	Rows/exec	Estimated	Self time (s)	% time	Self LIO	% LIO	PR	PW	Time (s)	CR	Cost	obj
1			0			0.000050	0.9	0	0.0	0	0	0.005432	1,870
2	1		0		1	0.005382	99.1	1,870	100.0	0	0	0.005382	1,870	2	188047

Calls	Inclusive (s)	Literals
3	0.024	'*', '', '', '', '', '', '', '', '', '', '', '', '', '', **,…
3	0.002	'*', '', '', '', '', '', '', '', '', '', '', '', '', '', **, …
3	0.002	'*', '', '', '', '', '', '', '', '', '', '', '', '', '', **,…
3	0.002	'*', '', '', '', '', '', '', '', '', '', '', '', '', '', **, …
3	0.002	'*', '', '', '', '', '', '', '', '', '', '', '', '', '', **,…

Component	Duration (s)	%	Occurrences
cpu	0.352953	84.7	350
cpu	0.040994	9.8	350
recursive	0.018535	4.4
wait	0.002529	0.6	12
cpu	0.001000	0.2	350
unaccounted-for	0.000606	0.1	1,050

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Current (CU)	Rows	Misses
PARSE	350	0.355953	0.372854	6	78	0	0	350
EXEC	350	0.040994	0.043200	12	358	2,154	350	0
CLOSE	350	0.001000	0.000563	0	0	0	0	0

Component	Duration (s)	%	Occurrences
cpu	0.253971	88.3	251
cpu	0.034992	12.2	251
wait	0.000954	0.3	5
cpu	0.000000	0.0	251
unaccounted-for	-0.002291	-0.8	753

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Current (CU)	Rows	Misses
PARSE	251	0.253971	0.256408	0	0	0	0	251
EXEC	251	0.034992	0.030809	5	256	1,544	251	0
CLOSE	251	0.000000	0.000409	0	0	0	0	0

Component	Duration (s)	%	Occurrences
recursive	0.040612	49.5
wait	0.014392	17.6	1
cpu	0.008999	11.0	1
cpu	0.008998	11.0	1
wait	0.008094	9.9	3
wait	0.000616	0.8	3
wait	0.000162	0.2	7
wait	0.000082	0.1	1
unaccounted-for	0.000023	0.0	3
cpu	0.000000	0.0	1

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Current (CU)	Misses
PARSE	1	0.013998	0.013202	3	18	1	1
EXEC	1	0.024996	0.068773	14	44	47	0
CLOSE	1	0.000000	0.000003	0	0	0	0

Component	Duration (s)	%	Occurrences
wait	0.015414	50.8	4
cpu	0.010998	36.2	50
cpu	0.009998	32.9	50
cpu	0.000000	0.0	50
cpu	0.000000	0.0	1
unaccounted-for	-0.006045	-19.9	151

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Rows
PARSE	1	0.000000	0.000019	0	0	0
EXEC	50	0.010998	0.007154	0	0	0
FETCH	50	0.009998	0.023110	4	1,000	50
CLOSE	50	0.000000	0.000082	0	0	0

Component	Duration (s)	%	Occurrences
wait	0.023874	97.1	2
cpu	0.001000	4.1	2
cpu	0.000999	4.1	1
cpu	0.000000	0.0	1
cpu	0.000000	0.0	1
unaccounted-for	-0.001279	-5.2	5

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Rows
PARSE	1	0.000000	0.000061	0	0	0
EXEC	1	0.000999	0.000318	0	0	0
FETCH	2	0.001000	0.024202	2	4	1
CLOSE	1	0.000000	0.000013	0	0	0

Id	Operation	Exec.	Rows	Rows/exec	Estimated	Self time (s)	% time	Self LIO	% LIO	PR	PW	Time (s)	CR	Cost	obj
1	1		1		1	0.017191	71.1	1	33.3	2	0	0.024172	3	3	226
2	2		1		1	0.006981	28.9	2	66.7	1	0	0.006981	2	2	237

Component	Duration (s)	%	Occurrences
wait	0.015645	87.9	7
cpu	0.002000	11.2	3
cpu	0.001000	5.6	2
cpu	0.000000	0.0	2
cpu	0.000000	0.0	2
unaccounted-for	-0.000843	-4.7	9

caso-1.trc

Diagnosis

Response time profile

By wait class

Top statements by component and by class

By profile component

By wait class

SQL statements by contribution

Call types

Longest depth-0 calls

Latency distribution

Reads

First read and reread of the same block

Objects with the most wait time

Shareable texts

Unaccounted-for time between calls

CPU in PARSE calls

CPU in FETCH calls

CPU in EXEC calls

Single-block read

CPU in CLOSE calls

Direct read into the PGA

Unaccounted-for time within calls

Buffer cleanup (TRUNCATE or DROP)

User I/O (data reads and writes)

Waiting for the application

Inter-process message

Opening or closing files

Sending the response

Unaccounted-for

CPU

Application

Idle

Other

Network

Recursive SQL (child statements)

#1 · SELECT

Text

Variants that cost the most

Statement profile

Calls

Execution plan 3212480556

Stop after N rows

Full table scan

#2 · SELECT

Text

Variants that cost the most

Statement profile

Calls

Execution plan 3212480556

Stop after N rows

Full table scan

#3 · INSERT

Text

Variants that cost the most

Statement profile

Calls

Execution plan 3212480556

Conventional insert

#4 · PL/SQL

Text

Statement profile

Calls

Recursive SQL executed by this statement

#5 · ALTER SESSION

Text

Statement profile

Calls

#6 · ?

Text

Statement profile

Calls

#7 · DELETE

Text

Statement profile

Calls

Execution plan 2124198792

Delete

Index full scan, in order

#8 · INSERT

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Rows
PARSE	2	0.000000	0.000122	0	0	0
EXEC	2	0.001000	0.000487	0	0	0
FETCH	3	0.002000	0.017187	7	12	1
CLOSE	2	0.000000	0.000006	0	0	0

Id	Operation	Rows	Estimated	Self time (s)	% time	Self LIO	% LIO	PR	Time (s)	CR	Cost	obj
1		1	2	0.000033	0.2	0	0.0	5	0.016567	9	7
2		1	2	0.000571	3.4	0	0.0	5	0.016534	9	6
3		1	2	0.000007	0.0	0	0.0	2	0.007862	5	2
4	2	1	2	0.007832	47.3	2	22.2	2	0.007846	4	2	19
5	3	1	1	0.000014	0.1	2	22.2	0	0.000014	2	1	3
6		0	1	0.000002	0.0	0	0.0	0	0.000009	1	0	432
7		0	1	0.000007	0.0	1	11.1	0	0.000007	1	0	433
8		1	1	0.000004	0.0	0	0.0	3	0.008101	4	3
9		1	1	0.000044	0.3	0	0.0	3	0.008097	4	3
10	1	1	1	0.008001	48.3	2	22.2	3	0.008053	4	2	31
11		5	4	0.000052	0.3	2	22.2	1	0.000052	2	1	54

Component	Duration (s)	%	Occurrences
wait	0.016134	96.4	1
unaccounted-for	0.000609	3.6	8
cpu	0.000000	0.0	2
cpu	0.000000	0.0	2
cpu	0.000000	0.0	2
cpu	0.000000	0.0	2

Call	Count	Duration (s)	Disk (PIO)	Consistent (CR)
PARSE	2	0.000054	0	0
EXEC	2	0.000403	0	0
FETCH	2	0.016270	1	6
CLOSE	2	0.000016	0	0

Id	Operation	Estimated	Self time (s)	% time	Self LIO	% LIO	PR	Time (s)	CR	Cost	obj
1		2	0.000017	0.1	0	0.0	1	0.016258	3	17
2			0.000009	0.1	0	0.0	1	0.016241	3
3			0.000006	0.0	0	0.0	1	0.016230	3
4			0.000002	0.0	0	0.0	1	0.016224	3
5		1	0.000002	0.0	0	0.0	1	0.016222	3	8
6		1	0.000003	0.0	0	0.0	1	0.016220	3	6	104
7	1	5	0.016217	99.7	3	100.0	1	0.016217	3	3	107
8		1	0.000000	0.0	0	0.0	0	0.000000	0	1	36
9		1	0.000000	0.0	0	0.0	0	0.000000	0	2	18
10			0.000002	0.0	0	0.0	0	0.000002	0
11			0.000000	0.0	0	0.0	0	0.000000	0
12		1	0.000000	0.0	0	0.0	0	0.000000	0	8
13		1	0.000000	0.0	0	0.0	0	0.000000	0	6	104
14		5	0.000000	0.0	0	0.0	0	0.000000	0	3	107
15		1	0.000000	0.0	0	0.0	0	0.000000	0	1	36
16		1	0.000000	0.0	0	0.0	0	0.000000	0	2	18

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Rows
PARSE	1	0.000000	0.000069	0	0	0
EXEC	1	0.000000	0.000313	0	0	0
FETCH	2	0.001000	0.015992	2	7	2
CLOSE	1	0.000000	0.000102	0	0	0

Id	Operation	Exec.	Rows	Rows/exec	Estimated	Self time (s)	% time	Self LIO	% LIO	PR	PW	Time (s)	CR	Cost	obj
1	1		2		1	0.015835	99.3	2	40.0	2	0	0.015948	5	3	227
2	2		2		1	0.000113	0.7	3	60.0	1	0	0.000113	3	2	238

Component	Duration (s)	%	Occurrences
cpu	0.007998	54.9	50
unaccounted-for	0.006013	41.2	101
recursive	0.000547	3.8
wait	0.000019	0.1	2
cpu	0.000000	0.0	50
cpu	0.000000	0.0	1

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Current (CU)	Rows	Misses
PARSE	1	0.000000	0.000236	0	0	0	0	1
EXEC	50	0.008998	0.014271	2	13	82	50	1
CLOSE	50	0.000000	0.000070	0	0	0	0	0

#	Duration (s)	Text
48	0.000	select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2…
37	0.000	select decode(u.type#, ***, u.ext_username, u.name), o.name, t.update$, t.insert$, t.delete$, t.enabled, decode(bitand(t.p…