oracledba.ru Forum Index oracledba.ru

 
 FAQFAQ   SearchSearch   MemberlistMemberlist   UsergroupsUsergroups   RegisterRegister 
 ProfileProfile   Log in to check your private messagesLog in to check your private messages   Log inLog in 

рассинхронизация tim и ela

 
This forum is locked: you cannot post, reply to, or edit topics.   This topic is locked: you cannot edit posts or make replies.    oracledba.ru Forum Index -> OraSRP
View previous topic :: View next topic  
Author Message
adversus



Joined: 26 Jul 2008
Posts: 2
PostPosted: Mon Oct 27, 2008 3:08 pm    Post subject: рассинхронизация tim и ela Reply with quote
Доброго времени суток!

для начала приведу небольшую вырезку из трейса (сами запросы я немного порезал - убрал столбцы, дабы не захламлять трейс).

Code:

FETCH #229:c=0,e=35,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=2,tim=6712998615
*** 2008-10-27 14:53:29.306
WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713001132
STAT #278 id=1 cnt=1 pid=0 pos=1 obj=98908 op='TABLE ACCESS BY INDEX ROWID SPMNPLAN (cr=3 pr=0 pw=0 time=22 us)'
STAT #278 id=2 cnt=1 pid=1 pos=1 obj=98909 op='INDEX UNIQUE SCAN SPMNPLAN0 (cr=2 pr=0 pw=0 time=9 us)'
EXEC #229:c=0,e=116,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=6713001562
WAIT #229: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713001600
FETCH #229:c=0,e=37,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=2,tim=6713001615
WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713002276
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1297371904 #bytes=410295344 p3=0 obj#=98331 tim=6713002324
WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713002337
=====================
PARSING IN CURSOR #279 len=1010 dep=0 uid=2718 oct=3 lid=2718 tim=6713002405 hv=3832172761 ad='a4645788'
SELECT ...
FROM GAL."SPMNPLAN" T0
WHERE T0."FNREC"=:P1
END OF STMT
PARSE #279:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713002403
EXEC #279:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713002583
WAIT #279: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713002599
WAIT #279: nam='SQL*Net more data to client' ela= 5 driver id=1297371904 #bytes=2001 p3=0 obj#=98331 tim=6713002657
WAIT #279: nam='SQL*Net more data to client' ela= 6 driver id=1297371904 #bytes=2008 p3=0 obj#=98331 tim=6713002736
FETCH #279:c=0,e=54,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=6713002753
WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713004938
STAT #279 id=1 cnt=1 pid=0 pos=1 obj=98908 op='TABLE ACCESS BY INDEX ROWID SPMNPLAN (cr=3 pr=0 pw=0 time=26 us)'
STAT #279 id=2 cnt=1 pid=1 pos=1 obj=98909 op='INDEX UNIQUE SCAN SPMNPLAN0 (cr=2 pr=0 pw=0 time=12 us)'
EXEC #192:c=0,e=94,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713005102
WAIT #192: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713005129
FETCH #192:c=0,e=31,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=6713005144
WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713005617
EXEC #192:c=0,e=88,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713005723
WAIT #192: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713005746
FETCH #192:c=0,e=26,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=6713005761
WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713006356
EXEC #192:c=0,e=105,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713006501
WAIT #192: nam='SQL*Net message to client' ela= 4 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713006536
FETCH #192:c=0,e=39,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=6713006554
WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713007119
EXEC #192:c=0,e=87,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713007224
WAIT #192: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713007247
FETCH #192:c=0,e=26,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=6713007261
WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713008179
EXEC #229:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=6713008305
WAIT #229: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713008338
FETCH #229:c=0,e=33,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=2,tim=6713008351
WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713009087
WAIT #0: nam='SQL*Net more data from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713009145
=====================
PARSING IN CURSOR #278 len=1010 dep=0 uid=2718 oct=3 lid=2718 tim=6713009208 hv=3832172761 ad='a4645788'
SELECT
FROM GAL."SPMNPLAN" T0
WHERE T0."FNREC"=:P1
END OF STMT
PARSE #278:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713009206
EXEC #278:c=0,e=77,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713009368
WAIT #278: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713009384
WAIT #278: nam='SQL*Net more data to client' ela= 8 driver id=1297371904 #bytes=2001 p3=0 obj#=98331 tim=6713009443
WAIT #278: nam='SQL*Net more data to client' ela= 8 driver id=1297371904 #bytes=2008 p3=0 obj#=98331 tim=6713009525
FETCH #278:c=0,e=55,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=6713009541
WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713010528
STAT #278 id=1 cnt=1 pid=0 pos=1 obj=98908 op='TABLE ACCESS BY INDEX ROWID SPMNPLAN (cr=3 pr=0 pw=0 time=27 us)'
STAT #278 id=2 cnt=1 pid=1 pos=1 obj=98909 op='INDEX UNIQUE SCAN SPMNPLAN0 (cr=2 pr=0 pw=0 time=13 us)'
EXEC #229:c=0,e=102,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=6713010707
WAIT #229: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713010735
FETCH #229:c=0,e=30,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=2,tim=6713010749
WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713011481
WAIT #0: nam='SQL*Net more data from client' ela= 3 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713011533
=====================
PARSING IN CURSOR #279 len=1010 dep=0 uid=2718 oct=3 lid=2718 tim=6713011600 hv=3832172761 ad='a4645788'
SELECT
FROM GAL."SPMNPLAN" T0
WHERE T0."FNREC"=:P1
END OF STMT
PARSE #279:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713011598
EXEC #279:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713011764
WAIT #279: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713011778
WAIT #279: nam='SQL*Net more data to client' ela= 6 driver id=1297371904 #bytes=2001 p3=0 obj#=98331 tim=6713011835
WAIT #279: nam='SQL*Net more data to client' ela= 5 driver id=1297371904 #bytes=2008 p3=0 obj#=98331 tim=6713011914
FETCH #279:c=0,e=51,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=6713011930
WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713012784
STAT #279 id=1 cnt=1 pid=0 pos=1 obj=98908 op='TABLE ACCESS BY INDEX ROWID SPMNPLAN (cr=3 pr=0 pw=0 time=24 us)'
STAT #279 id=2 cnt=1 pid=1 pos=1 obj=98909 op='INDEX UNIQUE SCAN SPMNPLAN0 (cr=2 pr=0 pw=0 time=11 us)'
EXEC #229:c=0,e=106,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=6713012956
WAIT #229: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713012988
FETCH #229:c=0,e=34,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=2,tim=6713013002
WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713013659
WAIT #0: nam='SQL*Net more data from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713013702
=====================
PARSING IN CURSOR #278 len=1010 dep=0 uid=2718 oct=3 lid=2718 tim=6713013757 hv=3832172761 ad='a4645788'
SELECT
FROM GAL."SPMNPLAN" T0
WHERE T0."FNREC"=:P1
END OF STMT
PARSE #278:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713013755
EXEC #278:c=0,e=70,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6713013898
WAIT #278: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6713013913
WAIT #278: nam='SQL*Net more data to client' ela= 5 driver id=1297371904 #bytes=2001 p3=0 obj#=98331 tim=6713013967
WAIT #278: nam='SQL*Net more data to client' ela= 5 driver id=1297371904 #bytes=2008 p3=0 obj#=98331 tim=6713014042
FETCH #278:c=0,e=43,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=6713014057
*** 2008-10-27 14:53:37.025
WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6720723510
STAT #279 id=1 cnt=1 pid=0 pos=1 obj=98908 op='TABLE ACCESS BY INDEX ROWID SPMNPLAN (cr=3 pr=0 pw=0 time=25 us)'
STAT #279 id=2 cnt=1 pid=1 pos=1 obj=98909 op='INDEX UNIQUE SCAN SPMNPLAN0 (cr=2 pr=0 pw=0 time=13 us)'


Обратите внимание на строку вначале *** 2008-10-27 14:53:29.306 и в конце *** 2008-10-27 14:53:37.025. - это почти 8 секунд. если подсчитать все e и ela, то 8 сек. никак не выходит. однако, можно обратить внимание на вот это:
Code:

FETCH #278:c=0,e=43,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=6713014057
*** 2008-10-27 14:53:37.025
WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=98331 tim=6720723510

Если судить по tim, то прошло 7.5 секунд, однако если судить по ela - то 2 микросекунды.

Собсно вопрос - как это понять? куда ушли все 7.5 секунд? на событие ожидание SQL*Net message from client или на что-то еще, что не учитывает оракел?

заранее спасибо
Back to top
View user's profile Send private message
Display posts from previous:   
This forum is locked: you cannot post, reply to, or edit topics.   This topic is locked: you cannot edit posts or make replies.    oracledba.ru Forum Index -> OraSRP All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum


Powered by phpBB © 2001, 2005 phpBB Group