Showing posts with label oradebug. Show all posts
Showing posts with label oradebug. Show all posts

Sunday, April 25, 2010

Oracle Hang状態でActive Session Listを獲得しよう。

Maxgaugeのようなツールの最高のメリットはOracle Hang状態でもActive Session Listを得ることができるということです。待機イベントとSQL情報が含まれたActive Session Listこそがすべての性能トラブルシューティングの初めです。ここからすべてのトラブルシューティングが始まります。


MaxgaugeのようなツールがOracle Hang状況でもデータを収集できるのはDMA（Direct Memory Access）を使用するためです。この方法はOracleのCOE（Center of Expertise)チームが極限の状況、すなわちSQLで必要な情報を収集できない際使用していた方法です。これがMaxgaugeのようなツールのおかげで普遍化されたのです。


もしMaxgaugeのようなツールがなければどうすればいいでしょうか。Oracleが提供するASHDUMP機能をPreliminary Connectionとともに使えば同じ効果が得られます。


  • Preliminary ConnectionとはSQL*Net方式ではない、Direct Memory Access方式で接続することです。
  • ASHDUMPとはActive Session ListのメモリーバージョンであるASH（Active Session History）をテキストファイルに書き込む機能です。

従って、この二つの機能を一緒に使えばまるでDMA方式でActive Session Listを得るのは同じ効果があります。


簡単な例で説明します。


まずPreliminary Connectionを結びます。 


#> sqlplus -prelim sys/oracle@ukja1106 as sysdba

SQL*Plus: Release 11.1.0.6.0 - Production on Mon Apr 26 09:43:35 2010

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

一般的なクエリは動きません。 

alter session set nls_date_format='yyyy/mm/dd hh24:mi:ss'

*

ERROR at line 1:

ORA-01012: not logged on

Process ID: 0

Session ID: 0 Serial number: 0

Preliminary Connection状態でASHDUMPを行ないます。レベル（10）は10分を意味します。すなわち、過去の10分間のASHを意味します。 

SYS@ukja1106> oradebug setmypid

Statement processed.

SYS@ukja1106> oradebug dump ashdump 10

Statement processed.

SYS@ukja1106> oradebug tracefile_name

c:\oracle\diag\rdbms\ukja1106\ukja1106\trace\ukja1106_ora_12152.trc

ダンプファイルの内容は次のようです。11gからはActive Session Listとともに該当リストをテーブルに格納するためのスクリプトまで提供します。ハングの悪夢が終わったあと（大部分リスタート）、正確な分析をする目的です。 

Processing Oradebug command 'dump ashdump 10'

ASH dump

<<>>

****************

SCRIPT TO IMPORT

****************

------------------------------------------

Step 1: Create destination table 

------------------------------------------

CREATE TABLE ashdump AS

SELECT * FROM SYS.WRH$_ACTIVE_SESSION_HISTORY WHERE rownum < 0

----------------------------------------------------------------

Step 2: Create the SQL*Loader control file  as below

----------------------------------------------------------------

load data 

infile * "str '\n####\n'"

append

into table ashdump

fields terminated by ',' optionally enclosed by '"'

(                               

SNAP_ID  CONSTANT 0           , 

DBID                          , 

INSTANCE_NUMBER               , 

SAMPLE_ID                     , 

SAMPLE_TIME TIMESTAMP ENCLOSED BY '"' AND '"' "TO_TIMESTAMP(:SAMPLE_TIME   ,'MM-DD-YYYY HH24:MI:SSXFF')"   , 

SESSION_ID                    , 

SESSION_SERIAL#               , 

SESSION_TYPE                  , 

USER_ID                       , 

SQL_ID                        , 

SQL_CHILD_NUMBER              , 

SQL_OPCODE                    , 

FORCE_MATCHING_SIGNATURE      , 

TOP_LEVEL_SQL_ID              , 

TOP_LEVEL_SQL_OPCODE          , 

SQL_PLAN_HASH_VALUE           , 

SQL_PLAN_LINE_ID              , 

SQL_PLAN_OPERATION#           , 

SQL_PLAN_OPTIONS#             , 

SQL_EXEC_ID                   , 

SQL_EXEC_START DATE 'MM/DD/YYYY HH24:MI:SS' ENCLOSED BY '"' AND '"' ":SQL_EXEC_START"   , 

PLSQL_ENTRY_OBJECT_ID         , 

PLSQL_ENTRY_SUBPROGRAM_ID     , 

PLSQL_OBJECT_ID               , 

PLSQL_SUBPROGRAM_ID           , 

QC_INSTANCE_ID                , 

QC_SESSION_ID                 , 

QC_SESSION_SERIAL#            , 

EVENT_ID                      , 

SEQ#                          , 

P1                            , 

P2                            , 

P3                            , 

WAIT_TIME                     , 

TIME_WAITED                   , 

BLOCKING_SESSION              , 

BLOCKING_SESSION_SERIAL#      , 

CURRENT_OBJ#                  , 

CURRENT_FILE#                 , 

CURRENT_BLOCK#                , 

CURRENT_ROW#                  , 

CONSUMER_GROUP_ID             , 

XID                           , 

REMOTE_INSTANCE#              , 

TIME_MODEL                    , 

SERVICE_HASH                  , 

PROGRAM                       , 

MODULE                        , 

ACTION                        , 

CLIENT_ID                       

)                               

---------------------------------------------------

Step 3: Load the ash rows dumped in this trace file

---------------------------------------------------

sqlldr userid/password control=ashldr.ctl data= errors=1000000

---------------------------------------------------

<<>>

<<>>

####

58646642,1,12519562,"04-26-2010 09:44:01.822000000",160,1,2,0,

"",0,0,0,"",0,0,0,0,0,

0,"",0,0,0,0,0,0,0,

3213517201,9858,0,3,1,0,69788,4294967295,0,

4294967295,0,0,0,0,,0,0,165959219,

"ORACLE.EXE (CKPT)","",

"",""

####

58646642,1,12519486,"04-26-2010 09:42:45.808000000",160,1,2,0,

"",0,0,0,"",0,0,0,0,0,

0,"",0,0,0,0,0,0,0,

3213517201,9767,1,1,1,0,38825,4294967295,0,

4294967295,0,0,0,0,,0,0,165959219,

"ORACLE.EXE (CKPT)","",

"",""

####

58646642,1,12519416,"04-26-2010 09:41:35.770000000",160,1,2,0,

"",0,0,0,"",0,0,0,0,0,

0,"",0,0,0,0,0,0,0,

4078387448,9683,3,3,3,0,11083,4294967295,0,

4294967295,0,0,0,0,,0,0,165959219,

"ORACLE.EXE (CKPT)","",

"",""

####

58646642,1,12519384,"04-26-2010 09:41:03.774000000",163,1,2,0,

"",0,0,0,"",0,0,0,0,0,

0,"",0,0,0,0,0,0,0,

3176176482,40612,5,1,1000,999888,0,4294967291,0,

4294967295,0,0,0,0,,0,0,165959219,

"ORACLE.EXE (DIA0)","",

"",""

####

58646642,1,12519304,"04-26-2010 09:39:43.719000000",160,1,2,0,

"",0,0,0,"",0,0,0,0,0,

0,"",0,0,0,0,0,0,0,

3213517201,9551,1,1,1,0,38798,4294967295,0,

4294967295,0,0,0,0,,0,0,165959219,

"ORACLE.EXE (CKPT)","",

"",""

####

58646642,1,12519265,"04-26-2010 09:39:04.663000000",163,1,2,0,

"",0,0,0,"",0,0,0,0,0,

0,"",0,0,0,0,0,0,0,

3176176482,40493,5,1,1000,999941,0,4294967291,0,

4294967295,0,0,0,0,,0,0,165959219,

"ORACLE.EXE (DIA0)","",

"",""

####

58646642,1,12519183,"04-26-2010 09:37:42.554000000",160,1,2,0,

"",0,0,0,"",0,0,0,0,0,

0,"",0,0,0,0,0,0,0,

3213517201,9406,0,1,1,0,54077,4294967295,0,

4294967295,0,0,0,0,,0,0,165959219,

"ORACLE.EXE (CKPT)","",

"",""

####

<<>>



*** 2010-04-26 09:45:51.625

Oradebug command 'dump ashdump 10' console output:

事後分析用で使用したら有効であるはずです。ただし、Preliminary ConnectionとOradebugは非公式的な支援機能だから徹底なテストのあとに使用しなければならないし、可能な限りオラクル支援エンジニアの承認の上で使用しなければなりません。


もっと詳しい情報は次のリンクを参照してください。


at 6:27 PM Posted by Dion_Cho 0 comments
Labels: ,

Thursday, June 11, 2009

Callstackを通じるTroubleshootingの簡単な例

下を見てください。想像できる一番簡単な問い合わせです。

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

その簡単さにもかかわらず、Hangされてしまいました。この問題の分析のために、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
-----------------

Sessionは何もしないで、Idle状態に留まっています。原因が探せる他の方法はないでしょうか。

Oracleはshort_stackと呼ばれる機能を提供しています。short_stackは最小限のCallstack情報を見せてくれます。

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

何か意味ある部分が見えますか。この部分はどうですか。

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

私には「Flash freeze(ksdxffrz)が呼ばれてから、Sessionが停止になった(ksdxsus)」と解析されます。したがって、InstanceをResumeさせれば、問題は解決されるでしょう。

SYS@ukja10> oradebug ffresumeinst
Statement processed.

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

D
-
X

Elapsed: 00:09:30.14

errorstackはより正確なCallstack情報を提供します。

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

たとえ簡単なデモですが、Callstack分析の有用さを良く見せてくれる典型的な例でしょう。Callstackで使われた関数名については下のMetalink文書を参照してください。

  • 175982.1: ORA-600 Lookup Error Categories
  • 453521.1: ORA-04031 "KSFQ Buffers" ksmlgpalloc
  • 558671.1: Getting ORA-01461 while INSERT INTO WWV_THINGS
at 1:42 AM Posted by Dion_Cho 0 comments
Labels: , , ,
Subscribe to: Posts (Atom)