Saturday, August 20, 2011

Excessive waited 'SQL*Net message from client' - when query V$LOCK

Someone informed me. She queried V$LOCK and took a long time. This is Oracle Database 11gR2 RAC. This used V$LOCK to check Blocking Locks with nagios and It got timeout.
SQL> select INST_ID, SID, TYPE, ID1, ID2, LMODE, REQUEST, CTIME, BLOCK from gv$lock where (ID1,ID2,TYPE) in (select ID1,ID2,TYPE from gv$lock where request>0) ORDER BY id1, request;

no rows selected

Elapsed: 00:00:57.14
So, I changed to use V$SESSION
SQL> select INST_ID, SID,BLOCKING_INSTANCE, BLOCKING_SESSION from gv$session where BLOCKING_SESSION is not null;

no rows selected

Elapsed: 00:00:00.02
I didn't write about what SQL statement be better. I was just curious about V$LOCK. what wrong?
So, I traced session with events 10046 (ALTER SESSION SET EVENTS '10046 trace name context forever, level 12'):

CASE 1: SELECT * FROM V$LOCK
SQL> SELECT * FROM V$LOCK;
.
.
.
859 rows selected.

Elapsed: 00:00:54.45
In trace file:
PARSING IN CURSOR #47629932173200 len=20 dep=0 uid=0 oct=3 lid=0 tim=1313835279273571 hv=901831827 ad='c21fd5348' sqlid='0vduu38uw1r4m'
SELECT * FROM V$LOCK
END OF STMT
PARSE #47629932173200:c=5000,e=5177,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=554400005,tim=1313835279273570
EXEC #47629932173200:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=554400005,tim=1313835279273693
WAIT #47629932173200: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835279273723
FETCH #47629932173200:c=76988,e=77563,p=0,cr=0,cu=3,mis=0,r=1,dep=0,og=1,plh=554400005,tim=1313835279351309
WAIT #47629932173200: nam='SQL*Net message from client' ela= 224 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835279351626
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835279351758

*** 2011-08-20 17:14:41.648
FETCH #47629932173200:c=2289652,e=2296395,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835281648052
WAIT #47629932173200: nam='SQL*Net message from client' ela= 480 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835281649099
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835281672706

*** 2011-08-20 17:14:44.013
FETCH #47629932173200:c=2360641,e=2364217,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835284013343
WAIT #47629932173200: nam='SQL*Net message from client' ela= 471 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835284013887
WAIT #47629932173200: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835284050108

*** 2011-08-20 17:14:48.473
FETCH #47629932173200:c=4452323,e=4459119,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835288473025
WAIT #47629932173200: nam='SQL*Net message from client' ela= 416 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835288473518
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835288497355

*** 2011-08-20 17:14:50.804
FETCH #47629932173200:c=2322647,e=2330806,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835290804346
WAIT #47629932173200: nam='SQL*Net message from client' ela= 498 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835290804930
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835290816770

*** 2011-08-20 17:14:53.194
FETCH #47629932173200:c=2387637,e=2389109,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835293194065
WAIT #47629932173200: nam='SQL*Net message from client' ela= 448 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835293194598

*** 2011-08-20 17:14:55.225
WAIT #47629932173200: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835295225888

*** 2011-08-20 17:14:57.619
FETCH #47629932173200:c=4419328,e=4424683,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835297619305
WAIT #47629932173200: nam='SQL*Net message from client' ela= 520 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835297619902
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835297655518

*** 2011-08-20 17:14:59.954
FETCH #47629932173200:c=2331646,e=2334055,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835299953994
WAIT #47629932173200: nam='SQL*Net message from client' ela= 455 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835299954524
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835299966515

*** 2011-08-20 17:15:04.361
FETCH #47629932173200:c=4404330,e=4406925,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835304361470
WAIT #47629932173200: nam='SQL*Net message from client' ela= 479 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835304362041
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835304385925

*** 2011-08-20 17:15:06.668
FETCH #47629932173200:c=2305650,e=2306045,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835306668142
WAIT #47629932173200: nam='SQL*Net message from client' ela= 534 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835306668766
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835306680590

*** 2011-08-20 17:15:11.111
FETCH #47629932173200:c=4439325,e=4442211,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835311110999
WAIT #47629932173200: nam='SQL*Net message from client' ela= 437 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835311111521
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835311123339

*** 2011-08-20 17:15:13.346
FETCH #47629932173200:c=2231661,e=2235394,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835313346938
WAIT #47629932173200: nam='SQL*Net message from client' ela= 477 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835313347500
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835313359340

*** 2011-08-20 17:15:15.716
FETCH #47629932173200:c=2365640,e=2369004,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835315716524
WAIT #47629932173200: nam='SQL*Net message from client' ela= 452 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835315717055
WAIT #47629932173200: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835315729001

*** 2011-08-20 17:15:18.032
FETCH #47629932173200:c=2311649,e=2315041,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835318032118
WAIT #47629932173200: nam='SQL*Net message from client' ela= 453 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835318032657

*** 2011-08-20 17:15:20.086
WAIT #47629932173200: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835320086008
FETCH #47629932173200:c=2242659,e=2243320,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835320276002
WAIT #47629932173200: nam='SQL*Net message from client' ela= 451 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835320276518
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835320276555
FETCH #47629932173200:c=3999,e=3553,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835320280095
WAIT #47629932173200: nam='SQL*Net message from client' ela= 368 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835320280490
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835320280642
FETCH #47629932173200:c=5000,e=4703,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835320285210
WAIT #47629932173200: nam='SQL*Net message from client' ela= 355 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835320285594
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835320285648

*** 2011-08-20 17:15:22.308
FETCH #47629932173200:c=2021692,e=2022498,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322308109
WAIT #47629932173200: nam='SQL*Net message from client' ela= 520 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322308729
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322308771
FETCH #47629932173200:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322308811
WAIT #47629932173200: nam='SQL*Net message from client' ela= 389 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322309220
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322309243
FETCH #47629932173200:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322309269
WAIT #47629932173200: nam='SQL*Net message from client' ela= 379 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322309687
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322309711
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322309738
WAIT #47629932173200: nam='SQL*Net message from client' ela= 393 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322310151
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322310175
FETCH #47629932173200:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322310201
WAIT #47629932173200: nam='SQL*Net message from client' ela= 367 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322310587
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322310611
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322310637
WAIT #47629932173200: nam='SQL*Net message from client' ela= 1408 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322312066
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322312098
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322312124
WAIT #47629932173200: nam='SQL*Net message from client' ela= 370 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322312513
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322312537
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322312563
WAIT #47629932173200: nam='SQL*Net message from client' ela= 380 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322312962
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322312988
FETCH #47629932173200:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322313014
WAIT #47629932173200: nam='SQL*Net message from client' ela= 371 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322313404
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322313427
FETCH #47629932173200:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322313453
WAIT #47629932173200: nam='SQL*Net message from client' ela= 378 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322313850
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322313873
FETCH #47629932173200:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322313898
WAIT #47629932173200: nam='SQL*Net message from client' ela= 347 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322314264
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322314287
FETCH #47629932173200:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322314312
WAIT #47629932173200: nam='SQL*Net message from client' ela= 367 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322314698
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322314725
FETCH #47629932173200:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322314751
WAIT #47629932173200: nam='SQL*Net message from client' ela= 373 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322315143
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322315167
FETCH #47629932173200:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322315192
WAIT #47629932173200: nam='SQL*Net message from client' ela= 386 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322315597
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322315627
FETCH #47629932173200:c=1000,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322315655
WAIT #47629932173200: nam='SQL*Net message from client' ela= 366 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322316043
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322316066
FETCH #47629932173200:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322316091
WAIT #47629932173200: nam='SQL*Net message from client' ela= 366 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322316476
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322316499
FETCH #47629932173200:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322316524
WAIT #47629932173200: nam='SQL*Net message from client' ela= 377 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322316920
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322316946
FETCH #47629932173200:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322316972
WAIT #47629932173200: nam='SQL*Net message from client' ela= 701 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322317692
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322317753
FETCH #47629932173200:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322317784
WAIT #47629932173200: nam='SQL*Net message from client' ela= 580 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322318397
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322318427
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322318454
WAIT #47629932173200: nam='SQL*Net message from client' ela= 597 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322319071
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322319103
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322319130
WAIT #47629932173200: nam='SQL*Net message from client' ela= 577 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322319727
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322319752
FETCH #47629932173200:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322319778
WAIT #47629932173200: nam='SQL*Net message from client' ela= 391 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322320188
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322320214
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322320241
WAIT #47629932173200: nam='SQL*Net message from client' ela= 411 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322320672
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322320705
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322320734
WAIT #47629932173200: nam='SQL*Net message from client' ela= 420 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322321173
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322321202
FETCH #47629932173200:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322321231
WAIT #47629932173200: nam='SQL*Net message from client' ela= 384 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322321635
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322321662
FETCH #47629932173200:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322321696
WAIT #47629932173200: nam='SQL*Net message from client' ela= 390 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322322120
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322322148
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322322176
WAIT #47629932173200: nam='SQL*Net message from client' ela= 401 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322322596
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322322627
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322322656
WAIT #47629932173200: nam='SQL*Net message from client' ela= 374 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322323057
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322323086
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322323114
WAIT #47629932173200: nam='SQL*Net message from client' ela= 390 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322323523
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322323552
FETCH #47629932173200:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322323581
WAIT #47629932173200: nam='SQL*Net message from client' ela= 476 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322324077
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322324102
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322324128
WAIT #47629932173200: nam='SQL*Net message from client' ela= 400 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322324547
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322324577
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322324605
WAIT #47629932173200: nam='SQL*Net message from client' ela= 400 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322325027
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322325059
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322325087
WAIT #47629932173200: nam='SQL*Net message from client' ela= 411 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322325517
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322325544
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322325571
WAIT #47629932173200: nam='SQL*Net message from client' ela= 435 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322326025
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322326055
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322326083
WAIT #47629932173200: nam='SQL*Net message from client' ela= 419 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322326521
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322326550
FETCH #47629932173200:c=108983,e=108208,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835322434750
WAIT #47629932173200: nam='SQL*Net message from client' ela= 473 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322435285
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835322482605

*** 2011-08-20 17:15:24.669
FETCH #47629932173200:c=2223662,e=2233925,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835324669231
WAIT #47629932173200: nam='SQL*Net message from client' ela= 430 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835324669748
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835324670244
FETCH #47629932173200:c=2000,e=2918,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835324672707
WAIT #47629932173200: nam='SQL*Net message from client' ela= 366 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835324673102
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835324673147
FETCH #47629932173200:c=141978,e=144541,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835324817657
WAIT #47629932173200: nam='SQL*Net message from client' ela= 461 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835324818215
WAIT #47629932173200: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835324843272

*** 2011-08-20 17:15:29.311
FETCH #47629932173200:c=4477319,e=4493394,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835329311636
WAIT #47629932173200: nam='SQL*Net message from client' ela= 504 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835329312227
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835329324389

*** 2011-08-20 17:15:31.626
FETCH #47629932173200:c=2311648,e=2314492,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=554400005,tim=1313835331626739
WAIT #47629932173200: nam='SQL*Net message from client' ela= 502 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835331627312
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835331639171

*** 2011-08-20 17:15:33.713
FETCH #47629932173200:c=2084683,e=2085710,p=0,cr=0,cu=0,mis=0,r=3,dep=0,og=1,plh=554400005,tim=1313835333713057
STAT #47629932173200 id=1 cnt=859 pid=0 pos=1 obj=0 op='HASH JOIN (cr=0 pr=0 pw=0 time=3447076 us cost=1 size=156 card=1)'
STAT #47629932173200 id=2 cnt=860 pid=1 pos=1 obj=4294951276 op='VIEW GV$_LOCK (cr=0 pr=0 pw=0 time=4629 us cost=0 size=760 card=10)'
STAT #47629932173200 id=3 cnt=860 pid=2 pos=1 obj=0 op='UNION-ALL (cr=0 pr=0 pw=0 time=4627 us)'
STAT #47629932173200 id=4 cnt=785 pid=3 pos=1 obj=0 op='FILTER (cr=0 pr=0 pw=0 time=4210 us)'
STAT #47629932173200 id=5 cnt=785 pid=4 pos=1 obj=4294951275 op='VIEW GV$_LOCK1 (cr=0 pr=0 pw=0 time=3982 us cost=0 size=152 card=2)'
STAT #47629932173200 id=6 cnt=785 pid=5 pos=1 obj=0 op='UNION-ALL (cr=0 pr=0 pw=0 time=3869 us)'
STAT #47629932173200 id=7 cnt=0 pid=6 pos=1 obj=0 op='FIXED TABLE FULL X$KDNSSF (cr=0 pr=0 pw=0 time=2402 us cost=0 size=102 card=1)'
STAT #47629932173200 id=8 cnt=785 pid=6 pos=2 obj=0 op='FIXED TABLE FULL X$KSQEQ (cr=0 pr=0 pw=0 time=1128 us cost=0 size=102 card=1)'
STAT #47629932173200 id=9 cnt=72 pid=3 pos=2 obj=0 op='FIXED TABLE FULL X$KTADM (cr=0 pr=0 pw=0 time=6638 us cost=0 size=102 card=1)'
STAT #47629932173200 id=10 cnt=0 pid=3 pos=3 obj=0 op='FIXED TABLE FULL X$KTATRFIL (cr=0 pr=0 pw=0 time=10 us cost=0 size=102 card=1)'
STAT #47629932173200 id=11 cnt=0 pid=3 pos=4 obj=0 op='FIXED TABLE FULL X$KTATRFSL (cr=0 pr=0 pw=0 time=8 us cost=0 size=102 card=1)'
STAT #47629932173200 id=12 cnt=0 pid=3 pos=5 obj=0 op='FIXED TABLE FULL X$KTATL (cr=0 pr=0 pw=0 time=12 us cost=0 size=102 card=1)'
STAT #47629932173200 id=13 cnt=0 pid=3 pos=6 obj=0 op='FIXED TABLE FULL X$KTSTUSC (cr=0 pr=0 pw=0 time=20 us cost=0 size=102 card=1)'
STAT #47629932173200 id=14 cnt=0 pid=3 pos=7 obj=0 op='FIXED TABLE FULL X$KTSTUSS (cr=0 pr=0 pw=0 time=14 us cost=0 size=102 card=1)'
STAT #47629932173200 id=15 cnt=0 pid=3 pos=8 obj=0 op='FIXED TABLE FULL X$KTSTUSG (cr=0 pr=0 pw=0 time=12 us cost=0 size=102 card=1)'
STAT #47629932173200 id=16 cnt=3 pid=3 pos=9 obj=0 op='FIXED TABLE FULL X$KTCXB (cr=0 pr=0 pw=0 time=3248 us cost=0 size=102 card=1)'
STAT #47629932173200 id=17 cnt=104219136 pid=1 pos=2 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=31937820 us cost=0 size=8000 card=100)'
STAT #47629932173200 id=18 cnt=4536 pid=17 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=7944 us cost=0 size=32 card=1)'
STAT #47629932173200 id=19 cnt=104219136 pid=17 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=16110270 us cost=0 size=4800 card=100)'
STAT #47629932173200 id=20 cnt=22976 pid=19 pos=1 obj=0 op='FIXED TABLE FULL X$KSQRS (cr=0 pr=0 pw=0 time=13789 us cost=0 size=4800 card=100)'
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message from client 59 160.06 160.08
SQL*Net message to client 59 0.00 0.00

********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 59 54.32 54.40 0 0 3 859
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 61 54.32 54.41 0 0 3 859
I found excessive time waited with events 'SQL*Net message from client' , then changed SQL

Case 2: SELECT /*+ PARALLEL */ * FROM V$LOCK
SQL> SELECT /*+ PARALLEL */ * FROM V$LOCK;
.
.
.
777 rows selected.

Elapsed: 00:00:00.11
In trace file:
PARSING IN CURSOR #47629932173200 len=36 dep=0 uid=0 oct=3 lid=0 tim=1313835672181268 hv=293609904 ad='c2f9eff78' sqlid='1ca4fz88s08dh'
SELECT /*+ PARALLEL */ * FROM V$LOCK
END OF STMT
PARSE #47629932173200:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1453144240,tim=1313835672181267
EXEC #47629932173200:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1453144240,tim=1313835672181370
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672181397
FETCH #47629932173200:c=62991,e=62788,p=0,cr=0,cu=1,mis=0,r=1,dep=0,og=1,plh=1453144240,tim=1313835672244202
WAIT #47629932173200: nam='SQL*Net message from client' ela= 234 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672244596
WAIT #47629932173200: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672244658
FETCH #47629932173200:c=0,e=87,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672244714
WAIT #47629932173200: nam='SQL*Net message from client' ela= 343 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672245538
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672245562
FETCH #47629932173200:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672245615
WAIT #47629932173200: nam='SQL*Net message from client' ela= 294 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672245924
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672245947
FETCH #47629932173200:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672245977
WAIT #47629932173200: nam='SQL*Net message from client' ela= 287 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672246278
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672246297
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672246326
WAIT #47629932173200: nam='SQL*Net message from client' ela= 290 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672246630
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672246648
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672246676
WAIT #47629932173200: nam='SQL*Net message from client' ela= 288 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672246978
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672246998
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672247026
WAIT #47629932173200: nam='SQL*Net message from client' ela= 288 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672247328
WAIT #47629932173200: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672247345
FETCH #47629932173200:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672247377
WAIT #47629932173200: nam='SQL*Net message from client' ela= 294 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672247684
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672247702
FETCH #47629932173200:c=1000,e=37,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672247733
WAIT #47629932173200: nam='SQL*Net message from client' ela= 308 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672248055
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672248076
FETCH #47629932173200:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672248106
WAIT #47629932173200: nam='SQL*Net message from client' ela= 286 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672248405
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672248441
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672248470
WAIT #47629932173200: nam='SQL*Net message from client' ela= 298 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672248782
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672248803
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672248832
WAIT #47629932173200: nam='SQL*Net message from client' ela= 294 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672249140
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672249158
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672249187
WAIT #47629932173200: nam='SQL*Net message from client' ela= 302 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672249502
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672249520
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672249548
WAIT #47629932173200: nam='SQL*Net message from client' ela= 297 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672249859
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672249881
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672249909
WAIT #47629932173200: nam='SQL*Net message from client' ela= 296 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672250219
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672250237
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672250266
WAIT #47629932173200: nam='SQL*Net message from client' ela= 302 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672250581
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672250600
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672250628
WAIT #47629932173200: nam='SQL*Net message from client' ela= 293 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672250934
WAIT #47629932173200: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672250953
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672250982
WAIT #47629932173200: nam='SQL*Net message from client' ela= 283 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672251279
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672251297
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672251325
WAIT #47629932173200: nam='SQL*Net message from client' ela= 297 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672251635
WAIT #47629932173200: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672251653
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672251682
WAIT #47629932173200: nam='SQL*Net message from client' ela= 306 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672252002
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672252023
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672252052
WAIT #47629932173200: nam='SQL*Net message from client' ela= 280 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672252345
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672252363
FETCH #47629932173200:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672252402
WAIT #47629932173200: nam='SQL*Net message from client' ela= 284 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672252700
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672252719
FETCH #47629932173200:c=1000,e=38,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672252750
WAIT #47629932173200: nam='SQL*Net message from client' ela= 304 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672253068
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672253087
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672253116
WAIT #47629932173200: nam='SQL*Net message from client' ela= 290 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672253419
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672253437
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672253465
WAIT #47629932173200: nam='SQL*Net message from client' ela= 290 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672253768
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672253787
FETCH #47629932173200:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672253827
WAIT #47629932173200: nam='SQL*Net message from client' ela= 309 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672254164
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672254189
FETCH #47629932173200:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672254218
WAIT #47629932173200: nam='SQL*Net message from client' ela= 289 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672254522
WAIT #47629932173200: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672254540
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672254569
WAIT #47629932173200: nam='SQL*Net message from client' ela= 316 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672254899
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672254919
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672254947
WAIT #47629932173200: nam='SQL*Net message from client' ela= 291 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672255252
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672255270
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672255299
WAIT #47629932173200: nam='SQL*Net message from client' ela= 288 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672255601
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672255619
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672255647
WAIT #47629932173200: nam='SQL*Net message from client' ela= 295 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672255956
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672255978
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672256007
WAIT #47629932173200: nam='SQL*Net message from client' ela= 282 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672256302
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672256321
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672256349
WAIT #47629932173200: nam='SQL*Net message from client' ela= 286 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672256656
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672256675
FETCH #47629932173200:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672256702
WAIT #47629932173200: nam='SQL*Net message from client' ela= 309 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672257025
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672257044
FETCH #47629932173200:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672257073
WAIT #47629932173200: nam='SQL*Net message from client' ela= 284 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672257370
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672257392
FETCH #47629932173200:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672257420
WAIT #47629932173200: nam='SQL*Net message from client' ela= 285 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672257718
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672257739
FETCH #47629932173200:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672257776
WAIT #47629932173200: nam='SQL*Net message from client' ela= 298 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672258088
WAIT #47629932173200: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672258186
FETCH #47629932173200:c=1000,e=1210,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672259313
WAIT #47629932173200: nam='SQL*Net message from client' ela= 307 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672259639
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672259657
FETCH #47629932173200:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672259673
WAIT #47629932173200: nam='SQL*Net message from client' ela= 284 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672259970
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672259990
FETCH #47629932173200:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672260005
WAIT #47629932173200: nam='SQL*Net message from client' ela= 291 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672260309
WAIT #47629932173200: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672260325
FETCH #47629932173200:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672260341
WAIT #47629932173200: nam='SQL*Net message from client' ela= 305 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672260658
WAIT #47629932173200: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672260673
FETCH #47629932173200:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672260689
WAIT #47629932173200: nam='SQL*Net message from client' ela= 299 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672261000
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672261017
FETCH #47629932173200:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672261034
WAIT #47629932173200: nam='SQL*Net message from client' ela= 282 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672261329
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672261345
FETCH #47629932173200:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672261360
WAIT #47629932173200: nam='SQL*Net message from client' ela= 277 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672261654
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672261670
FETCH #47629932173200:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672261692
WAIT #47629932173200: nam='SQL*Net message from client' ela= 300 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672262005
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672262025
FETCH #47629932173200:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672262040
WAIT #47629932173200: nam='SQL*Net message from client' ela= 300 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672262353
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672262369
FETCH #47629932173200:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672262388
WAIT #47629932173200: nam='SQL*Net message from client' ela= 285 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672262686
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672262702
FETCH #47629932173200:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672262717
WAIT #47629932173200: nam='SQL*Net message from client' ela= 313 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672263045
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672263062
FETCH #47629932173200:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672263077
WAIT #47629932173200: nam='SQL*Net message from client' ela= 292 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672263382
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672263398
FETCH #47629932173200:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672263414
WAIT #47629932173200: nam='SQL*Net message from client' ela= 292 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672263718
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672263736
FETCH #47629932173200:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672263752
WAIT #47629932173200: nam='SQL*Net message from client' ela= 308 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672264072
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672264091
FETCH #47629932173200:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=1453144240,tim=1313835672264106
WAIT #47629932173200: nam='SQL*Net message from client' ela= 285 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672264404
WAIT #47629932173200: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1313835672264420
FETCH #47629932173200:c=14998,e=15096,p=0,cr=0,cu=0,mis=0,r=11,dep=0,og=1,plh=1453144240,tim=1313835672279511
STAT #47629932173200 id=1 cnt=777 pid=0 pos=1 obj=0 op='HASH JOIN (cr=0 pr=0 pw=0 time=63691 us cost=1 size=156 card=1)'
STAT #47629932173200 id=2 cnt=777 pid=1 pos=1 obj=0 op='HASH JOIN (cr=0 pr=0 pw=0 time=7199 us cost=1 size=108 card=1)'
STAT #47629932173200 id=3 cnt=4536 pid=2 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=1778 us cost=0 size=32 card=1)'
STAT #47629932173200 id=4 cnt=778 pid=2 pos=2 obj=4294951276 op='VIEW GV$_LOCK (cr=0 pr=0 pw=0 time=4864 us cost=0 size=760 card=10)'
STAT #47629932173200 id=5 cnt=778 pid=4 pos=1 obj=0 op='UNION-ALL (cr=0 pr=0 pw=0 time=4752 us)'
STAT #47629932173200 id=6 cnt=777 pid=5 pos=1 obj=0 op='FILTER (cr=0 pr=0 pw=0 time=4413 us)'
STAT #47629932173200 id=7 cnt=777 pid=6 pos=1 obj=4294951275 op='VIEW GV$_LOCK1 (cr=0 pr=0 pw=0 time=4412 us cost=0 size=152 card=2)'
STAT #47629932173200 id=8 cnt=777 pid=7 pos=1 obj=0 op='UNION-ALL (cr=0 pr=0 pw=0 time=4188 us)'
STAT #47629932173200 id=9 cnt=0 pid=8 pos=1 obj=0 op='FIXED TABLE FULL X$KDNSSF (cr=0 pr=0 pw=0 time=2292 us cost=0 size=102 card=1)'
STAT #47629932173200 id=10 cnt=777 pid=8 pos=2 obj=0 op='FIXED TABLE FULL X$KSQEQ (cr=0 pr=0 pw=0 time=1340 us cost=0 size=102 card=1)'
STAT #47629932173200 id=11 cnt=0 pid=5 pos=2 obj=0 op='FIXED TABLE FULL X$KTADM (cr=0 pr=0 pw=0 time=23694 us cost=0 size=102 card=1)'
STAT #47629932173200 id=12 cnt=0 pid=5 pos=3 obj=0 op='FIXED TABLE FULL X$KTATRFIL (cr=0 pr=0 pw=0 time=12 us cost=0 size=102 card=1)'
STAT #47629932173200 id=13 cnt=0 pid=5 pos=4 obj=0 op='FIXED TABLE FULL X$KTATRFSL (cr=0 pr=0 pw=0 time=8 us cost=0 size=102 card=1)'
STAT #47629932173200 id=14 cnt=0 pid=5 pos=5 obj=0 op='FIXED TABLE FULL X$KTATL (cr=0 pr=0 pw=0 time=11 us cost=0 size=102 card=1)'
STAT #47629932173200 id=15 cnt=0 pid=5 pos=6 obj=0 op='FIXED TABLE FULL X$KTSTUSC (cr=0 pr=0 pw=0 time=19 us cost=0 size=102 card=1)'
STAT #47629932173200 id=16 cnt=0 pid=5 pos=7 obj=0 op='FIXED TABLE FULL X$KTSTUSS (cr=0 pr=0 pw=0 time=14 us cost=0 size=102 card=1)'
STAT #47629932173200 id=17 cnt=0 pid=5 pos=8 obj=0 op='FIXED TABLE FULL X$KTSTUSG (cr=0 pr=0 pw=0 time=12 us cost=0 size=102 card=1)'
STAT #47629932173200 id=18 cnt=1 pid=5 pos=9 obj=0 op='FIXED TABLE FULL X$KTCXB (cr=0 pr=0 pw=0 time=8269 us cost=0 size=102 card=1)'
STAT #47629932173200 id=19 cnt=22976 pid=1 pos=2 obj=0 op='FIXED TABLE FULL X$KSQRS (cr=0 pr=0 pw=0 time=9577 us cost=0 size=4800 card=100)'

It's faster than case 1!!!
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message from client 53 17.28 17.30
SQL*Net message to client 53 0.00 0.00

********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 53 0.08 0.08 0 0 1 777
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 55 0.08 0.08 0 0 1 777
But I'm not sure, why CASE 1 took excessive 'SQL*Net message from client' waited. But I just reduced it by using PARALLEL hint.
SQL> select /*+ PARALLEL */ INST_ID, SID, TYPE, ID1, ID2, LMODE, REQUEST, CTIME, BLOCK from gv$lock where (ID1,ID2,TYPE) in (select ID1,ID2,TYPE from gv$lock where request>0) ORDER BY id1, request;

no rows selected

Elapsed: 00:00:00.23
Idea to check Blocking Locks: You can query DBA_BLOCKERS & use DBA_LOCK also.

4 comments:

Marcus said...

'SQL*Net message from client' is not the problem here. The aggregated data (from TKPROF?) seems to be wrong for CASE 1.

The sum of the wait time for this event is 0.0259s for CASE 1 (not 160.06s) and 0.0153s in CASE 2. The total and the difference do not matter compared to the 54.32s and 0.08s for the FETCH operations.

Looking at the STAT lines from both traces: There is an addtional expensive MERGE JOIN CARTESIAN in case 1 which is not there in case 2, which probably explains the differences.

You might want to:

-run your trace files through e.g. OraSRP instead of TKPROF
-look at the execution plan with execution statistics generated through dbms_xplan to see what exactly is happening here
-generally want to fetch more than just 15 records at once

Surachart Opun said...

Thank You so much. You helped me figure out. I fixed this by change Joining.


SQL> select /*+ ordered */ s.inst_id,l.laddr,l.kaddr,s.ksusenum,r.ksqrsidt,r.ksqrsid1, r.ksqrsid2,l.lmode,l.request,l.ctime,decode(l.lmode,0,0,l.block) from v$_lock l, x$ksuse s, x$ksqrs r where l.saddr=s.addr and concat(USERENV('Instance'),l.raddr)=concat(r.inst_id,r.addr) and s.inst_id = USERENV('Instance')
.
.
.
807 rows selected.

Elapsed: 00:00:00.09

Andrejs Vorobjovs said...

With this v$LOCK SQL I get 2 MERGE JOINS in RAC and non RAC and execution time is about 5 minutes and TEMP tablespace extends to 7GB.
With /*+ ordered */ plan changes dramatically, execution is near to 0.

set timing on

SELECT l1.id1 "id1",
l1.id2 "id2",
l2.id1 "id3",
l2.id2 "id4",
l1.sid "sid1",
l2.sid "sid2",
l1.TYPE "type1",
l2.TYPE "type2",
l1.request "request1",
l2.request "request2",
l1.lmode "mode1",
l2.lmode "mode2",
l1.ctime "ctime1",
l2.ctime "ctime2"
FROM v$lock l1, v$lock l2
WHERE l1.BLOCK = 1
AND l2.request > 0
AND l1.id1 = l2.id1
AND l2.id2 = l2.id2;

ORA-01652: unable to extend temp segment by 128 in tablespace TEMP

Elapsed: 00:00:48.25

Surachart Opun said...

not sure .. your sql
WHERE l1.BLOCK = 1
AND l2.request > 0
AND l1.id1 = l2.id1
AND l2.id2 = l2.id2;


... AND l2.id2 = l2.id2;

I surprise with Execution plan on 11g (V$LOCK). MERGE JOIN CARTESIAN