Dion Cho – Oracle Performance Storyteller

We are natural born scientists

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





About these ads

Written by Dion Cho

June 11, 2009 at 7:00 am

7 Responses

Subscribe to comments with RSS.

  1. Hi Dion,

    Was this a test or a real case
    No matter what case it was how did you come conclusion to run oradebug ffresumeinst (or where did you get what to run) there is no explanation for that.

    coskan

    June 11, 2009 at 9:00 am

  2. @Coskan.

    1. It’s just a simple test case. I bet, in the real system, this would never happen!

    2. As you know already, flash freeze is done by “oradebug ffbegin” and resolved by “oradebug ffresumeinst” command.

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

    I use it in the benchmarking env to freeze current sessions.

    Dion Cho

    June 11, 2009 at 9:07 am

  3. Hi Dion:
    Sorry for the stupid question.
    What is special about ksdxsus+1037<-_ksdxffrz+50 that made you curious? And once that is determined how did you know that you had to use oradebug ffresumeinst.
    Since you simulated this you will know how to end it.

    Kumar

    June 11, 2009 at 3:44 pm

  4. Thanks for the reply. Now I know “oradebug ffbegin” was the command which was missing from the post :)

    I should have checked Miladin Madrakovics oradebug doc before asking :)

    coskan

    June 11, 2009 at 5:26 pm

  5. @Kumar.

    Exact point. That’s why I called this post “stupid”. :)

    Dion Cho

    June 12, 2009 at 9:58 pm

  6. @Dion

    For Kumars quesion, I think the last 2-3 calls are standart and related
    with the debugging process itself so you can have a rough idea to start investigating from the last 3. or 4. call.

    Am I right ?

    coskan

    June 15, 2009 at 7:46 am

  7. @Coskan.

    I think that Kumar just wanted to point out the stupidity of my test case. I made the problem, so I know what to do. Without knowing the call of “oradebug ffbegin”, it would not be easy to find out the solution even with the help of callstacks.

    Dion Cho

    June 18, 2009 at 3:13 am


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 59 other followers

%d bloggers like this: