How to read Oracle Errorstack Output

Read how Oracle Errorstack Output Wirte By tanelpoder, translation by me. When oracle has critical errors such as: ora-600, Errorstack dump is automatically dumped By oracle dump. When you see an error in alert. log, it will generate a trace file starting with "ksedmp: internal or fatalerror" in the trace, such errors (ORA-7445 or ORA-600 with some parameters ). "Kesdmp" means that the Kernel Service Error Dump. Therefore, the errorstack dump is under this line.
Errorstack dump can also be manually called by using Oradebug errorstack 3 (after the target process is set using Oradebug setospid ). Oradebug Errorstack seems to be Hang for a session (but there is no reasonable wait event in v $ session_wait) or it consumes more resources than normal, and you want to know the specific variable value of the current SQL statement. The Errorstack trace file has a lot of information, which is more or less useful for our troubleshooting. However, a large amount of data and binary dump may make you confused. Here I will show you some structures that you can understand. In this article, we will discuss the following topics: 1. We found that the SQL text is currently being executed from the errorstack trace file. 2. From the errorstack trace file, it is found that PL/SQL package and PL/SQL source code line number are currently being executed. 3. The current bind variable value is found in the errorstack trace file. 4. Find the number of private memory (UGA) that a cursor is using from the errorstack trace file ). Www.2cto.com I will paste the related part of errorstack dump in the following illustration. 1. the SQL text being executed is found in the errorstack trace file. You can easily find the text information of the Current SQL statement. In the "Current SQL statement for this session" section of tracefile: [html] **** 15:30:32. 830 *** service name :( SOL102) 15:30:32. 829 *** session id: (156.974) 15:30:32. 829 removed ed ORADEBUG command 'dump errorstack 3' from process Unix process pid: 8556, image:
* ** 15:30:32. 830 ksedmp: internal or fatal error Current SQL statement for this session: delete from mytab where owner =: B1 ----- PL/SQL Call Stack ----- object line object handle number name 38d172270 8 function SYS. DELETE_FUNC 38d1518f0 1 anonymous block ----- Call Stack Trace ----- www.2cto.com calling call entry argument values in hex location type point (? Means dubious value) -------------------- -------- ---------------------- -------------------------- ksedst () + 23? 0000000000000001 0017B342C 000000000 0FFDF2420 0FFFFFD7F ksedmp () + 636? 0000000000000001 0017B1EC1 000000000 00601C7E0 000000000 ksdxfdmp () + 1062? 0000000000000001 0018A3F03 000000000 00601C7E0 000000000 ksdxcb () + 1238? 0000000000000001 0018A22D3 000000000 0FF2DCC80... 2. From the errorstack trace file, we found that PL/SQL package and PL/SQL source code line number are being executed. [Html] *** 15:30:32. 830 ksedmp: internal or fatal error Current SQL statement for this session: delete from mytab where owner =: B1 ----- PL/SQL Call Stack ----- object line object handle number name 38d172270 8 function SYS. DELETE_FUNC 38d1518f0 1 anonymous block www.2cto.com ----- Call Stack Trace ----- calling call entry argument values in hex location type point (? Means dubious value) -------------------- -------- ---------------------- -------------------------- ksedst () + 23? 0000000000000001 0017B342C 000000000 0FFDF2420 0FFFFFD7F ksedmp () + 636? 0000000000000001 0017B1EC1 000000000 00601C7E0 000000000 ksdxfdmp () + 1062? 0000000000000001 0018A3F03 000000000 00601C7E0
If the process in the tracefile of dump is a PL/SQL Call, the PL/SQL Call heap is also dumped (in the PL/SQL Call Stack part ). This part tells you that an error occurs when Oracle executes the PL/SQL process and dump. Three columns of the PL/SQL call stack report: 1. The object handleobject handle is the address where the object (PL/SQL stored procedure or anonymous block) is loaded into the library cache. You can map this address through X $ KGLOB. KGLHDADR to find that the object is being processed. However, the owner and name of the object are reported in the third column.
2. line number: This is very important information. It will tell you the exact PL/SQL source code that is being executed when errorstack dump occurs. For example, in the output above, the anonymous block calls SYS. DELETE_FUNC In the first line (the first line of the anonymous block ). When errorstack dump occurs, the eighth row of PL/SQL source code of SYS. DELETE_FUNC is being executed. 3. object namePL/Name of the object stored in SQL (or anonymous block, when the object is not stored in a process ). when it is an anonymous block (the text of the anonymous block can be found through V $ SQL), you can associate this address with V $ SQL. ADDRESS to find the text information of anonymous blocks. The PL/SQL call stack above www.2cto.com only contains two rows. 38d172270 8 function SYS. DELETE_FUNC38d1518f0 1 anonymous block
You should read a PL/SQL call stack from below: 1. the row at the bottom tells us that an anonymous block is being executed and the first row of the anonymous block is being executed. It is calling this function (SYS. DELETE_FUNC ). 2. The top information tells us that SYS. DELETE_FUNC is being executed. An error occurs in row 8 and errorstack information is dumped. By querying DBA_SOURCE, we can find the owner and name of this object from dump and row number information. SQL> select line, text 2 from dba_source 3 where owner = 'sys '4 and name = 'delete _ func' 5 -- and line between X and Y 6 and type = 'function' -- PROCEDURE, package body, type body 7 order by line asc 8/[html] line text ---- resize 1 function delete_func (owner_name in varchar2) return number 2 as 3 num_deleted number; 4 begin 5 -- this Is a demo procedure 6 -- it does not do anything useful! 7 8 delete from mytab WHERE owner = owner_name; 9 COMMIT; 10 11 num_deleted: = SQL % ROWCOUNT; 12 DBMS_OUTPUT.PUT_LINE ('deleted rows = '| TO_CHAR (num_deleted )); 13 14 return num_deleted; 15 end; www.2cto.com
S selected. you can find the eighth row of PL/SQL being executed in dump (recursive DELETE query ). generally, when error dump, crash, or hang occurs (the top row is the code that the "child" function is executing by the "parent" function ), PL/SQL errorstack tells us the exact PL/SQL code. 3. from the errorstack trace file, I found that the current bind variable value problem is frequently asked. Let me answer this question: 1. A session may consume a lot of CPU in some way, and there is no meaningful wait event.2. so you need to investigate what SQL is being executed and you need to check the bind variables contained in SQL. 3. the SQL Execution Plan is normal, but the performance is poor. 4. It can be assumed that data skew exists when some tables or row sources become larger, and CBO does not calculate the correct execution plan. Therefore, You Need To Know What bind variables are used by SQL when a problem occurs. Unfortunately, there is no V $ view. Let's check the current Bind Variable value of a session. If you want to use V $ SQL _BIND_CAPTURE, you will be wrong (it only randomly samples and binds variable values, not stores all used bound variable values ). real-time SQL Monitoring in Oracle 11gR2 can achieve this goal. In V $ SQL _MONITOR, there is a column of BIND_XML, which contains the bind variable values that are running for a long enough time (the SQL statements that occupy more than 5s by default will appear in the next view. however, this is only valid when 11gR2 has Diag + Tuning pack licenses. The reason why we cannot trace the bound variable value is that the bound variable value exists in the private memory of the process. Therefore, we cannot easily track the private memory of another process. This is also why we use ORADEBUG to connect to the problematic process and send a signal to dump errorstack. Fortunately, the dump tracefile contains CURSORDUMP, including bind variable value. Note: I have written a blog about V $ SQL _MONITOR. For more information, see V $ SQL _MONITOR.
In the following example, number 8213 is the OS PROCESS ID (V $ PROCESS. SPID): SQL> oradebug setospid 8213 Oracle pid: 15, Unix process pid: 8213, image: oracleSOL102 @ solaris02SQL> oradebug dump errorstack 3 Statement processed. of course, if you diagnose CRASH or ORA-600 (errors have occurred, dump file already exists) You certainly don't need to use ORADEBUG. Take a look at the following dump: [html] **** 15:30:32. 830 ksedmp: internal or fatal error Current SQL statement for this session: DELETE FROM MYTAB WHERE OWNER =: b1 ----- PL/SQL Call Stack ----- object line object handle number name www.2cto.com 38d172270 8 function SYS. DELETE_FUNC 38d1518f0 1 anonymous block
----- Call Stack Trace ----- calling call entry argument values in hex location type point (? Means dubious value) -------------------- -------- ---------------------- -------------------------- ksedst () + 23? 0000000000000001 0017B342C 000000000 0FFDF2420 0FFFFFD7F ksedmp () + 636? 0000000000000001 0017B1EC1 000000000 00601C7E0 000000000 ksdxfdmp () + 1062? 0000000000000001 0018A3F03 000000000 00601C7E0 000000000 ksdxcb () + 1238? 0000000000000001 0018A22D3 000000000 0FF2DCC80 0FFFFFD7F .... when you open the trace file, I usually search for the first "Session Cursor Dump". When I search for it, I will see the following output: [html] ******************* Session Cursor Dump ************** * ****** Current cursor: 6, pgadep: 1 Open cursors (pls, sys, hwm, max): 5 (3, 1, 64,300) NULL 1 SYNTAX 0 PARSE 0 BOUND 4 FETCH 0 ROW 0 Cached frame pages (total, free): 4 k (41, 38), 8 k (1, 1 ), 16 k (1, 1), 32 k (0, 0) pgactx: 38cc705e0 ctxcbk: 38cc701f0 ctxqbc: 0 ctxrws: 39392a188 Explain plan: Dumping stream from 0 to 97 limit 0000: 143 136 161 146 147 3 0 0 137 119 1 0 16 0 0 0 3 1 2 .......... w ......... 0020: 0 0 0 0 59 7 3 3 121 101 115 5 9 1 1 3 83 89 .....;.... yes ..... SY 0040: 83 12 8 106 108 109 224 152 228 163 113 111 3 2 3 3 2 0 143 S .. jlm .... qo ........ 0060: 56 164 146 147 3 0 0 134 116 2 38 24 133 86 229 24 144 100 133 8 ........ t. &.. v... d. 0080: 81 193 219 234 223 154 138 3 1 2 192 214 188 3 2 14 142 Q ................ www.2cto.com ============== Plan Table ============ tables + ------------------------------------- + | Id | Operation | Name | Rows | bytes | Cost | Time | Bytes + --------------------------------- + | 0 | delete statement | 1366 | 1 | DELETE | MYTAB | 2 | table access full | MYTAB | 119 K | 2023 K | 1366 | 00:00:17 | ---------------------------------------- + ----------------------------------- +
We can find the Current cursor: 6, which tells us that the cursor opened in the UGA of this session is executing the Cursor # 6.the pgadep: 1 variable to tell us the PGA depth, that is, the recursive depth of the query execution. If pgadep is 0, it means that this query is a top-level query and is being executed by the user or application through the OCI interface. When pgadep is 1, it is a recursive query that is executed through the recursive Program Interface (RPI). It may be a data dictionary query or only an SQL statement that is executed through PL/SQL. Therefore, we can find the bound variable value of the current query currently being executed. What we need to do is search for Cursor6 # Before trace file. Remember: this is case sensitive. [Html] Cursor #6 (empty) state = BOUND curiob = fffffd7ffdd0f380 curflg = cd fl2 = 0 par = 0 ses = 398f72fe8 sqltxt (38d15d0f8) = delete from mytab where owner =: b1 hash = partition parent = 38ca516d0 maxchild = 01 plk = 395bf4dd8 ppn = n cursor instantiation = fffffd7ffdd0f380 used = 1266132628 child #0 (38d151620) pcs = 38ca512e0 clk = 395b767b8 ci = 38ca509c8 pn = 38d179e58 ctx = 38cc705e0 kgsccflg = 0 llk [fffffd7ffdd0f388, required] idx = 0 xscflg = c0110676 fl2 = 1d120000 fl3 = 4228218c fl4 = 100 Bind bytecodes Opcode = 6 Bind Rpi Scalar SQL In (may be out) Nocopy NoSkip Offsi = 48, offsi = 0 kkscoacd
Bind #0 www.2cto.com oacdty = 01 mxl = 32 (32) mxlc = 00 mal = 00 scl = 00 pre = 00 oacflg = 13 fl2 = 206001 frm = 01 csi = 31 siz = 32 off = 0 kxsbbbfp = fffffd7ffdd31808 bln = 32 avl = 03 flg = 09 value = "SYS" Frames pfr fffffd7ffdd3f8c0 siz = 4488 efr fffffd7ffdd3f800 siz = 4464 enxt: 3.0x000004b0 enxt: 2.0x00000020 enxt: 1.0x00000ca0 pnxt: 2.0x00000008 pnxt: 1.0x00000010 kxscphp fffffffd7ffddc0388 siz = 984 inu = 472 nps = 344 kxscbhp fffff D7ffdcef1a8 siz = 1008 inu = 120 nps = 0 kxscwhp fffffd7ffddc0748 siz = 10496 inu = 6608 nps = 6608 1. we have found that the state of Cursor #6 from the trace file is BOUND, which means that the BOUND variable value has been assigned. 2. the SQL text is previously found. We can see that only one variable value is bound (it is automatically placed by the PL/SQL Execution engine ).
3. Bind variale numbering starts from 0, so if we want to card the first Bind value, we need to search Bind #0. This is a systematic and reliable way to find the bound variable value. 4. we can find from the errorstack trace file how many private memory (UGA) a cursor is using. Finally, we can continue with the previous example to measure how many UGA private memory is used by some cursor of a session. [Html] Cursor frame dump enxt: 3.0x000004b0 enxt: 2.0x00000020 enxt: 1.0x00000ca0 pnxt: 2.0x00000008 pnxt: 1.0x00000010 kxscphp inclusiz = 984 inu = 472 nps = 344 kxscbhp inclusiz = 1008 inu = 120 nps = 0 kxscwhp fffffd7ffddc0748 siz = 10496 inu = 6608 nps = 6608 in cursor frame dump we can see some information about the beginning of kxsc, these means that the Kernel eXECUTION Shared Cursor. The siz of each row tells us the size of the currently allocated private memory. Of course, we need to summarize all the siz. This value is the memory usage of the cursor.
Below are some of my guesses: www.2cto.com [html] Heap description Meaning kxscphp Cursor permanent heap. allocated when cursor is opened extends Cursor default heap-default duration allocations extends Cursor ephemeral heap-short lived duration allocations extends Cursor Work heap-used when actually executing the cursor (workareas etc) kxscbhp Cursor Bind heap-this is where bind variable values and their metadata are kept. author: Coast_lichao