Oracle執行語句跟蹤(1)——使用sql trace實現語句追蹤

系統上的某個接口提交數據經常超時（超過3秒），而我單獨在后台數據庫(Oracle)執行insert，只需要17ms。提交數據的客戶端沒有任何的調試日志，只能通過跟蹤后台語句記錄實際調用過程中的數據庫執行時間。從而發現問題耗時最多的階段。

安裝dbms_support包

SQL> @?\rdbms\admin\dbmssupp.sql
SQL> grant execute on dbms_support to test;

找到需要跟蹤的會話，一個接口可能會建立多個會話，需要根據會話建立的時間來判斷真正需要跟蹤的會話。

SQL> alter session set nls_date_format='YYYY-MM-DD HH24:MI:SS';
SQL> select sid,serial#,logon_time from v$session where username=&name and program=&program;
輸入 name 的值:  'test'
輸入 program 的值:  'test.exe'

使用start_trace_in_session進行跟蹤

SQL>exec dbms_support.start_trace_in_session(1157,59729,TRUE,TRUE);

開始跟蹤后，在客戶端進行對應的操作。

使用stop_trace_in_session結束跟蹤

SQL> exec dbms_support.stop_trace_in_session(1157,59729);

使用以下的語句獲得trace文件的位置。

     SELECT    d.VALUE 
          || '\' 
          || LOWER (RTRIM (i.INSTANCE, CHR (0))) 
          || '_ora_' 
          || p.spid 
          || '.trc' trace_file_name 
     FROM (SELECT p.spid 
             FROM v$mystat m, v$session s, v$process p 
            WHERE m.statistic# = 1 AND s.SID = &SID AND p.addr = s.paddr) p, 
          (SELECT t.INSTANCE 
             FROM v$thread t, v$parameter v 
            WHERE v.NAME = 'thread' 
              AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i, 
          (SELECT VALUE 
             FROM v$parameter 
            WHERE NAME = 'user_dump_dest') d 

用文本編輯器可以直接打開trace文件

圖中的這一段就是對一個語句的從解析到返回數據的整個過程，如果統計從開始請求到消息返回客戶端的時間，直接將紅框中的兩個tim相減就可以了，11592216806504-11592199796058=17010446,其單位是1/1000000秒。若要單獨獲取執行時間，可以EXEC的TIM減掉PARSE的TIM，差值即為執行的時間。其它字段的說明可以參照這個文檔。

另外也可以使用TKPROF將trace文件轉換成為執行計划解析的文本。

D:\app\oracle\diag\rdbms\wxmesdb\wxmesdb\trace>tkprof wxmesdb_ora_6520.trc trace_1.txt

TKPROF: Release 12.1.0.1.0 - Development on 星期三 1月 6 08:30:11 2016

Copyright (c) 1982, 2013, Oracle and/or its affiliates.  All rights reserved.

如上圖所示，可以得到執行時間為17秒，與上一步中通過TIM相減的差值一致。

--EOF--