How to find the offending SQL from a trace file
Extracting the SQL statement from a trace file is a two-step process.
First you must find the SQL itself, then you must identify the values of any bind variables that the SQL may be referencing.
The following text assumes that you have located the trace file associated with the reported error.
Locate the line "Current cursor:" (this should be right at the beginning of the "*** Cursor Dump ***" section). Note the number associated with the current cursor. (See the examples below for more details)
If the current cursor number is 0 then no current SQL is available. Under these conditions, the Call Stack Trace displayed near the top of the trace file gives the best indication of what was happening at the time of the error. Normally, Oracle Support Services will need to see this trace file in order to progress the issue.
If the Current cursor number is non-zero, search the remainder of the trace file for the line beginning with "Cursor n" where n is the cursor number just found. From 10.2 and onwards, search for "Cursor#n". On the next line you should see "cursor name:" which will be followed by the SQL statement.
Note: You will quite often be able to locate the SQL by searching for the line "Current SQL statement for this session:". Normally this is displayed near the beginning of the trace file.
If the SQL statement does not reference any bind variables (ie. ":b1", ":b2", etc.) then Step 2 can be ignored.
Step 2: Find values of the bind variables
If the SQL statement does reference bind variables, then following the SQL statement shown in the cursor, you should in most cases be able to locate a section of text associated with each bind variable. Each section of text will begin "bind x:" where x ranges from 0 to n-1 where n is the number of bind variables used in the SQL statement.
There may be a large memory dump between the SQL statement and the binds - it should just be ignored at this stage.
For each bind variable there are a number of attributes listed. The following are the ones we are interested in here:
- dty the datatype. Typical values are:
1 VARCHAR2 or NVARCHAR2
2 NUMBER
8 LONG
11 ROWID
12 DATE
23 RAW
24 LONG RAW
96 CHAR
112 CLOB or NCLOB
113 BLOB
114 BFILE
- mxl the maximum length - ie. the maximum number of bytes occupied by the variable. Eg. dty=2 and mxl=22 denotes a NUMBER(22) column.
- scl the scale (for NUMBER columns)
- pre the precision (for NUMBER columns)
- value the value of the bind variable
Mapping the bind variables from the cursor dump with the bind variables in the SQL statement
is straight-forward: :b1 ~ bind 0
:b2 ~ bind 1
:b3 ~ bind 2
etc.
The binds can also be called :1, :2, etc. or :a1, :a2, etc. the important thing is that the *order* in which they are used in the SQL statement matches the order of the variable dumps.
You should now be able to find the datatype of the bind variable (including length, scale, and precision if applicable) and the value.
In some (rare) cases, there is no "value=..." included in the dump, and then the method described in step 2 cannot be used to identify the values of the bind variables.
In the following we will work through some examples of how to extract the SQL statement from trace files.
IMPORTANT: Replacing bind variables with literals can result in the optimizer choosing a different query path and thus the problem may not reproduce!
Example 1:
You should now be able to find the datatype of the bind variable (including length, scale, and precision if applicable) and the value.
The cursor dump starts with:
******************** Cursor Dump ************************
Current cursor: 2, pgadep: 1
Cursor Dump:
----------------------------------------
so we are looking for cursor 2:
----------------------------------------
Cursor 2 (20139ad0): CURFETCH curiob: 2013bca4
curflg: 7 curpar: 20139ab0
curusr: 0 curses 587a 250c
cursor name: select text from view$ where rowid=:1
child pin: 50a 5b650, child lock: 50a 5a 628,
parent lock: 50a 5a 844
xscflg: 20141466, parent handle: 4f 348490, xscfl2: 400
nxt: 2.0x 0000006c nxt: 1.0x000001d8
Cursor
frame allocation dump:
frm: -------- Comment -------- Size Seg Off
bhp size: 52/560
bind 0: dty=11 mxl=16(16) mal=00 <-這去參考step2找到dty 11所代表的是rowid
scl=00 pre=00 oacflg=18 oacfl2=1 size=16
offset=0
bfp=2013e 9f 4 bln=16 avl=16 flg=05
value= 0000138C .0046.0004 <-這是bind value傳入的值
The current SQL is:
select text from view$ where rowid=:1
and the bind variable translates into:
:1 ~ bind 0 - ROWID (dty=11), value = 0000138C .0046.0004
so we can deduct that the original SQL statement was:
select text from view$ where rowid= 0000138C .0046.0004
Example 2:
The cursor dump starts with:
******************** Cursor Dump ************************
Current cursor: 11, pgadep: 1
Cursor Dump:
----------------------------------------
ie. we should look for cursor 11:
----------------------------------------
Cursor 11 (202cb 9f 0): CURBOUND curiob: 202f 8b04
curflg: dd curpar:
0 curusr: 0 curses 30047c 7c
cursor name: SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME =
:b1 FOR UPDATE
child pin:
0, child lock: 300dc9b4, parent lock: 301730b8
xscflg: 1151421, parent handle: 3025b4dc
bind 0: dty=1 mxl=32(00) mal=00 scl=00 pre=00 oacflg=01
No bind buffers allocated <-表示bind value沒有任何的值
----------------------------------------
The current SQL statement is then:
SELECT LOCKID FROM DBMS_LOCK_ALLOCATED WHERE NAME = :b1 FOR UPDATE
The bind variable :b1 is of type VARCHAR2(32) (dty=1, mxl=32), but no value has been assigned to it at the time of the dump ("No bind buffers allocated").
Example 3:
******************** Cursor Dump ************************
Current cursor: 2, pgadep: 0
Cursor Dump:
----------------------------------------
...
----------------------------------------
Cursor 2 (20140444): CURNULL curiob: 0
curflg: 44 curpar: 0 curusr: 0 curses 701dc 94c
----------------------------------------
In this case there is no SQL being executed at the time of the dump.
Example 4:
******************** Cursor Dump ************************
Current cursor: 1, pgadep: 0
pgactx: ccf 361c 0
ctxcbk: 0 ctxqbc: 0 ctxrws: 0
Cursor Dump:
----------------------------------------
Cursor 1 (400d9478): CURBOUND curiob:
400e43d8
curflg: 4c curpar: 0 curusr: 0 curses d 5348f 80
cursor name: BEGIN myparser.convert('/tmp','workflow000_2.log',2);
END;
child pin: d 14a 4d70, child lock: d1589968, parent lock: d 14c 64a 0
xscflg: 100064, parent handle: d 083f 1c 0, xscfl2: 4040408
nxt: 1.0x 000000a 8
Cursor frame allocation dump:
frm: -------- Comment -------- Size Seg Off
----------------------------------------
No binds included, so the SQL statement is the PL/SQL block:
BEGIN myparser.convert('/tmp','workflow000_2.log',2); END;
拿昨天的ora-600的trace file來看(ref: /oracle/admin/NTUH/udump/ntuh1_ora_22049.trc)：
******************** Cursor Dump ************************
Current cursor: 3, pgadep: 0 <-直接去找cursor3的資訊.
pgactx: 4029e 9f 6ce0 ctxcbk: 0 ctxqbc: 4029e 9f 7458 ctxrws: 4028646c 9e0
Explain plan:
Plan Table
--------
-------------------------------------------------------------------------------------------------------------------------
| Operation | Name | Rows | Bytes | Cost | TQ |IN-OUT| PQ Distrib |Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------------
| SELECT STATEMENT | | 0 | 0 | 6 | | | | | |
| NESTED LOOPS | | 1 | 208 | 6 | | | | | |
| TABLE ACCESS BY GLOBAL INDEX | P0001_PATIENTDEMOGRAPHICS| 1 | 184 | 3 | | | | ROW LOCATION| ROW LOCATION|
| INDEX UNIQUE SCAN | PK_P0001 | 1 | 0 | 2 | | | | | |
| TABLE ACCESS BY GLOBAL INDEX | P1001_CHARTNOLINKPERSONID| 1 | 24 | 3 | | | | ROW LOCATION| ROW LOCATION|
| INDEX RANGE SCAN | PK_P1001 | 1 | 0 | 2 | | | | | |
-------------------------------------------------------------------------------------------------------------------------
Cursor Dump:
----------------------------------------
Cursor 1 (103474bd8): CURNULL curiob: 0
curflg: 45 curpar: 0 curusr: 0 curses 4025a 918128
----------------------------------------
Cursor 2 ( 103474c 28): CURNULL curiob: 0
curflg: 45 curpar: 0 curusr: 0 curses 4025a 918128
----------------------------------------
Cursor 3 ( 103474c 78): CURBOUND curiob: 10356c 1f 8
curflg: 46 curpar: 0 curusr: a9 curses 4025a 918128
cursor name:
SELECT P0001.*, P1001.HOSPITALCODE, P1001.CHARTNO FROM DBPAD.P0001_PATIENTDEMOGRAPHICS P0001 INNER JOIN DBPAD.P1001_CHARTNOLINKPERSONID P1001 ON P0001.PERSONID = P1001.PERSONID WHERE P1001.PERSONID = :"SYS_B_0" AND ISAVAILABLE = :"SYS_B_1"
child pin: 0, child lock: 402867bf470, parent lock: 402d6359730
xscflg: 110400, parent handle: 402ae 3469c 8, xscfl2: 840401
Dumping Literal Information
Bind Pos: 0, Bind Len: 10, Bind Val:
Bind Pos: 1, Bind Len: 1, Bind Val:
bind 0: dty=1 mxl=32(00) mal=00 scl=00 pre=00 oacflg=10 oacfl2=300 size=32 offset=0
No bind buffers allocated
bind 1: dty=1 mxl=32(00) mal=00 scl=00 pre=00 oacflg=10 oacfl2=100 size=32 offset=0
No bind buffers allocated <-bind value data type是barchar2(32),且沒有傳任何的值.
----------------------------------------
Cursor 4 (103474cc8): CURROW curiob: 1036446b0
curflg: 7 curpar: 0 curusr: 0 curses 4025a 8e09e8
cursor name: select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataobj#,o.flags from obj$ o where o.obj#=:1
child pin: 0, child lock: 40290e6edc0, parent lock: 402e0cbd650 ^--這個我猜是oracle去資料字典中找相關對應的object.
xscflg: 21141426, parent handle: 40278d66d28, xscfl2: 5000401
Dumping cursor sharing failures: 0
bhp size: 1008/1176
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=10349ca10 bln=22 avl=04 flg=05
value=23648
End of cursor dump
***************** dump of cursor xsc= 10356c 1f 8 **
留言列表
資訊技術 (11)
