Help Interpreting TKProf
Hi.
I'm running tkprof on my PC with a version 9i client.
The trace file was generated on a Solars version
8.1.7.4 database. (I'm using tkprof on 9i to get wait
statistics.) The trace is 10046 level 12
I assume the time waited is in addition to the elapsed
time for the call -- correct?
Since the database itself is 8i, does that mean that
the wait stats are in centiseconds? I want to know
what the sql*net message from client wait time of
10.73 represents:
Elapsed times include waiting on following events:
Event waited onTimes Max. Wait Total
Waited
Waited -- -
SQL*Net message to client 8 0.00 0.00
SQL*Net message from client 8 10.71 10.73
Here's all the code:
select /*ClassSQL*/ distinct co.class,cl.claname
from
classorder co,class cl where co.paper='DNA' and
co.page='EM' and co.class=
cl.class and co.paper=cl.paper and cl.clatype='0'
order by 1
call count cpuelapsed disk
querycurrentrows
--- -- -- --
-- -- --
Parse1 0.01 0.01 0
0 0 0
Execute 1 0.00 0.00 0
0 0 0
Fetch8 0.01 0.01 0
169 0 82
--- -- -- --
-- -- --
total 10 0.02 0.02 0
169 0 82
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 586 (SYSADMIN)
Rows Row Source Operation
---
---
82 SORT UNIQUE
82 NESTED LOOPS
83INDEX RANGE SCAN (object id 395118)
82TABLE ACCESS BY INDEX ROWID CLASS
164 INDEX UNIQUE SCAN (object id 395113)
Rows Execution Plan
---
---
0 SELECT STATEMENT GOAL: CHOOSE
82 SORT (UNIQUE)
82NESTED LOOPS
83 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'I_CLO1' (NON-UNIQUE)
82 TABLE ACCESS GOAL: ANALYZED (BY INDEX
ROWID) OF 'CLASS'
164 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'I_CLA1' (UNIQUE)
Thanks for any help.
Barb
__
Do you Yahoo!?
Protect your identity with Yahoo! Mail AddressGuard
http://antispam.yahoo.com/whatsnewfree
--
Please see the official ORACLE-L FAQ: http://www.orafaq.net
--
Author: Barbara Baker
INET: [EMAIL PROTECTED]
Fat City Network Services-- 858-538-5051 http://www.fatcity.com
San Diego, California-- Mailing list and web hosting services
-
To REMOVE yourself from this mailing list, send an E-Mail message
to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from). You may
also send the HELP command for other information (like subscribing).
Re: Help Interpreting TKProf
Barbs, what this trace file tells you is that the client program
takes much more time delivering the data to oracle then it takes
for oracle to deliver the data to the program. In other words, your
program takes its time between the calls to the database. Maybe you
should run the profiler and see where time in the program is spent.
On 11/12/2003 01:09:24 PM, Barbara Baker wrote:
Hi.
I'm running tkprof on my PC with a version 9i client.
The trace file was generated on a Solars version
8.1.7.4 database. (I'm using tkprof on 9i to get wait
statistics.) The trace is 10046 level 12
I assume the time waited is in addition to the elapsed
time for the call -- correct?
Since the database itself is 8i, does that mean that
the wait stats are in centiseconds? I want to know
what the sql*net message from client wait time of
10.73 represents:
Elapsed times include waiting on following events:
Event waited onTimes Max. Wait Total
Waited
Waited -- -
SQL*Net message to client 8 0.00 0.00
SQL*Net message from client 8 10.71 10.73
Here's all the code:
select /*ClassSQL*/ distinct co.class,cl.claname
from
classorder co,class cl where co.paper='DNA' and
co.page='EM' and co.class=
cl.class and co.paper=cl.paper and cl.clatype='0'
order by 1
call count cpuelapsed disk
querycurrentrows
--- -- -- --
-- -- --
Parse1 0.01 0.01 0
0 0 0
Execute 1 0.00 0.00 0
0 0 0
Fetch8 0.01 0.01 0
169 0 82
--- -- -- --
-- -- --
total 10 0.02 0.02 0
169 0 82
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 586 (SYSADMIN)
Rows Row Source Operation
---
---
82 SORT UNIQUE
82 NESTED LOOPS
83INDEX RANGE SCAN (object id 395118)
82TABLE ACCESS BY INDEX ROWID CLASS
164 INDEX UNIQUE SCAN (object id 395113)
Rows Execution Plan
---
---
0 SELECT STATEMENT GOAL: CHOOSE
82 SORT (UNIQUE)
82NESTED LOOPS
83 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'I_CLO1' (NON-UNIQUE)
82 TABLE ACCESS GOAL: ANALYZED (BY INDEX
ROWID) OF 'CLASS'
164 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'I_CLA1' (UNIQUE)
Thanks for any help.
Barb
__
Do you Yahoo!?
Protect your identity with Yahoo! Mail AddressGuard
http://antispam.yahoo.com/whatsnewfree
--
Please see the official ORACLE-L FAQ: http://www.orafaq.net
--
Author: Barbara Baker
INET: [EMAIL PROTECTED]
Fat City Network Services-- 858-538-5051 http://www.fatcity.com
San Diego, California-- Mailing list and web hosting services
-
To REMOVE yourself from this mailing list, send an E-Mail message
to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from). You may
also send the HELP command for other information (like subscribing).
Mladen Gogala
Oracle DBA
Note:
This message is for the named person's use only. It may contain confidential,
proprietary or legally privileged information. No confidentiality or privilege is
waived or lost by any mistransmission. If you receive this message in error, please
immediately delete it and all copies of it from your system, destroy any hard copies
of it and notify the sender. You must not, directly or indirectly, use, disclose,
distribute, print, or copy any part of this message if you are not the intended
recipient. Wang Trading LLC and any of its subsidiaries each reserve the right to
monitor all e-mail communications through its networks.
Any views expressed in this message are those of the individual sender, except where
the message states otherwise and the sender is authorized to state them to be the
views of any such entity.
--
Please see the official ORACLE-L FAQ: http://www.orafaq.net
--
Author: Mladen Gogala
INET: [EMAIL PROTECTED]
Fat City Network Services-- 858-538-5051 http://www.fatcity.com
San Diego, California-- Mailing list and web hosting services
-
To REMOVE yourself from this mailing list, send an E-Mail message
to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
Re: Help Interpreting TKProf
Barb,
This is a great example of where reading the trace file will tell you
what you need to know. Is the 10 centiseconds of time in 8 1.25
centisecond events or in 1 10 centisecond event and 7 .1 centisecond
events? The location (parse/execute/fetch/post tx) are also important.
Daniel
Barbara Baker wrote:
Hi.
I'm running tkprof on my PC with a version 9i client.
The trace file was generated on a Solars version
8.1.7.4 database. (I'm using tkprof on 9i to get wait
statistics.) The trace is 10046 level 12
I assume the time waited is in addition to the elapsed
time for the call -- correct?
Since the database itself is 8i, does that mean that
the wait stats are in centiseconds? I want to know
what the sql*net message from client wait time of
10.73 represents:
Elapsed times include waiting on following events:
Event waited onTimes Max. Wait Total
Waited
Waited -- -
SQL*Net message to client 8 0.00 0.00
SQL*Net message from client 8 10.71 10.73
Here's all the code:
select /*ClassSQL*/ distinct co.class,cl.claname
from
classorder co,class cl where co.paper='DNA' and
co.page='EM' and co.class=
cl.class and co.paper=cl.paper and cl.clatype='0'
order by 1
call count cpuelapsed disk
querycurrentrows
--- -- -- --
-- -- --
Parse1 0.01 0.01 0
0 0 0
Execute 1 0.00 0.00 0
0 0 0
Fetch8 0.01 0.01 0
169 0 82
--- -- -- --
-- -- --
total 10 0.02 0.02 0
169 0 82
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 586 (SYSADMIN)
Rows Row Source Operation
---
---
82 SORT UNIQUE
82 NESTED LOOPS
83INDEX RANGE SCAN (object id 395118)
82TABLE ACCESS BY INDEX ROWID CLASS
164 INDEX UNIQUE SCAN (object id 395113)
Rows Execution Plan
---
---
0 SELECT STATEMENT GOAL: CHOOSE
82 SORT (UNIQUE)
82NESTED LOOPS
83 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'I_CLO1' (NON-UNIQUE)
82 TABLE ACCESS GOAL: ANALYZED (BY INDEX
ROWID) OF 'CLASS'
164 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'I_CLA1' (UNIQUE)
Thanks for any help.
Barb
__
Do you Yahoo!?
Protect your identity with Yahoo! Mail AddressGuard
http://antispam.yahoo.com/whatsnewfree
--
Please see the official ORACLE-L FAQ: http://www.orafaq.net
--
Author: Barbara Baker
INET: [EMAIL PROTECTED]
Fat City Network Services-- 858-538-5051 http://www.fatcity.com
San Diego, California-- Mailing list and web hosting services
-
To REMOVE yourself from this mailing list, send an E-Mail message
to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from). You may
also send the HELP command for other information (like subscribing).
--
Please see the official ORACLE-L FAQ: http://www.orafaq.net
--
Author: Daniel Fink
INET: [EMAIL PROTECTED]
Fat City Network Services-- 858-538-5051 http://www.fatcity.com
San Diego, California-- Mailing list and web hosting services
-
To REMOVE yourself from this mailing list, send an E-Mail message
to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from). You may
also send the HELP command for other information (like subscribing).
RE: Help Interpreting TKProf
Barb,
I think tkprof prints output in seconds, so I think you're looking at
10.73 seconds of response time here.
First, some definitions:
- The SQL*Net message from client event maps to an OS read() call to
the file descriptor to which SQL*Net is connected.
- The SQL*Net message to client event maps to an OS write() call to
the file descriptor to which SQL*Net is connected.
The Oracle kernel uses a to event just to write a short message (often
1 byte) to a pipe. It takes practically no time to do that--usually on
the order of 3 microseconds (0.03 seconds).
However, as soon as a given to event completes, the kernel often next
executes a read() from the same file descriptor. The duration of this
read() is what ultimately shows up as the from event's duration.
What this means is that all the time spent in the following tiers gets
logged as SQL*Net message from client (see p13 of my book for a
picture):
- comm from db server to apps server
- apps server computation time
- comm from apps server to browser
- browser computation time
- user think time
- comm from browser to apps server
- apps server computation time
- comm from apps server to db server
Thus you'll almost always (maybe even always always) see from events
lasting longer than to events.
Getting good information out of SQL*Net message from client is
possible only if you are careful in how you collect your trace data. If,
for example, you allow 10 seconds of user think time into your trace
data, then it forces you to do a lot more analytical work on your trace
data to properly ignore the right data--unless, of course, the thing
you need to find out is that the user is wasting your business's time by
consuming 10 seconds instead of 2.
Optimizing Oracle Performance covers all this in great detail.
Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
Upcoming events:
- Performance Diagnosis 101: 11/19 Sydney, 12/16 Detroit
- SQL Optimization 101: 12/8 Dallas, 2/16 Dallas
- Hotsos Symposium 2004: March 7-10 Dallas
- Visit www.hotsos.com for schedule details...
-Original Message-
Barbara Baker
Sent: Wednesday, November 12, 2003 12:09 PM
To: Multiple recipients of list ORACLE-L
Hi.
I'm running tkprof on my PC with a version 9i client.
The trace file was generated on a Solars version
8.1.7.4 database. (I'm using tkprof on 9i to get wait
statistics.) The trace is 10046 level 12
I assume the time waited is in addition to the elapsed
time for the call -- correct?
Since the database itself is 8i, does that mean that
the wait stats are in centiseconds? I want to know
what the sql*net message from client wait time of
10.73 represents:
Elapsed times include waiting on following events:
Event waited onTimes Max. Wait Total
Waited
Waited -- -
SQL*Net message to client 8 0.00 0.00
SQL*Net message from client 8 10.71 10.73
Here's all the code:
select /*ClassSQL*/ distinct co.class,cl.claname
from
classorder co,class cl where co.paper='DNA' and
co.page='EM' and co.class=
cl.class and co.paper=cl.paper and cl.clatype='0'
order by 1
call count cpuelapsed disk
querycurrentrows
--- -- -- --
-- -- --
Parse1 0.01 0.01 0
0 0 0
Execute 1 0.00 0.00 0
0 0 0
Fetch8 0.01 0.01 0
169 0 82
--- -- -- --
-- -- --
total 10 0.02 0.02 0
169 0 82
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 586 (SYSADMIN)
Rows Row Source Operation
---
---
82 SORT UNIQUE
82 NESTED LOOPS
83INDEX RANGE SCAN (object id 395118)
82TABLE ACCESS BY INDEX ROWID CLASS
164 INDEX UNIQUE SCAN (object id 395113)
Rows Execution Plan
---
---
0 SELECT STATEMENT GOAL: CHOOSE
82 SORT (UNIQUE)
82NESTED LOOPS
83 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'I_CLO1' (NON-UNIQUE)
82 TABLE ACCESS GOAL: ANALYZED (BY INDEX
ROWID) OF 'CLASS'
164 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF
'I_CLA1' (UNIQUE)
Thanks for any help.
Barb
__
Do you Yahoo!?
Protect your identity with Yahoo! Mail AddressGuard
http://antispam.yahoo.com/whatsnewfree
--
Please see the official ORACLE-L FAQ: http://www.orafaq.net
--
Author: Barbara Baker
INET: [EMAIL PROTECTED]
Fat City Network Services-- 858-538-5051 http://www.fatcity.com
San Diego, California-- Mailing list and web hosting services
-
To
Re: Help Interpreting TKProf
In other words, you can finish performance analysis of the client
only by finding out where the time is spent on the client side.
If it's an interactive program and you have a homo sapiens interacting
with it, then think time is a factor. If, on the other hand, it's
a batch program, then run a profiler (gprof, Jprof or alike) to find
out where the time is spent.
On 11/12/2003 02:09:28 PM, Cary Millsap wrote:
Barb,
I think tkprof prints output in seconds, so I think you're looking at
10.73 seconds of response time here.
First, some definitions:
- The SQL*Net message from client event maps to an OS read() call to
the file descriptor to which SQL*Net is connected.
- The SQL*Net message to client event maps to an OS write() call to
the file descriptor to which SQL*Net is connected.
The Oracle kernel uses a to event just to write a short message (often
1 byte) to a pipe. It takes practically no time to do that--usually on
the order of 3 microseconds (0.03 seconds).
However, as soon as a given to event completes, the kernel often next
executes a read() from the same file descriptor. The duration of this
read() is what ultimately shows up as the from event's duration.
What this means is that all the time spent in the following tiers gets
logged as SQL*Net message from client (see p13 of my book for a
picture):
- comm from db server to apps server
- apps server computation time
- comm from apps server to browser
- browser computation time
- user think time
- comm from browser to apps server
- apps server computation time
- comm from apps server to db server
Thus you'll almost always (maybe even always always) see from events
lasting longer than to events.
Getting good information out of SQL*Net message from client is
possible only if you are careful in how you collect your trace data. If,
for example, you allow 10 seconds of user think time into your trace
data, then it forces you to do a lot more analytical work on your trace
data to properly ignore the right data--unless, of course, the thing
you need to find out is that the user is wasting your business's time by
consuming 10 seconds instead of 2.
Optimizing Oracle Performance covers all this in great detail.
Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
Upcoming events:
- Performance Diagnosis 101: 11/19 Sydney, 12/16 Detroit
- SQL Optimization 101: 12/8 Dallas, 2/16 Dallas
- Hotsos Symposium 2004: March 7-10 Dallas
- Visit www.hotsos.com for schedule details...
-Original Message-
Barbara Baker
Sent: Wednesday, November 12, 2003 12:09 PM
To: Multiple recipients of list ORACLE-L
Hi.
I'm running tkprof on my PC with a version 9i client.
The trace file was generated on a Solars version
8.1.7.4 database. (I'm using tkprof on 9i to get wait
statistics.) The trace is 10046 level 12
I assume the time waited is in addition to the elapsed
time for the call -- correct?
Since the database itself is 8i, does that mean that
the wait stats are in centiseconds? I want to know
what the sql*net message from client wait time of
10.73 represents:
Elapsed times include waiting on following events:
Event waited onTimes Max. Wait Total
Waited
Waited -- -
SQL*Net message to client 8 0.00 0.00
SQL*Net message from client 8 10.71 10.73
Here's all the code:
select /*ClassSQL*/ distinct co.class,cl.claname
from
classorder co,class cl where co.paper='DNA' and
co.page='EM' and co.class=
cl.class and co.paper=cl.paper and cl.clatype='0'
order by 1
call count cpuelapsed disk
querycurrentrows
--- -- -- --
-- -- --
Parse1 0.01 0.01 0
0 0 0
Execute 1 0.00 0.00 0
0 0 0
Fetch8 0.01 0.01 0
169 0 82
--- -- -- --
-- -- --
total 10 0.02 0.02 0
169 0 82
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 586 (SYSADMIN)
Rows Row Source Operation
---
---
82 SORT UNIQUE
82 NESTED LOOPS
83INDEX RANGE SCAN (object id 395118)
82TABLE ACCESS BY INDEX ROWID CLASS
164 INDEX UNIQUE SCAN (object id 395113)
Rows Execution Plan
---
---
0 SELECT STATEMENT GOAL: CHOOSE
82 SORT (UNIQUE)
82NESTED LOOPS
83 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'I_CLO1' (NON-UNIQUE)
82 TABLE ACCESS GOAL: ANALYZED (BY INDEX
ROWID) OF 'CLASS'
164 INDEX
Re: Help Interpreting TKProf
Daniel, it's seconds, not centiseconds. The tkprof writes things down in seconds. If it's a 9i trace, then the times within trc files are in microseconds. In trc file produced by 8i, it's centiseconds. By some magic, tkprof knows the difference and usually gets the right times. On 11/12/2003 01:49:34 PM, Daniel Fink wrote: Barb, This is a great example of where reading the trace file will tell you what you need to know. Is the 10 centiseconds of time in 8 1.25 centisecond events or in 1 10 centisecond event and 7 .1 centisecond events? The location (parse/execute/fetch/post tx) are also important. Daniel Barbara Baker wrote: Hi. I'm running tkprof on my PC with a version 9i client. The trace file was generated on a Solars version 8.1.7.4 database. (I'm using tkprof on 9i to get wait statistics.) The trace is 10046 level 12 I assume the time waited is in addition to the elapsed time for the call -- correct? Since the database itself is 8i, does that mean that the wait stats are in centiseconds? I want to know what the sql*net message from client wait time of 10.73 represents: Elapsed times include waiting on following events: Event waited onTimes Max. Wait Total Waited Waited -- - SQL*Net message to client 8 0.00 0.00 SQL*Net message from client 8 10.71 10.73 Here's all the code: select /*ClassSQL*/ distinct co.class,cl.claname from classorder co,class cl where co.paper='DNA' and co.page='EM' and co.class= cl.class and co.paper=cl.paper and cl.clatype='0' order by 1 call count cpuelapsed disk querycurrentrows --- -- -- -- -- -- -- Parse1 0.01 0.01 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch8 0.01 0.01 0 169 0 82 --- -- -- -- -- -- -- total 10 0.02 0.02 0 169 0 82 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 586 (SYSADMIN) Rows Row Source Operation --- --- 82 SORT UNIQUE 82 NESTED LOOPS 83INDEX RANGE SCAN (object id 395118) 82TABLE ACCESS BY INDEX ROWID CLASS 164 INDEX UNIQUE SCAN (object id 395113) Rows Execution Plan --- --- 0 SELECT STATEMENT GOAL: CHOOSE 82 SORT (UNIQUE) 82NESTED LOOPS 83 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'I_CLO1' (NON-UNIQUE) 82 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'CLASS' 164 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'I_CLA1' (UNIQUE) Thanks for any help. Barb __ Do you Yahoo!? Protect your identity with Yahoo! Mail AddressGuard http://antispam.yahoo.com/whatsnewfree -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Barbara Baker INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Daniel Fink INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing). Mladen Gogala Oracle DBA Note: This message is for the named person's use only. It may contain confidential, proprietary or legally privileged information. No confidentiality or privilege is waived or lost by any mistransmission. If you receive this message in error, please immediately delete it and all copies of it from your system, destroy any hard copies of it and notify the sender. You must not, directly or
Re: Help Interpreting TKProf
Daniel: Does this mean I was supposed to be paying attention in class?? Here's everything I can find associated with sql*net message from client in that cursor. Can't figure out from this how it came up with 10.73 (although that one wait matches up with the max wait of 10.71) Am I being really dense? WAIT!! don't answer that! WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1071 p1=1413697536 p2=1 p3=0 --- Daniel Fink [EMAIL PROTECTED] wrote: Barb, This is a great example of where reading the trace file will tell you what you need to know. Is the 10 centiseconds of time in 8 1.25 centisecond events or in 1 10 centisecond event and 7 .1 centisecond events? The location (parse/execute/fetch/post tx) are also important. Daniel Barbara Baker wrote: Hi. I'm running tkprof on my PC with a version 9i client. The trace file was generated on a Solars version 8.1.7.4 database. (I'm using tkprof on 9i to get wait statistics.) The trace is 10046 level 12 I assume the time waited is in addition to the elapsed time for the call -- correct? Since the database itself is 8i, does that mean that the wait stats are in centiseconds? I want to know what the sql*net message from client wait time of 10.73 represents: Elapsed times include waiting on following events: Event waited onTimes Max. Wait Total Waited Waited -- - SQL*Net message to client 8 0.00 0.00 SQL*Net message from client 8 10.71 10.73 Here's all the code: select /*ClassSQL*/ distinct co.class,cl.claname from classorder co,class cl where co.paper='DNA' and co.page='EM' and co.class= cl.class and co.paper=cl.paper and cl.clatype='0' order by 1 call count cpuelapsed disk querycurrentrows --- -- -- -- -- -- -- Parse1 0.01 0.01 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch8 0.01 0.01 0 169 0 82 --- -- -- -- -- -- -- total 10 0.02 0.02 0 169 0 82 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 586 (SYSADMIN) Rows Row Source Operation --- --- 82 SORT UNIQUE 82 NESTED LOOPS 83INDEX RANGE SCAN (object id 395118) 82TABLE ACCESS BY INDEX ROWID CLASS 164 INDEX UNIQUE SCAN (object id 395113) Rows Execution Plan --- --- 0 SELECT STATEMENT GOAL: CHOOSE 82 SORT (UNIQUE) 82NESTED LOOPS 83 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'I_CLO1' (NON-UNIQUE) 82 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'CLASS' 164 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'I_CLA1' (UNIQUE) Thanks for any help. Barb __ Do you Yahoo!? Protect your identity with Yahoo! Mail AddressGuard http://antispam.yahoo.com/whatsnewfree -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Barbara Baker INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Daniel Fink INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL
Re: Help Interpreting TKProf
Barbara, I know how distracted you were with all the jokes being tossed about, but really... It looks to me (with just this snippet of trace) that the cursor #3 did some communication and then waited for 10 seconds for a response. Without seeing the raw trace file and sequence of events, this is my best guess. Daniel Barbara Baker wrote: Daniel: Does this mean I was supposed to be paying attention in class?? Here's everything I can find associated with sql*net message from client in that cursor. Can't figure out from this how it came up with 10.73 (although that one wait matches up with the max wait of 10.71) Am I being really dense? WAIT!! don't answer that! WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1 wait_time = 1 centisecond p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1 wait_time = wait_time (1 cs) + 1 cs = 2 cs p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1071 p1=1413697536 p2=1 p3=0 wait_time = wait_time(2 cs) + 1071 cs = 1073 cs -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Daniel Fink INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing).
RE: Help Interpreting TKProf
Barb, What you're really after is called forward attribution in the book. You need to see the dbcall that immediately follows each WAIT nam='SQL*Net message from client' event in the trace file. This will tell you what database call's execution it was that ended the read(). Cary Millsap Hotsos Enterprises, Ltd. http://www.hotsos.com Upcoming events: - Performance Diagnosis 101: 11/19 Sydney, 12/16 Detroit - SQL Optimization 101: 12/8 Dallas, 2/16 Dallas - Hotsos Symposium 2004: March 7-10 Dallas - Visit www.hotsos.com for schedule details... -Original Message- Daniel Fink Sent: Wednesday, November 12, 2003 2:35 PM To: Multiple recipients of list ORACLE-L Barbara, I know how distracted you were with all the jokes being tossed about, but really... It looks to me (with just this snippet of trace) that the cursor #3 did some communication and then waited for 10 seconds for a response. Without seeing the raw trace file and sequence of events, this is my best guess. Daniel Barbara Baker wrote: Daniel: Does this mean I was supposed to be paying attention in class?? Here's everything I can find associated with sql*net message from client in that cursor. Can't figure out from this how it came up with 10.73 (although that one wait matches up with the max wait of 10.71) Am I being really dense? WAIT!! don't answer that! WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1 wait_time = 1 centisecond p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1 wait_time = wait_time (1 cs) + 1 cs = 2 cs p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1071 p1=1413697536 p2=1 p3=0 wait_time = wait_time(2 cs) + 1071 cs = 1073 cs -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Daniel Fink INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing). -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Cary Millsap INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing).
RE: Help Interpreting TKProf
To finish off the answer to your direct question, compute the sum of the ela values shown in your excerpt: 0 cs 0 1 0 0 0 1 1071 --- 1073 cs = 10.73 seconds Cary Millsap Hotsos Enterprises, Ltd. http://www.hotsos.com Upcoming events: - Performance Diagnosis 101: 11/19 Sydney, 12/16 Detroit - SQL Optimization 101: 12/8 Dallas, 2/16 Dallas - Hotsos Symposium 2004: March 7-10 Dallas - Visit www.hotsos.com for schedule details... -Original Message- Barbara Baker Sent: Wednesday, November 12, 2003 1:59 PM To: Multiple recipients of list ORACLE-L Daniel: Does this mean I was supposed to be paying attention in class?? Here's everything I can find associated with sql*net message from client in that cursor. Can't figure out from this how it came up with 10.73 (although that one wait matches up with the max wait of 10.71) Am I being really dense? WAIT!! don't answer that! WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1 p1=1413697536 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 1071 p1=1413697536 p2=1 p3=0 --- Daniel Fink [EMAIL PROTECTED] wrote: Barb, This is a great example of where reading the trace file will tell you what you need to know. Is the 10 centiseconds of time in 8 1.25 centisecond events or in 1 10 centisecond event and 7 .1 centisecond events? The location (parse/execute/fetch/post tx) are also important. Daniel Barbara Baker wrote: Hi. I'm running tkprof on my PC with a version 9i client. The trace file was generated on a Solars version 8.1.7.4 database. (I'm using tkprof on 9i to get wait statistics.) The trace is 10046 level 12 I assume the time waited is in addition to the elapsed time for the call -- correct? Since the database itself is 8i, does that mean that the wait stats are in centiseconds? I want to know what the sql*net message from client wait time of 10.73 represents: Elapsed times include waiting on following events: Event waited onTimes Max. Wait Total Waited Waited -- - SQL*Net message to client 8 0.00 0.00 SQL*Net message from client 8 10.71 10.73 Here's all the code: select /*ClassSQL*/ distinct co.class,cl.claname from classorder co,class cl where co.paper='DNA' and co.page='EM' and co.class= cl.class and co.paper=cl.paper and cl.clatype='0' order by 1 call count cpuelapsed disk querycurrentrows --- -- -- -- -- -- -- Parse1 0.01 0.01 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch8 0.01 0.01 0 169 0 82 --- -- -- -- -- -- -- total 10 0.02 0.02 0 169 0 82 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 586 (SYSADMIN) Rows Row Source Operation --- --- 82 SORT UNIQUE 82 NESTED LOOPS 83INDEX RANGE SCAN (object id 395118) 82TABLE ACCESS BY INDEX ROWID CLASS 164 INDEX UNIQUE SCAN (object id 395113) Rows Execution Plan --- --- 0 SELECT STATEMENT GOAL: CHOOSE 82 SORT (UNIQUE) 82NESTED LOOPS 83 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'I_CLO1' (NON-UNIQUE) 82 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'CLASS' 164 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'I_CLA1' (UNIQUE) Thanks for any help. Barb __ Do you Yahoo!? Protect your identity with Yahoo! Mail AddressGuard http://antispam.yahoo.com/whatsnewfree -- Please see the official ORACLE-L FAQ: http://www.orafaq.net -- Author: Barbara Baker INET: [EMAIL PROTECTED] Fat City Network Services-- 858-538-5051 http://www.fatcity.com San Diego, California-- Mailing list and web hosting services - To REMOVE yourself from this mailing list, send an E-Mail message to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in the message BODY, include a line
