teste-sintetico.trc

Analyzed on 2026-10-26 18:51:43 · 1.8 KiB · 36 lines · up to 10 statements per list

Total time

0.007 s

7.0 ms

Period

2024-01-02 09:59:59

to 10:00:00

Database calls

4 at depth 0

Waits

0.005 s between calls

Distinct statements

1 commits · 0 rollbacks

Session and environment

Database: Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production · 19.3.0.0.0
Instance: teste1
Server: teste-node
Session: 10.20 · pid 4242
Module: modulo (x)
Time unit: microseconds
File on server: /tmp/teste_ora_1.trc

Diagnosis

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

medium The session spent most of its time waiting for the application 71.3% of total time

The database sat idle waiting for the client's next request. SQL tuning does not reduce this time: look at the application, the network and the number of round trips (calls per unit of work). View in profile

medium Statement #1: plan operation 1 accounts for 98.0% of the time 24.6% of total time

Operation TABLE ACCESS BY INDEX ROWID T. Visits the table row by row from the index: unselective index or missing the columns the filter uses. Also significant: operation 2, INDEX UNIQUE SCAN T_PK (20.0% of logical reads). The operations are highlighted in the plan, in the statement detail. View in the plan of statement #1

Response time profile

Each row is a part of the total time; together they add up to 100%. Click a component or class name to see what it measures and when it is a concern. Unaccounted-for time within calls usually points to CPU queuing or uninstrumented code; a negative value comes from the granularity of CPU measurement.

Component	Duration (s)	% of total	Occurrences	Avg (s)	Min (s)	Max (s)
Idle	0.005000	71.3	1	0.005000	0.005000	0.005000
User I/O	0.001300	18.5	2	0.000650	0.000300	0.001000
unaccounted-for	0.000286	4.1
cpu	0.000195	2.8	2	0.000097	0.000040	0.000155
unaccounted-for	0.000161	2.3	6	0.000027
cpu	0.000050	0.7	1	0.000050	0.000050	0.000050
cpu	0.000015	0.2	2	0.000008	0.000005	0.000010
Network	0.000002	0.0	1	0.000002	0.000002	0.000002
cpu	0.000001	0.0	1	0.000001	0.000001	0.000001
Total	0.007010	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
0.005000	71.3	1	SQL*Net message from client
0.001300	18.5	2	db file sequential read
0.000447	6.4		unaccounted-for time between calls · unaccounted-for time within calls
0.000261	3.7	6	CPU: FETCH dbcalls · CPU: PARSE dbcalls · CPU: EXEC dbcalls · CPU: CLOSE dbcalls
0.000002	0.0	1	SQL*Net message to client

Waiting for the application

SQL*Net message from client

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

Normal when: Always present between calls. Long, isolated waits are the user thinking or the application doing something else.
A concern when: Dominates the total time with many short waits: the application talks to the database too much (one row per call, SQL in a loop). With few long waits, the delay is in the application.
Where to look: Number of waits (round trips), average per wait, FETCH calls with few rows each.

Single-block read

db file sequential read

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

Normal when: Index access to a few blocks. Average of 0.1 to 1 ms on SSD/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: Reads per object, read histogram and the highlighted plan operations.

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: High: the trace was turned on or off midway, the process was off CPU (saturated server), the application took time without the client wait showing up, or a collection file is missing.
Where to look: Large time gaps, trace period and, for a collection, whether all files arrived.

CPU in FETCH calls

CPU: FETCH dbcalls

CPU time spent by the session fetching rows. High: too many logical reads (LIO), usually a plan that reads far more blocks than the returned rows require.

Normal when: Part of the database's work.
A concern when: Dominates the total time: check the calls and statements that use the most CPU.
Where to look: Calls by type and LIO per execution.

Unaccounted-for time within calls

unaccounted-for time within calls

Part of the call duration (e) that is neither CPU (c) nor a wait recorded inside it.

Normal when: Small. A negative value comes from CPU measurement granularity.
A concern when: High: CPU queue (more ready processes than cores), memory paging (swap) or uninstrumented code.
Where to look: Server CPU load at the time and free memory.

CPU in PARSE calls

CPU: PARSE dbcalls

CPU time spent by the session parsing SQL. High: hard parse due to SQL without binds, or repeated parse of the same cursor (opened and closed on every execution).

Normal when: Part of the database's work.
A concern when: Dominates the total time: check the calls and statements that use the most CPU.
Where to look: Calls by type and LIO per execution.

CPU in EXEC calls

CPU: EXEC dbcalls

CPU time spent by the session in execution: DML, cursor open and the body of PL/SQL blocks. High in PL/SQL: heavy logic or SQL inside a loop.

Normal when: Part of the database's work.
A concern when: Dominates the total time: check the calls and statements that use the most CPU.
Where to look: Calls by type and LIO per execution.

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: Almost always microseconds, once per call.
A concern when: High average: server network buffer full or saturated network.
Where to look: Average per wait.

CPU in CLOSE calls

CPU: CLOSE dbcalls

CPU time spent by the session closing the cursor. Almost always small.

Normal when: Part of the database's work.
A concern when: Dominates the total time: check the calls and statements that use the most CPU.
Where to look: Calls by type and LIO per execution.

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: 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: Number of calls and average per wait.

User I/O (data reads and writes)

User I/O

Data reads and writes done by the session itself.

Normal when: Some I/O is always present.
A concern when: Too many blocks (the plan reads more than it needs) or high average time per read (slow storage).
Where to look: Reads per object, read histogram, plan of the statements that read the most.

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.

CPU

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

Normal when: This is the database's work.
A concern when: High: too many logical reads (plan), excessive parsing or heavy PL/SQL.
Where to look: LIO per execution and the calls that use the most CPU.

Network

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

Normal when: Small.
A concern when: Large results, low arraysize or slow dblink.
Where to look: SQL*Net more data events and the dblink ones.

Recursive SQL (child statements)

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

Normal when: PL/SQL statement that runs other SQL.
A concern when: High in a simple SELECT or DML: PL/SQL function called per row, heavy trigger.
Where to look: The statement's recursive SQL list.

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

SQL*Net message from client wait0.005 s · 71.3% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
1	0.005000	100.0		aaaaaaaaaaaaa	select * from t where id=1

db file sequential read wait0.001 s · 18.5% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
1	0.001000	76.9		aaaaaaaaaaaaa	select * from t where id=1
2	0.000300	23.1		bbbbbbbbbbbbb	select obj# from obj$ where x=1

CPU: FETCH dbcalls cpu0.000 s · 2.8% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000155	79.5		aaaaaaaaaaaaa	select * from t where id=1
2	0.000040	20.5		bbbbbbbbbbbbb	select obj# from obj$ where x=1

unaccounted-for time within calls unaccounted-for0.000 s · 2.3% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000116	72.0		aaaaaaaaaaaaa	select * from t where id=1
2	0.000045	28.0		bbbbbbbbbbbbb	select obj# from obj$ where x=1

CPU: PARSE dbcalls cpu0.000 s · 0.7% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000050	100.0		aaaaaaaaaaaaa	select * from t where id=1

CPU: EXEC dbcalls cpu0.000 s · 0.2% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000010	66.7		aaaaaaaaaaaaa	select * from t where id=1
2	0.000005	33.3		bbbbbbbbbbbbb	select obj# from obj$ where x=1

SQL*Net message to client wait0.000 s · 0.0% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000002	100.0		aaaaaaaaaaaaa	select * from t where id=1

CPU: CLOSE dbcalls cpu0.000 s · 0.0% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000001	100.0		aaaaaaaaaaaaa	select * from t where id=1

By wait class

Idle0.005 s · 71.3% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
1	0.005000	100.0		aaaaaaaaaaaaa	select * from t where id=1

User I/O0.001 s · 18.5% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
1	0.001000	76.9		aaaaaaaaaaaaa	select * from t where id=1
2	0.000300	23.1		bbbbbbbbbbbbb	select obj# from obj$ where x=1

Unaccounted-for0.000 s · 6.4% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000116	26.0		aaaaaaaaaaaaa	select * from t where id=1
2	0.000045	10.1		bbbbbbbbbbbbb	select obj# from obj$ where x=1

CPU0.000 s · 3.7% of total time · 2 statements

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000216	82.8		aaaaaaaaaaaaa	select * from t where id=1
2	0.000045	17.2		bbbbbbbbbbbbb	select obj# from obj$ where x=1

Network0.000 s · 0.0% of total time · 1 statement

#	Time (s)	% of total	chart	SQL ID	Text
1	0.000002	100.0		aaaaaaaaaaaaa	select * from t where id=1

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	0.007	95.9	0.002	SELECT	0	1	1	1	10	1	aaaaaaaaaaaaa	select * from t where id=1
2	0.000	0.0	0.000	SELECT	1	1	1	1	3	1	bbbbbbbbbbbbb	select obj# from obj$ where x=1

Time not attributed to any statement: 0.000 s.

Call types

Call	Count	Duration (s)	Disk (PIO)	Consistent (CR)	Rows	Misses
FETCH	2	0.002	2	13	2	0
PARSE	1	0.000	0	0	0	1
EXEC	2	0.000	0	0	0	0
CLOSE	1	0.000	0	0	0	0

Longest depth-0 calls

Call	Duration (s)	CPU (s)	Start (+s)	Line	LIO	PIO	Rows	Statement
FETCH	0.001600	0.000200	0.000	31	10	1	1	#1 select * from t where id=1
PARSE	0.000100	0.000050	0.000	17	0	0	0	#1 select * from t where id=1
EXEC	0.000020	0.000010	0.000	18	0	0	0	#1 select * from t where id=1
CLOSE	0.000002	0.000001	0.007	35	0	0	0	#1 select * from t where id=1

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.

SQL*Net message from client1 occurrences · 0.005 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	1	100.0	0.005000	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

db file sequential read2 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	1	50.0	0.000300	23.1
1 ms ≤ e < 10 ms	1	50.0	0.001000	76.9
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 client1 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	1	100.0	0.000002	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

FETCH (call duration e)2 occurrences · 0.002 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	1	50.0	0.000380	19.2
1 ms ≤ e < 10 ms	1	50.0	0.001600	80.8
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)1 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	0	0.0	0.000000	0.0
10 µs ≤ e < 100 µs	0	0.0	0.000000	0.0
100 µs ≤ e < 1 ms	1	100.0	0.000100	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

EXEC (call duration e)2 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	0	0.0	0.000000	0.0
10 µs ≤ e < 100 µs	2	100.0	0.000030	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

CLOSE (call duration e)1 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	1	100.0	0.000002	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

Reads

reads (disk buckets)2 occurrences · 0.001 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 5 ms	2	100.0	0.001300	100.0
5 ms ≤ e < 10 ms	0	0.0	0.000000	0.0
10 ms ≤ e < 15 ms	0	0.0	0.000000	0.0
15 ms ≤ e < 20 ms	0	0.0	0.000000	0.0
20 ms ≤ e < 25 ms	0	0.0	0.000000	0.0
25 ms ≤ e < 50 ms	0	0.0	0.000000	0.0
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)2 occurrences · 0.001 s

Duration bucket	Occurrences	% occ.	Duration (s)	% duration
0 ≤ e < 15 µs	0	0.0	0.000000	0.0
15 µs ≤ e < 25 µs	0	0.0	0.000000	0.0
25 µs ≤ e < 50 µs	0	0.0	0.000000	0.0
50 µs ≤ e < 100 µs	0	0.0	0.000000	0.0
100 µs ≤ e < 500 µs	1	50.0	0.000300	23.1
500 µs ≤ e < 1 ms	0	0.0	0.000000	0.0
1 ms ≤ e < 10 ms	1	50.0	0.001000	76.9
10 ms ≤ e < ∞	0	0.0	0.000000	0.0

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	1	0.000	1	0.001

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
50	T	0.001	2	db file sequential read

Statement details

#1 · SELECT

sql_id aaaaaaaaaaaaahv 111

Share of total time

0.007 s

95.9% of total time

Inclusive

0.002 s

all of the statement's calls

Depth

called by the application

Text

select * from t12 where id=1

1 T: plan operation 1
2 T, table of index T_PK: plan operation 2

Statement profile

Component	Duration (s)	%	Occurrences
wait	0.005000	74.4	1
wait	0.001000	14.9	1
recursive	0.000390	5.8
cpu	0.000155	2.3	1
unaccounted-for	0.000116	1.7	4
cpu	0.000050	0.7	1
cpu	0.000010	0.1	1
wait	0.000002	0.0	1
cpu	0.000001	0.0	1

Calls

Call	Count	CPU (s)	Duration (s)	Disk (PIO)	Consistent (CR)	Rows	Misses
PARSE	1	0.000050	0.000100	0	0	0	1
EXEC	1	0.000010	0.000020	0	0	0	0
FETCH	1	0.000200	0.001600	1	10	1	0
CLOSE	1	0.000001	0.000002	0	0	0	0

Execution plan 10

From the STAT lines in the trace.

Where the plan spends time by each operation's own value, without that of the operations below it

1 Id 1 · TABLE ACCESS BY INDEX ROWID T 98.0% of time · 80.0% of logical reads
Visits the table row by row from the index: unselective index or missing the columns the filter uses.
2 Id 2 · INDEX UNIQUE SCAN T_PK 2.0% of time · 20.0% of logical reads

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.001470	98.0	8	80.0	1	0	0.001500	10	2	50
2	2		1		1	0.000030	2.0	2	20.0	0	0	0.000030	2	1	51

Table access by index ROWID

TABLE ACCESS BY INDEX ROWID

Accesses the table one row at a time by the ROWIDs returned by the index scan right below.

Good when: Few rows, or rows stored close together in the table (low clustering factor).
Bad when: Many scattered rows (high clustering factor): almost one block read per row. Or a filter predicate applied only here that discards most of what the index returned: the index is missing that predicate's column.
In the plan, check: Compare the rows of the index scan right below with this operation's: if far fewer remain here, the predicate is on the table, not in the index.

Unique key lookup

INDEX UNIQUE SCAN

Looks up a single key in a unique index (PK or UNIQUE): goes down from the root block through the branch blocks to the key's leaf block.

Good when: Almost always: it reads only the index height (BLEVEL + 1 blocks).
Bad when: As the inner of a NESTED LOOPS with millions of outer rows: cheap per execution, expensive in total.
In the plan, check: Exec and total self LIO.

Tap an operation to see what it does and when it is good or bad. Time (s) and CR are cumulative: they include the operations below each one (its input row sources); the self values subtract those operations. Oracle measures time per operation by sampling, so it may not add up between an operation and the ones below it; logical reads are always counted. Rows/exec and Estimated in red: the optimizer got the cardinality wrong by 10 times or more.

Recursive SQL executed by this statement

#	Duration (s)	Text
2	0.000	select obj# from obj$ where x=1

#2 · SELECT

sql_id bbbbbbbbbbbbbhv 222

Share of total time

0.000 s

0.0% of total time