Skip to Main Content

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, ludovic.

Asked: September 06, 2016 - 12:01 pm UTC

Last updated: April 02, 2019 - 6:41 am UTC

Version: 11.2

Viewed 1000+ times

You Asked

Hello,

I need to analyze my database. I used trace + tkprof and I see this result :

SQL ID: 4yvsj6a508pgf Plan Hash: 2709293936

SELECT NAME
FROM
SYS.USER$ WHERE USER# = :B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 11445 0.17 0.55 0 0 0 0
Execute 34174 2.09 2.26 0 0 0 0
Fetch 34174 0.57 0.76 0 68348 0 34174
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 79793 2.84 3.59 0 68348 0 34174

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: SYS (recursive depth: 2)
Number of plan statistics captured: 11451

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS CLUSTER USER$ (cr=2 pr=0 pw=0 time=21 us cost=1 size=18 card=1)
1 1 1 INDEX UNIQUE SCAN I_USER# (cr=1 pr=0 pw=0 time=8 us cost=0 size=0 card=1)(object id 11)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
latch: shared pool 33 0.00 0.01
library cache: mutex X 8 0.01 0.02
********************************************************************************


SQL ID: b8rntuss3bj8y Plan Hash: 3360735762

SELECT .... WHERE ROWID = :B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3344 0.07 1.01 0 0 0 0
Execute 3344 0.31 0.25 0 18 0 0
Fetch 3344 0.20 0.12 0 3290 0 3344
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10032 0.59 1.40 0 3308 0 3344

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 85 (recursive depth: 2)
Number of plan statistics captured: 3344

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY USER ROWID T1 (cr=1 pr=0 pw=0 time=25 us cost=1 size=2551 card=1)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
library cache: mutex X 3 0.00 0.00
cursor: pin S wait on X 8 0.12 0.94
latch: cache buffers chains 8 0.00 0.00
buffer busy waits 11 0.00 0.00
latch: In memory undo latch 7 0.00 0.00
latch: row cache objects 3 0.00 0.00
********************************************************************************


I don't understand what means "Number of plan statistics captured" ? There is a link with the event "library cache: mutex X" ?

and Chris said...

"Number of plan statistics captured" tells you how many executions Oracle recorded information about the plan.

It uses these to populate the "Rows (1st) Rows (avg) Rows (max)" columns in the row source operation. So 

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY USER ROWID T1 (cr=1 pr=0 pw=0 time=25 us cost=1 size=2551 card=1)


Tells you that of the 3,344 plans captured:

The first processed 1 row
The mean of these processed 1 row
The most any of these executions ever processed was 1 row.

In short, this plan always processed 1 row ;)

"library cache: mutex X" is unrelated to this. This is a wait event. 

library cache: mutex X 3 0.00 0.00


Tell you that you waited 3 times for this. For a total of zero seconds ;)

So nothing to worry about in this case. You can find more about wait events by reading:

http://docs.oracle.com/database/121/TGDBA/pfgrf_instance_tune.htm#TGDBA95374

Rating

  (2 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Question about "Rows (1st) Rows (avg) Rows (max)"

Matthew, April 01, 2019 - 5:37 pm UTC

Oracle 12.1.0.2
TEMP_IID is a global temp table

SQL ID: 27jgupzwq3yp0 Plan Hash: 18995321

DELETE FROM TEMP_IID


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 111347 1.85 2.14 0 115 0 0
Execute 111347 3674.40 3749.80 4 1117987967 2284505 2212824
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 222694 3676.25 3751.94 4 1117988082 2284505 2212824

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 70
Number of plan statistics captured: 3

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 DELETE TEMP_IID (cr=9438 pr=0 pw=0 time=34212 us)
5 3 5 TABLE ACCESS FULL TEMP_IID (cr=9438 pr=0 pw=0 time=34166 us cost=2067 size=0 card=1)


It looks to me that DELETE from TEMP_IID was run 111 thousand times affecting 1.2 million rows or an average of about 20 rows each DELETE. But the "Rows (avg)" says the average was 3 rows for each delete. Am I missing something in how to read this section of tkprof output?

Connor McDonald
April 02, 2019 - 6:41 am UTC

The stats under "Rows" etc are gathered not for every execution (too expensive) but are sampled throughout the trace. For something as simple as a one line delete, the obvious thought is "but its the same data" but for a complicated SQL, don't forget we need to track those numbers for *each* line in the execution plan.

So we sample it, the rate being controlled by a hidden database parameter.

Question about "Rows (1st) Rows (avg) Rows (max)"

Matthew, April 01, 2019 - 5:40 pm UTC

Sorry... I meant to say 2.2 million rows total.
more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's latest video and Chris's latest video from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.