10046 trace confused
KramerApr 24 2012 — edited Apr 26 2012=====================
PARSING IN CURSOR #2 len=657 dep=0 uid=358 oct=3 lid=358 tim=1182070262728 hv=2222393979 ad='de83b938'
SELECT v_user.pm_logon_id,v_user.home_department_c, v_user.ic_n, v_user.staff_n, v_user.roster_scheme_n, v_user.meal_pref_c, v_user.work_department_c,v_user.
meal_payment_i, v_user.end_dt, v_user.ic_n as staff_work_ic_n
FROM v_ccs_op_user v_user
WHERE (v_user.end_dt IS NULL OR (TRUNC(v_user.end_dt, 'dd')>=TRUNC(to_date('2012-04-05 00:00:00','YYYY-MM-DD HH24:MI:SS'), 'dd'))) AND TRUNC(v_user.start_dt,
'dd')<=TRUNC(to_date('2012-04-05 00:00:00','YYYY-MM-DD HH24:MI:SS'), 'dd')
AND (v_user.HOME_DEPARTMENT_C IN (SELECT d.department_c FROM department d WHERE d.DIVISION_C='C') OR v_user.home_department_c IN ('Q'))
ORDER BY v_user.end_dt, v_user.start_dt ASC
END OF STMT
PARSE #2:c=0,e=4764,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1182070262719
BINDS #2:
EXEC #2:c=0,e=255,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1182070263378
WAIT #2: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182070263514
*** 2012-04-24 15:41:49.623
FETCH #2:c=306350000,e=299174653,p=0,cr=22298,cu=0,mis=0,r=1,dep=0,og=1,tim=1182369438322
WAIT #2: nam='SQL*Net message from client' ela= 1454 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369440799
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369441012
FETCH #2:c=0,e=293,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=1182369441265
WAIT #2: nam='SQL*Net message from client' ela= 7437 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369448858
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369449007
FETCH #2:c=0,e=283,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=1182369449257
WAIT #2: nam='SQL*Net message from client' ela= 6701 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369456082
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369456222
-----------
I was using 10046 to trace one SQL. I used command "tail -f" to monitor the raw trace file while running the SQL. During the monitoring, I found that most of the time was spend at this step FETCH #2:c=306350000,e=299174653,p=0,cr=22298,cu=0,mis=0,r=1,dep=0,og=1,tim=1182369438322. It is high lightened on the above output.
My question is
1. what does e=299174653 mean? is it meaning the elapsed time for the fetch step or the previous step which is EXEC ?
2. if the e=299174653 means elapsed time for the current fetch step, then why this fetch cost so much of time? what is the different between this first fetch and other fetches?
3. what is the exec and fetch means here? I thought the fetch is merely reading data from buffer or data file, and exec is some other actions. but seems my understanding is not correct.
4. is there any docs or something can help to understand the trace file?
thank you very much in advance :)
Edited by: Kramer on 2012-4-24 下午7:51