Posts Tagged ‘short_stack’
Simple and stupid example on troubleshooting using callstack
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
