orasrp SQL*Net message to client as non-idle event

[LS Cheng]

Hi

Has anyone used orasrp v3.2.3?

I just profile a trace file with it and it shows SQL*Net message to client
(idle) and SQL*Net message to client waits and top events.

I wonder how can we determine if SQL*Net message to client is idle or not,
for instance tkprof just sum them up and show as single wait event, how is
orasrp accounting the difference?

Cheers

--
LSC

[kyle Hailey]

Check out

http://sites.google.com/site/embtdbo/wait-event-documentation/oracle-network-waits

<http://sites.google.com/site/embtdbo/wait-event-documentation/oracle-network-waits>"SQL*Net
message to client' is not an idle event, it's a the time it takes pack a
message for the network. Tanel Poder has a great write up on it at
http://blog.tanelpoder.com/2008/02/10/sqlnet-message-to-client-vs-sqlnet-more-data-to-client/
If orasrp is calling "SQL*Net message to client" an idle event it makes me
wonder if they are getting it confused with "SQL*Net message from client"
which can rolls up time that can be idle, network or work (as in
application processing time)

orasrp looks cool. I'll have to check it out! I'd heard about a 10046
analyzer from Russia but hadn't tracked it down. This orasrp must be it.

For system load modeling and analysis, check out DB Optimizer:
http://sites.google.com/site/embtdbo/wait-event-documentation/database-tuning

Best
Kyle Hailey
http://db-optimizer.blogspot.com/

[Karl Arao]

Cool ! :) the pictures behind the words really help to grasp the idea
behind *SQL*Net events.*
*With this you get a good visual distinction... which provides better
understanding of course.. *



**- Karl Arao
karlarao.wordpress.com

Post by kyle Hailey
Check out
http://sites.google.com/site/embtdbo/wait-event-documentation/oracle-network-waits
<http://sites.google.com/site/embtdbo/wait-event-documentation/oracle-network-waits>"SQL*Net
message to client' is not an idle event, it's a the time it takes pack a
message for the network. Tanel Poder has a great write up on it at
http://blog.tanelpoder.com/2008/02/10/sqlnet-message-to-client-vs-sqlnet-more-data-to-client/
If orasrp is calling "SQL*Net message to client" an idle event it makes me
wonder if they are getting it confused with "SQL*Net message from client"
which can rolls up time that can be idle, network or work (as in
application processing time)
orasrp looks cool. I'll have to check it out! I'd heard about a 10046
analyzer from Russia but hadn't tracked it down. This orasrp must be it.
http://sites.google.com/site/embtdbo/wait-event-documentation/database-tuning
Best
Kyle Hailey
http://db-optimizer.blogspot.com/

[Egor Starostin]

Hi

Post by LS Cheng
I wonder how can we determine if SQL*Net message to client is idle or not,
for instance tkprof just sum them up and show as single wait event, how is
orasrp accounting the difference?

I think you mean 'SQL*Net message from client' since OraSRP can split
only a couple of events into an [idle] and [non-idle] parts:
'SQL*Net message from client' and 'SQL*Net message from dblink'.

OraSRP decides that 'SQL*Net message from client' is idle when it
happened between db calls. Otherwise (within db call) it's not
attributed as [idle].
If you are familiar with 10046 contents then here's an example from
real trace (with my small comments inline):
***
=====================
PARSING IN CURSOR #1 len=43 dep=0 uid=0 oct=3 lid=0 tim=1304096237
hv=2707617103 ad='89a03e18'
select * from all_objects where rownum < 20
END OF STMT
PARSE #1:c=0,e=143,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1304096209
EXEC #1:c=0,e=744,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1304097036
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1650815232
#bytes=1 p3=0 obj#=-1 tim=1304097096
FETCH #1:c=10000,e=6903,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,tim=1304104057
WAIT #1: nam='SQL*Net message from client' ela= 721 driver
id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1304104865 # [non-idle]
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1650815232
#bytes=1 p3=0 obj#=-1 tim=1304105319
FETCH #1:c=0,e=627,p=0,cr=21,cu=0,mis=0,r=15,dep=0,og=1,tim=1304105524
WAIT #1: nam='SQL*Net message from client' ela= 253 driver
id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1304105818 # [non-idle]
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1650815232
#bytes=1 p3=0 obj#=-1 tim=1304105867
FETCH #1:c=0,e=63,p=0,cr=6,cu=0,mis=0,r=3,dep=0,og=1,tim=1304105900
WAIT #1: nam='SQL*Net message from client' ela= 1960753 driver
id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1306066946 # [idle]
=====================
PARSING IN CURSOR #1 len=21 dep=0 uid=0 oct=3 lid=0 tim=1306069444
hv=2200891488 ad='89913b50'
select user from dual
END OF STMT
PARSE #1:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1306069440
***

The first and the second events 'SQL*Net message from client' are
happened within db call (select * from all_objects ...) and treated as
non-idle.
And the third one is happened between db calls and will be attributed
by OraSRP as [idle].

[LS Cheng]

You are right, it should be 'SQL*Net message from client'! Sorry about that
typo!

From your tracefile you determine 'SQL*Net message from client' as idle

because it is the last wait event before the next parse (db call)?


Thanks!

--
LSC

Hi

Post by LS Cheng
I wonder how can we determine if SQL*Net message to client is idle or

not,

Post by LS Cheng
for instance tkprof just sum them up and show as single wait event, how

is

Post by LS Cheng
orasrp accounting the difference?

I think you mean 'SQL*Net message from client' since OraSRP can split
'SQL*Net message from client' and 'SQL*Net message from dblink'.
OraSRP decides that 'SQL*Net message from client' is idle when it
happened between db calls. Otherwise (within db call) it's not
attributed as [idle].
If you are familiar with 10046 contents then here's an example from
***
=====================
PARSING IN CURSOR #1 len=43 dep=0 uid=0 oct=3 lid=0 tim=1304096237
hv=2707617103 ad='89a03e18'
select * from all_objects where rownum < 20
END OF STMT
PARSE #1:c=0,e=143,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1304096209
EXEC #1:c=0,e=744,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1304097036
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1650815232
#bytes=1 p3=0 obj#=-1 tim=1304097096
FETCH #1:c=10000,e=6903,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,tim=1304104057
WAIT #1: nam='SQL*Net message from client' ela= 721 driver
id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1304104865 # [non-idle]
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1650815232
#bytes=1 p3=0 obj#=-1 tim=1304105319
FETCH #1:c=0,e=627,p=0,cr=21,cu=0,mis=0,r=15,dep=0,og=1,tim=1304105524
WAIT #1: nam='SQL*Net message from client' ela= 253 driver
id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1304105818 # [non-idle]
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1650815232
#bytes=1 p3=0 obj#=-1 tim=1304105867
FETCH #1:c=0,e=63,p=0,cr=6,cu=0,mis=0,r=3,dep=0,og=1,tim=1304105900
WAIT #1: nam='SQL*Net message from client' ela= 1960753 driver
id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1306066946 # [idle]
=====================
PARSING IN CURSOR #1 len=21 dep=0 uid=0 oct=3 lid=0 tim=1306069444
hv=2200891488 ad='89913b50'
select user from dual
END OF STMT
PARSE #1:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1306069440
***
The first and the second events 'SQL*Net message from client' are
happened within db call (select * from all_objects ...) and treated as
non-idle.
And the third one is happened between db calls and will be attributed
by OraSRP as [idle].
--
Egor
http://oracledba.ru

[Egor Starostin]

From your tracefile you determine 'SQL*Net message from client'  as idle
because it is the last wait event before the next parse (db call)?

Right.

[Karl Arao]

Hi Egor,

How about this one.. I have one long "SQL*Net message from client" at
the end that took 14 seconds which constituted 42% of the Statement
Flat Profile.

Event Name% TimeSecondsCalls- Time per Call -AvgMinMax
----------------------------------------------------------------------------------------
PX Deq: Execute Reply 56.1%18.5378s7830.0237s0.0000s1.9955s
<---- 56.1% (18 sec)
SQL*Net message from client 42.7%14.1206s27.0603s0.0004s14.1202s
<----- 42.7% (14.12 sec) but only have 2 long calls
PX Deq: Signal ACK0.4%0.1394s1130.0012s0.0000s0.0996s
FETCH calls [CPU]0.2%0.0781s20.0391s0.0000s0.0781s
PX Deq Credit: send blkd0.2%0.0758s2070.0004s0.0000s0.0179s
os thread startup0.2%0.0517s340.0015s0.0000s0.0020s
PX Deq: Parse Reply0.1%0.0282s280.0010s0.0000s0.0246s
EXEC calls [CPU]0.0%0.0156s10.0156s0.0156s0.0156s
PX Deq Credit: need buffer0.0%0.0108s330.0003s0.0000s0.0075s
PX Deq: Join ACK0.0%0.0018s230.0001s0.0000s0.0015s
PX qref latch0.0%0.0000s100.0000s0.0000s0.0000s
SQL*Net message to client0.0%0.0000s20.0000s0.0000s0.0000s
PARSE calls [CPU]0.0%0.0000s10.0000s0.0000s0.0000s
Total100.0%33.0598s





Below is the snippet of the raw trace:


PARSING IN CURSOR #2 len=14969 dep=0 uid=56 oct=3 lid=56
tim=3065029088 hv=2270366289 ad='fd7e2568'

... output snipped ...

WAIT #2: nam='PX Deq: Execute Reply' ela= 2 sleeptime/senderid=10
passes=1 p3=0 obj#=-1 tim=3084910884
WAIT #2: nam='PX Deq: Execute Reply' ela= 1 sleeptime/senderid=10
passes=1 p3=0 obj#=-1 tim=3084911409
WAIT #2: nam='PX Deq: Execute Reply' ela= 4 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3084911456
WAIT #2: nam='PX Deq: Execute Reply' ela= 48 sleeptime/senderid=200
passes=2 p3=0 obj#=-1 tim=3084911524
WAIT #2: nam='PX Deq: Execute Reply' ela= 1 sleeptime/senderid=10
passes=1 p3=0 obj#=-1 tim=3084912006
FETCH #2:c=78125,e=19702325,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=3084912596
WAIT #2: nam='SQL*Net message from client' ela= 376 driver
id=1111838976 #bytes=1 p3=0 obj#=-1 tim=3084913221 <---- 1st wait
WAIT #2: nam='PX Deq: Signal ACK' ela= 3 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3084913408
*** 2010-02-02 13:50:51.343
WAIT #2: nam='PX Deq: Signal ACK' ela= 99563 sleeptime/senderid=10
passes=2 p3=0 obj#=-1 tim=3085013006
WAIT #2: nam='PX Deq: Signal ACK' ela= 23494 sleeptime/senderid=10
passes=3 p3=0 obj#=-1 tim=3085036560
WAIT #2: nam='PX Deq: Signal ACK' ela= 2 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036593
WAIT #2: nam='PX Deq: Signal ACK' ela= 1 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036618
WAIT #2: nam='PX Deq: Signal ACK' ela= 150 sleeptime/senderid=10
passes=2 p3=0 obj#=-1 tim=3085036789
WAIT #2: nam='PX Deq: Signal ACK' ela= 2 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036858
WAIT #2: nam='PX Deq: Signal ACK' ela= 1 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036888
WAIT #2: nam='PX Deq: Signal ACK' ela= 1 sleeptime/senderid=0 passes=1
p3=0 obj#=-1 tim=3085036911

... output snipped ...

WAIT #2: nam='PX Deq: Signal ACK' ela= 3 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3085058066
WAIT #2: nam='PX Deq: Signal ACK' ela= 85 sleeptime/senderid=200
passes=2 p3=0 obj#=-1 tim=3085058191
WAIT #2: nam='PX Deq: Signal ACK' ela= 3 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3085058272
WAIT #2: nam='PX Deq: Signal ACK' ela= 4 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3085058328
WAIT #2: nam='PX Deq: Signal ACK' ela= 2 sleeptime/senderid=200
passes=2 p3=0 obj#=-1 tim=3085058373
WAIT #2: nam='PX Deq: Signal ACK' ela= 1 sleeptime/senderid=200
passes=1 p3=0 obj#=-1 tim=3085058423
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1111838976
#bytes=1 p3=0 obj#=-1 tim=3085058657
*** 2010-02-02 13:51:05.499
WAIT #2: nam='SQL*Net message from client' ela= 14120193 driver
id=1111838976 #bytes=1 p3=0 obj#=-1 tim=3099178884 <---- 2nd wait
(14.12 sec)
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='PX COORDINATOR (cr=12 pr=0
pw=0 time=19882318 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=0 op='PX SEND QC (ORDER) :TQ10015
(cr=0 pr=0 pw=0 time=0 us)'
STAT #2 id=3 cnt=0 pid=2 pos=1 obj=0 op='SORT ORDER BY (cr=0 pr=0 pw=0
time=0 us)'
STAT #2 id=4 cnt=0 pid=3 pos=1 obj=0 op='PX RECEIVE (cr=0 pr=0 pw=0 time=0 us)'
STAT #2 id=5 cnt=0 pid=4 pos=1 obj=0 op='PX SEND RANGE :TQ10014 (cr=0
pr=0 pw=0 time=0 us)'

... output snipped ...






- Karl Arao
karlarao.wordpress.com
--
http://www.freelists.org/webpage/oracle-l

[Egor Starostin]

Hi

Post by Karl Arao
How about this one.. I have one long "SQL*Net message from client" at
the end that took 14 seconds which constituted 42% of the Statement
Flat Profile.

You mean, why it's not recognized as [idle] event?
I don't know. I've tried to copy-paste your snippet and orasrp
recognized this 'SQL*Net message from client' as an [idle].
Probably, full trace file contains some data which leads orasrp to
decide that it's not an idle event.
Or maybe it's just a bug in orasrp. What version do you use (orasrp --version)?

Or you mean, why in the first place you have 14 seconds of 'SQL*Net
message from client' in your trace? In that case I agree with Mark's
explanation.

[Karl Arao]

Egor .. the version is

[***@karl ~]$ orasrp --version
orasrp 3.2.2 beta

Thanks for clarifying that Mark :) yeah it could be possible, better
if I have put a logon trigger

create or replace trigger sys.set_trace
after logon on database
when (user = 'trace_user')
declare
lcommand varchar(200);
begin
execute immediate 'alter session set statistics_level=all';
execute immediate 'alter session set max_dump_file_size=unlimited';
execute immediate 'alter session set events ''10046 trace name
context forever, level 12''';
end set_trace;
/

then execute the SQL like this to avoid the "SQL*Net message from
client" at the end...

sqlplus "trace_user/trace_user" << eof
-- SQL HERE --
exit;
eof





- Karl Arao
karlarao.wordpress.com
--
http://www.freelists.org/webpage/oracle-l

[Dunbar, Norman]

Morning Karl,

Post by Karl Arao
Thanks for clarifying that Mark :) yeah it could be possible, better
if I have put a logon trigger

Or even something like:

begin
dbms_support.start_trace(true, true);
end;
/

-- SQL HERE

begin
dbms_support.stop_trace;
end;
/

But this depends on having the DBMS_SUPPORT package created (start
?/rdbms/admin/dbmssupp.sql as sys) and execute access granted to your
user.


Cheers,
Norman.



Information in this message may be confidential and may be legally privileged. If you have received this message by mistake, please notify the sender immediately, delete it and do not copy it to anyone else. We have checked this email and its attachments for viruses. But you should still check any attachment before opening it. We may have to make this message and any reply to it public if asked to under the Freedom of Information Act, Data Protection Act or for litigation. Email messages and attachments sent to or from any Environment Agency address may also be accessed by someone other than the sender or recipient, for business purposes. If we have sent you information and you wish to use it please read our terms and conditions which you can get by calling us on 08708 506 506. Find out more about the Environment Agency at www.environment-agency.gov.uk

Information in this message may be confidential and may be legally privileged. If you have received this message by mistake, please notify the sender immediately, delete it and do not copy it to anyone else.

We have checked this email and its attachments for viruses. But you should still check any attachment before opening it.
We may have to make this message and any reply to it public if asked to under the Freedom of Information Act, Data Protection Act or for litigation. Email messages and attachments sent to or from any Environment Agency address may also be accessed by someone other than the sender or recipient, for business purposes.

If we have sent you information and you wish to use it please read our terms and conditions which you can get by calling us on 08708 506 506. Find out more about the Environment Agency at www.environment-agency.gov.uk
--
http://www.freelists.org/webpage/oracle-l

[Niall Litchfield]

assuming you are on 10g, Which I recognise maybe a bad assumption

begin
....
dbms_monitor.session_trace_enable()
end;
/

or alternatively

exec dbms_monitor.serv_mod_act_trace_enable('stuff to identify','future
interesting sessions ','goes here');

On Mon, Feb 8, 2010 at 9:40 AM, Dunbar, Norman <

Post by Dunbar, Norman
Morning Karl,

Post by Karl Arao
Thanks for clarifying that Mark :) yeah it could be possible, better
if I have put a logon trigger

begin
dbms_support.start_trace(true, true);
end;
/
-- SQL HERE
begin
dbms_support.stop_trace;
end;
/
But this depends on having the DBMS_SUPPORT package created (start
?/rdbms/admin/dbmssupp.sql as sys) and execute access granted to your
user.
Cheers,
Norman.
Information in this message may be confidential and may be legally
privileged. If you have received this message by mistake, please notify the
sender immediately, delete it and do not copy it to anyone else. We have
checked this email and its attachments for viruses. But you should still
check any attachment before opening it. We may have to make this message and
any reply to it public if asked to under the Freedom of Information Act,
Data Protection Act or for litigation. Email messages and attachments sent
to or from any Environment Agency address may also be accessed by someone
other than the sender or recipient, for business purposes. If we have sent
you information and you wish to use it please read our terms and conditions
which you can get by calling us on 08708 506 506. Find out more about the
Environment Agency at www.environment-agency.gov.uk
Information in this message may be confidential and may be legally
privileged. If you have received this message by mistake, please notify the
sender immediately, delete it and do not copy it to anyone else.
We have checked this email and its attachments for viruses. But you should
still check any attachment before opening it.
We may have to make this message and any reply to it public if asked to
under the Freedom of Information Act, Data Protection Act or for litigation.
Email messages and attachments sent to or from any Environment Agency
address may also be accessed by someone other than the sender or recipient,
for business purposes.
If we have sent you information and you wish to use it please read our
terms and conditions which you can get by calling us on 08708 506 506. Find
out more about the Environment Agency at www.environment-agency.gov.uk
--
http://www.freelists.org/webpage/oracle-l