Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Posts Tagged ‘errorstack

Spying on the other session

with 10 comments

You might want to steal a look at the other session especially for the parameters altered by the session and the diagnostics events set by the the session.

As far as I know, there are no official ways(dynamic performace views) to get those values. But we have a well-known panacea – oradebug!

Session #1 set following parameters and events.

-- session #1
alter session set "_optim_peek_user_binds" = false;
alter session set sql_trace = true;

alter session set events '10046 trace name context forever, level 1';
alter session set events '10053 trace name context forever, level 1';

Errorstack on the level 3 dumps the modified parameters and events.

-- session #2
connect /as sysdba
oradebug setospid 9768
oradebug dump errorstack 3

The trace file contains following section.

...
Dump event group for SESSION
10053 trace name CONTEXT level 1, forever
10046 trace name CONTEXT level 1, forever
Dump event group for SYSTEM
DYNAMICALLY MODIFIED PARAMETERS:
  sql_trace                = TRUE
  _optim_peek_user_binds   = FALSE
  _rowsource_execution_statistics= FALSE
...

If all you want is just to find out the modified parameters, following dump command would to that.

oradebug dump modified_parameters 1

Very good, isn’t it?

Written by Dion Cho

July 18, 2009 at 11:03 am

Posted in Misc.

Tagged with , ,

Tracking the bind value with errorstack dump

with one comment

It is technically impossible to find out the bind value of the past query without proactive trace like 10046(level >= 4) or auditing enabled. But enabling 10046 event trace or auditing is too harsh requirement for that purpose.

One of the interesting solutions is errorstack(level >=2). Errorstack dump shows the bind value of the current process(not past!) along with the callstack and other important informations.

----------------------------------------
Cursor#2(08040C64) state=BOUND curiob=080479E8
...
 Bind bytecodes
  Opcode = 2   Bind Twotask Scalar Sql In (may be out) Copy 
  oacdef = 2bdb5bf0   Offsi = 36, Offsi = 0
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=080aa6e0  bln=22  avl=02  flg=05
  value=1



But the problem is that even the errorstack dump is NOT proactive solution, which means you should stay there at the right time and the right place. Night shift, huh?

Here you can make some ideas on automating the errorstack dump, like following.

1. ORA-00001 event trace
If your requirement is to get the bind value when the process got unique key violation, you can just turn on the trace for the diagnostic event 1, like this.

alter system set events '1 trace name errorstack level 2, forever';
or
alter session events '1 trace name errorstack level 2, forever';



, which means that whenever(forever) you hit the ORA-00001 exception(1), dump errorstack at level 2(errorstack level 2).

2. Proactively monitor the situation and dump errorstack using oradebug
For instance, let me assume that you want to find out the bind value which causes the serious TX lock contention. In this case, simple trick with PL/SQL and SQL*Plus would meet your requirement.

For instance, following simple script

connect /as sysdba

var sid number;

begin
	for idx in 1 .. 1000000 loop
		dbms_lock.sleep(1);
		select min(sid) into :sid from v$lock
			where type = 'TX' and request > 0 and block = 0 and ctime > 30;
			
		if :sid > 0 then
			exit;
		end if;
	end loop;
end;
/

print :sid

col spid new_value v_spid

select spid from v$process 
where addr in (select paddr from v$session where sid = :sid);

oradebug setospid &v_spid

oradebug dump errorstack 2



would dump errorstack for the process who has been waiting for the TX lock over 30 secs.

The result is

----------------------------------------
Cursor#2(08040C64) state=BOUND curiob=080479E8
 curflg=44 fl2=0 par=00000000 ses=2EB3F224
 sqltxt(2E5F0058)=insert into t1 values(:b1, 1)
  hash=bbc06f38e42d1542e8fdfe7363d9ab40
  parent=2945F7D0 maxchild=02 plk=2C75C638 ppn=n
cursor instantiation=080479E8
 child#1(27DB82B0) pcs=295262B8
  clk=2B138D44 ci=2AD04520 pn=2C7CEA94 ctx=2B7508A8
 kgsccflg=0 llk[080479EC,080479EC] idx=0
 xscflg=c0110676 fl2=d100008 fl3=42222008 fl4=0
 Bind bytecodes
  Opcode = 2   Bind Twotask Scalar Sql In (may be out) Copy 
  oacdef = 2bdb5bf0   Offsi = 36, Offsi = 0
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=080aa6e0  bln=22  avl=02  flg=05
  value=1


There would other tricks to get the bind value using errorstack at this way of emulating proactive trace. Even this is not a perfect solution, the merit of negligible overhead is not negligible.


Written by Dion Cho

June 15, 2009 at 1:55 am

Posted in Troubleshooting

Tagged with ,

Simple and stupid example on troubleshooting using callstack

with 7 comments

Look at this – the simplest query imagineable.

UKJA@ukja102> select * from dual;
...  <-- Hanged!!!



But it’s hanged!

Okay, it’s abnormal hang situation, so I look into the session.

SYS@ukja10> @session_list

  SID SERIAL# PROGRAM    EVENT                SQL_TEXT
----- ------- ---------- -------------------- ------------------------------
  146    6578 sqlplus.ex SQL*Net message from
              e           client
...

SYS@ukja10> exec print_table('select * from v$session where sid = 146');
SADDR                         : 2EB2FDFC
SID                           : 146
SERIAL#                       : 6578
AUDSID                        : 19288
PADDR                         : 2EA4F58C
USER#                         : 61
USERNAME                      : UKJA
COMMAND                       : 0
OWNERID                       : 2147483644
TADDR                         :
LOCKWAIT                      :
STATUS                        : INACTIVE
SERVER                        : DEDICATED
SCHEMA#                       : 61
SCHEMANAME                    : UKJA
OSUSER                        : UKJA\exem
PROCESS                       : 12172:10844
MACHINE                       : EX-EM.COM\UKJA
TERMINAL                      : UKJA
PROGRAM                       : sqlplus.exe
TYPE                          : USER
SQL_ADDRESS                   : 00
SQL_HASH_VALUE                : 0
SQL_ID                        :
SQL_CHILD_NUMBER              :
PREV_SQL_ADDR                 : 27DAB918
PREV_HASH_VALUE               : 96831227
PREV_SQL_ID                   : 7us1frh2wb1rv
PREV_CHILD_NUMBER             : 0
MODULE                        : SQL*Plus
MODULE_HASH                   : 3669949024
ACTION                        :
ACTION_HASH                   : 0
CLIENT_INFO                   :
FIXED_TABLE_SEQUENCE          : 114132657
ROW_WAIT_OBJ#                 : -1
ROW_WAIT_FILE#                : 0
ROW_WAIT_BLOCK#               : 0
ROW_WAIT_ROW#                 : 0
LOGON_TIME                    : 2009/06/11 13:16:42
LAST_CALL_ET                  : 79
PDML_ENABLED                  : NO
FAILOVER_TYPE                 : NONE
FAILOVER_METHOD               : NONE
FAILED_OVER                   : NO
RESOURCE_CONSUMER_GROUP       :
PDML_STATUS                   : DISABLED
PDDL_STATUS                   : ENABLED
PQ_STATUS                     : ENABLED
CURRENT_QUEUE_DURATION        : 0
CLIENT_IDENTIFIER             :
BLOCKING_SESSION_STATUS       : NO HOLDER
BLOCKING_INSTANCE             :
BLOCKING_SESSION              :
SEQ#                          : 29
EVENT#                        : 256
EVENT                         : SQL*Net message from client
P1TEXT                        : driver id
P1                            : 1413697536
P1RAW                         : 54435000
P2TEXT                        : #bytes
P2                            : 1
P2RAW                         : 00000001
P3TEXT                        :
P3                            : 0
P3RAW                         : 00
WAIT_CLASS_ID                 : 2723168908
WAIT_CLASS#                   : 6
WAIT_CLASS                    : Idle
WAIT_TIME                     : 0
SECONDS_IN_WAIT               : 79
STATE                         : WAITING
SERVICE_NAME                  : UKJA10
SQL_TRACE                     : DISABLED
SQL_TRACE_WAITS               : FALSE
SQL_TRACE_BINDS               : FALSE
-----------------



I really see nothing special. It is just in the idle status doing nothing. Now what else can I do?

Oracle provides pretty little feature called short_stack, which prints the minimal callstack information.

SYS@ukja10> oradebug setospid 11744
Oracle pid: 23, Windows thread id: 11744, image: ORACLE.EXE (SHAD)              

SYS@ukja10> oradebug short_stack
_ksdxfstk+14<-_ksdxcb+1481<-_ksdxsus+1037<-_ksdxffrz+50<-_ksdxcb+1481
<-_ssthreadsrgruncallback+428<-_OracleOradebugThreadStart@4+795<-7C80B680
<-00000000<-719857C4<-719E4376<-62985408<-62983266<-60A08BD8<-609CCBB8
<-609AF9CD<-609ACF09<-6097E2C7<-__PGOSF126__opikndf2+781<-_opitsk+540
<-_opiino+1087<-_opiodr+1099<-_opidrv+819<-_sou2o+45<-_opimai_real+112
<-_opimai+92<-_OracleThreadStart@4+708<-7C80B680



Do you see any meaningful information? What makes me curios is following part.

... <-_ksdxsus+1037<-_ksdxffrz+50<- ... 



My interpretation. Flash freeze(ffrz) was invoked and the session was suspended(sus). Resuming the instance from flash freeze would prove my suspicion.

SYS@ukja10> oradebug ffresumeinst
Statement processed.

...
UKJA@ukja102> select * from dual;

D
-
X

Elapsed: 00:09:30.14



If you don’t like the simplicity of short_stack, errorstack would show more information.

SYS@ukja10> oradebug dump errorstack 2
Statement processed.
SYS@ukja10> oradebug tracefile_name
c:\oracle\admin\ukja10\udump\ukja10_ora_11744.trc

----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
_ksedst+38           CALLrel  _ksedst1+0           1 1
_ksedmp+898          CALLrel  _ksedst+0            1
_ksdxfdmp+847        CALLreg  00000000             2
_ksdxcb+1481         CALLreg  00000000             D68F43C 11 3 D68F39C D68F3EC
_ksdxsus+1037        CALLrel  _ksdxcb+0            1
_ksdxffrz+50         CALLrel  _ksdxsus+0           1
_ksdxcb+1481         CALLreg  00000000             D68FB20 7 1 D68FA80 D68FAD0
_ssthreadsrgruncall  CALLrel  _ksdxcb+0            1
back+428                                           
_OracleOradebugThre  CALLrel  _ssthreadsrgruncall  D68FF84
adStart@4+795                 back+0               
7C80B680             CALLreg  00000000             
00000000             VIRTUAL  7C93EB94             
719857C4             CALLrel  71983C6B             
719E4376             CALLreg  00000000             
62985408             CALL???  00000000             
62983266             CALLrel  6298530C             F90 AAD779A 810 0
60A08BD8             CALLreg  00000000             AAAF98C AAD779A AAAFB20 0 0
609CCBB8             CALLrel  60A07EF0             AA7FAF0 B83E01C A5FED30
609AF9CD             CALLrel  609CCAF0             AA7FAF0 A5FED30
609ACF09             CALLrel  609ACF48             A5FEC14 55 A5FED30 0 B83E2AC
                                                   0 3
6097E2C7             CALLrel  609ACEF4             A5FEC14 A5FED30 B83E2AC 0
__PGOSF126__opikndf  CALLreg  00000000             
2+781                                              
_opitsk+540          CALLreg  00000000             
_opiino+1087         CALLrel  _opitsk+0            0 0
_opiodr+1099         CALLreg  00000000             3C 4 B83FC8C
_opidrv+819          CALLrel  _opiodr+0            3C 4 B83FC8C 0
_sou2o+45            CALLrel  _opidrv+0            3C 4 B83FC8C
_opimai_real+112     CALLrel  _sou2o+0             B83FC80 3C 4 B83FC8C
_opimai+92           CALLrel  _opimai_real+0       2 B83FCB8
_OracleThreadStart@  CALLrel  _opimai+0            
4+708                                              
7C80B680             CALLreg  00000000             



Very stupid demo, isn’t it? But is a streotypical case which shows the usefullness and uniqueness of callstack analysis.

Tanel Poder shows his uniquesses and real-life approach on callstack analysis (short_stack) here, and you might like to see see following metalink notes which accidentally contain good information on callstack analysis.

  • 175982.1: ORA-600 Lookup Error Categories
  • 453521.1: ORA-04031 “KSFQ Buffers” ksmlgpalloc
  • 558671.1: Getting ORA-01461 while INSERT INTO WWV_THINGS





Written by Dion Cho

June 11, 2009 at 7:00 am

Follow

Get every new post delivered to your Inbox.

Join 59 other followers