An Oracle Call Tracer For Windows(32)
[中文]
Author:
fuyuncat
Source:
www.HelloDBA.com
Date:
2010-05-28 08:23:50
Share to
Warning: This tool is a beta version, it may cause unexpected error. Never play it in any crytical system!
Base on the my windows threads top CPU usage tool, TopShow, I built another tool, OraTracer, a simple oracle call tracer. You can use this tool to set multiple trace points for known oracle internal calls. And it will log the calling with detected arguments, call stacks corresponding to the trace point setting. The trace could be set in process level or thread level.
Example 1:
Capture executing SQLs in whole oracle db instance.First, set below trace points in the file "TracePoints.txt", which locate at the same folder of the executable file.
SQL代码
- _opiprs 6*1
- _rpisplu 6*2
- _kprbprs 6
The number following the call name that splited by a space character is the argument number. If it pluses with "*<num>", means you want treat the DWORD values as a pointer, and the number following "*" is the pointer deep. For the 1st trace point, the call name is "_opiprs", and argument number is 6, with 1 as pointer deep.
Note: "#" is comment flag.Then, Select the ORACLE.EXE in the process, without any thread be selected:
Finally, click the "Trace" button. If those trace point called in Oracle, you will get the trace log in the log window.
SQL代码
- ...
- [2010-5-28 3:53:23.426]User call: _rpisplu (TID: 5276)
- [Args(6)]:
- 6
- 0
- 0
- "select privilege#,level from sysauth$ connect by grantee#=prior privilege# and privilege#>0 start with grantee#=:1 and privilege#>0"
- 0x84(=>NULL)
- 0
- [2010-5-28 3:53:23.442]User call: _rpisplu (TID: 5276)
- [Args(6)]:
- 6
- 0
- 0
- "alter session set NLS_LANGUAGE='AMERICAN' NLS_TERRITORY='AMERICA' NLS_CURRENCY='$' NLS_ISO_CURRENCY='AMERICA' NLS_NUMERIC_CHARACTERS='.,' NLS_DATE_FORMAT='DD-MON-RR' NLS_DATE_LANGUAGE='AMERICAN' NLS_SORT='BINARY'"
- 0xd4(=>NULL)
- 0
- [2010-5-28 3:53:23.473]User call: _opiprs (TID: 5276)
- [Args(6)]:
- 0x70cce00(=>0x4000000)
- "alter session set NLS_LANGUAGE='AMERICAN' NLS_TERRITORY='AMERICA' NLS_CURRENCY='$' NLS_ISO_CURRENCY='AMERICA' NLS_NUMERIC_CHARACTERS='.,' NLS_DATE_FORMAT='DD-MON-RR' NLS_DATE_LANGUAGE='AMERICAN' NLS_SORT='BINARY'"
- 0xd5(=>NULL)
- 0x4bfe214(=>0x18)
- 0
- 6
- [2010-5-28 3:53:23.504]User call: _rpisplu (TID: 5276)
- [Args(6)]:
- 3
- 0x20(=>NULL)
- 0x20(=>NULL)
- "select sysdate + 1 / (24 * 60) from dual"
- 0x28(=>NULL)
- 1
- [2010-5-28 3:53:23.520]User call: _rpisplu (TID: 5276)
- [Args(6)]:
- 5
- 0x20(=>NULL)
- 0x20(=>NULL)
- "DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN := FALSE; BEGIN EMD_MAINTENANCE.EXECUTE_EM_DBMS_JOB_PROCS(); :mydate := next_date; IF broken THEN :b := 1; ELSE :b := 0; END IF; END; "
- 0xd5(=>NULL)
- 0
- ...
If you want to stop tracing, just click the "Stop" button.
Example 2:
Understanding the SQL execution drived by plan.As we know, the execution plan is in fact to drive the Source Generator to fetch data via specified functions. We trace those functions to help us understanding the executions plan.
Download below tracepoint setting file, rename it to "TracePoints.txt", put it in the same folder of OraTracer.exe:
http://www.HelloDBA.com/Download/TracePoints_ALL_Query_Calls.zipThen, get SPID of the session you want to trace.
SQL代码
- HELLODBA.COM>select distinct spid from v$mystat m, v$session s, v$process p where s.sid=m.sid and s.paddr=p.addr;
- SPID
- ------------
- 11076
Select ORACLE.EXE from the processes list => select the TID number 11076 from the threads list => Click "Trace" button.
And let's execute a SQL in the session we're tracing.
SQL代码
- HELLODBA.COM>select * from demo.t_test1 where owner='DEMO' and object_name like 'T_TEST%';
- OWNER OBJECT_NAME SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE CREATED
- LAST_DDL_TIME TIMESTAMP STATUS T G S
- ------------------------------ ------------------------------ ------------------------------ ---------- -------------- ------------------- -----------
- -------- ------------------- ------------------- ------- - - -
- DEMO T_TEST1 AAA 97819 97819 TABLE 2007-06-07
- 13:48:08 2007-06-07 13:48:08 2007-06-07:13:48:08 VALID N N N
Note: to avoid the recursive calls, you'd better execute the SQL before tracing.
From the log window, we can get the fetch calls be traced.
SQL代码
- [2010-5-28 6:28:29.649]User call: _qertbFetchByRowID (TID: 11076)
- [2010-5-28 6:28:29.711]User call: _qerixtFetch (TID: 11076)
- [2010-5-28 6:28:29.727]User call: _qertbFetchByRowID (TID: 11076)
- [2010-5-28 6:28:29.727]User call: _qerixtFetch (TID: 11076)
You may try to map the calls to the execution plan:
SQL代码
- HELLODBA.COM>select * from demo.t_test1 where owner='DEMO' and object_name like 'T_TEST%';
- Execution Plan
- ----------------------------------------------------------
- Plan hash value: 698582444
- -------------------------------------------------------------------------------------------
- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
- -------------------------------------------------------------------------------------------
- | 0 | SELECT STATEMENT | | 5 | 495 | 4 (0)| 00:00:04 |
- | 1 | TABLE ACCESS BY INDEX ROWID| T_TEST1 | 5 | 495 | 4 (0)| 00:00:04 | ==> _qertbFetchByRowID
- |* 2 | INDEX RANGE SCAN | T_TEST_IDX7 | 5 | | 1 (0)| 00:00:02 | ==> _qerixtFetch
- -------------------------------------------------------------------------------------------
Example 3:
Reading call stacks when specified call be traced.我们这里追踪"_kkeAdjSingTabCard"。设置追踪点：
SQL代码
- _kkeAdjSingTabCard*-1 6
The "*<num>" following the call name is the stack count you want to print, -1 mean no limit.
Then, get SPID of the session you want to trace.
SQL代码
- HELLODBA.COM>select distinct spid from v$mystat m, v$session s, v$process p where s.sid=m.sid and s.paddr=p.addr;
- SPID
- ------------
- 11076
Select ORACLE.EXE from the processes list => select the TID number 11076 from the threads list => Click "Trace" button.
And let's explain plan a SQL in the session we're tracing.
SQL代码
- HELLODBA.COM>explain plan for select /*+full(t)*/ count(*) from demo.t_test2 t;
- Explained.
We can get the call stacks from the log window.
SQL代码
- [2010-5-28 6:51:55.591]User call: _kkeAdjSingTabCard (TID: 11076)
- Call Stacks(-1):
- 0x1460029 (ORACLE.EXE!_kkoitbp+757)
- 0x144c44d (ORACLE.EXE!_kkoijbad+8869)
- 0x1445d8b (ORACLE.EXE!_kkoCopyPreds+851)
- 0x143ee0a (ORACLE.EXE!_kkosta+1694)
- 0x1d17f6c (ORACLE.EXE!__PGOSF443__apaRequestBindCapture+156)
- 0x1d18398 (ORACLE.EXE!_apagcp+388)
- 0x1d1683c (ORACLE.EXE!_apafbr+464)
- 0xea6682 (ORACLE.EXE!_opitcaNcp+1450)
- 0x5b4eb0 (ORACLE.EXE!_kksMinimalTypeCheck+20)
- 0x84d939 (ORACLE.EXE!_rpidrus+429)
- 0x5b8ce8 (ORACLE.EXE!_kksSetNLSHandle+5888)
- 0x87732e (ORACLE.EXE!_kxsReleaseRuntimeLock+1366)
- 0x831815 (ORACLE.EXE!_kkscbt+7237)
- 0x82e3cf (ORACLE.EXE!_kksParseCursor+2099)
- 0x82f1b8 (ORACLE.EXE!_kksxsccompat+148)
- 0x201683e (ORACLE.EXE!_opibrp+1970)
- 0x13cd5ed (ORACLE.EXE!_kpodrd+237)
- 0x13cba7c (ORACLE.EXE!_kpocrs+780)
- 0x85174e (ORACLE.EXE!_opirip+1102)
- 0x60feff90 (oracommon10.dll!_ttcpro+1276)
- 0x850a69 (ORACLE.EXE!_opiodr+1017)
- 0x1221350 (ORACLE.EXE!_opiino3+1092)
- 0x85174e (ORACLE.EXE!_opirip+1102)
- 0x420e58 (ORACLE.EXE!_opidcl+824)
- 0x42164a (ORACLE.EXE!_ksdwri+50)
- 0x401171 (ORACLE.EXE!_ssthrnfy+117)
- 0x401061 (ORACLE.EXE!_opimai_init+97)
- 0x401905 (ORACLE.EXE!_osnsoiint+713)
- 0x7c80b729 (KERNEL32.dll!GetModuleFileNameA+442)
- [Args(6)]:
- 0x81e58d0
- 0x81e5da8
- 0
- 0x40a03000
- 0x8559500
- 0
Download the last version of OraTracer at here:
http://www.HelloDBA.com/Download/OraTracer.zipEnjoy!
--- Fuyuncat ---
