Oracle優化-SQL_TRACE

思維導圖

---

Oracle優化10-SQL_TRACE解讀

Oracle優化11-10046事件

---

概述

當我們想了解一條SQL或者是PL/SQL包的運行情況時，特別是當他們的性能非常差時，比如有的時候看起來就好好像卡在什么地方一樣，該如何入手呢？

是不是恨不得鑽進去看下到底發生了什么？

好在Oracle提供了我們這樣的一種方法使用SQL_TRACE來跟蹤SQL的執行情況，通過SQLTRACE我們可以很容易的知道當前正在執行的SQL正在干什么。

---

以下操作基於Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

---

SQL_TRACE

SQL_TRACE命令會將SQL的執行過程輸出到一個TRACE文件中，我們通過閱讀這個TRACE文件就可以了解到在這個SQL執行的過程中，oracle究竟做了哪些事情。

---

如何開啟SQL_TRACE

#設置sql_trace生成的文件標識，便於查找 SQL> alter session set tracefile_identifier='mytest'; Session altered #對當前的會話開啟sql_trace SQL> alter session set sql_trace=true; Session altered SQL> 執行具體的sql #關閉當前會話的sql_trace SQL> alter session set sql_trace=false;

SQL_TRACE生成的文件在哪個目錄下呢？

開啟SQL跟蹤后，會生成一個trace文件，通過初始化參數user_dump_dest配置其所在目錄，該參數的值可以通過下面方法獲取到：

select name, value from v$parameter where name = 'user_dump_dest'

oracle@entel2:[/oracle]$cd /oracle/diag/rdbms/cc/cc/trace oracle@entel2:[/oracle/diag/rdbms/cc/cc/trace]$ls *mytest* cc_ora_305_mytest.trc cc_ora_305_mytest.trm

cc_ora_305_mytest.trc 就是我們的trace文件。

擴展：

11g中新增的trm文件

.trc文件稱為Sql Trace Collection file，它是系統的跟蹤文件(trace),當系統啟動時或運行過程中出現錯誤時,系統會自動記錄跟蹤文件到指定的目錄,以便於檢查,這些文件需定期維護刪除。

.trm file 全稱是trace map file. 被稱為跟蹤元數據文件，.trm文件中的元數據描述了存儲在.trc文件中的跟蹤記錄 。

.trm文件是伴隨着.trc文件產生，一個.trm對應一個.trc文件。.trm文件包含.trc文件的結構化信息。

The files located in the TRACE directory, with the “.trm” extensions, are called Trace Metadata files. The metadata in .trm files describe the trace records stored inside of .trc trace files.

---

不指定文件標識時，如何查找呢？

如果我們沒有指定標識時，改如何快速查找對應的trace文件呢？

trace文件的名字是獨立於版本和平台的，在大部分常見的平台下，命名結構如下：

{instance name}_{process name}_{process id}.trc

知道當前會話的sid 便可以查找到

比如下面這種情況

通過如下sql

select s.SID, s.SERVER, lower(case when s.SERVER in ('DEDICATED', 'SHARED') then i.INSTANCE_NAME || '_' || nvl(pp.SERVER_NAME, nvl(ss.NAME, 'ora')) || '_' || p.SPID || '.trc' else null end) as trace_file_name from v$instance i, v$session s, v$process p, v$px_process pp, v$shared_server ss where s.PADDR = p.ADDR and s.SID = pp.SID(+) and s.PADDR = ss.PADDR(+) and s.TYPE = 'USER' and s.SID = '263' order by s.SID ;

oracle@entel2:[/oracle/diag/rdbms/cc/cc/trace]$ls cc_ora_2642.trc cc_ora_2642.trc

---

其他情況的說明

• SQLTRACE除了設置會話級別，也可以設置系統級別

alter system set sql_trace=true;

這樣就可以對實例上的全部SQL進行跟蹤了，需要注意的是這種方式的代價是非常巨大的，請慎重操作。

• 另外SQLTRACE也可以在初始化參數中設置

SQL> show parameter sql_trace NAME TYPE VALUE -------------- ----------- -------------- sql_trace boolean FALSE

• 關閉會話級別的sql_trace, 除了使用

alter session set sql_trace=false ;

關閉外，直接退出sql_plus來終止也是可以的，只要關閉了當前會話，會話級別的sql_trace就失效了。

---

TKPROF工具

最原始的trace文件的可讀性是比較差的，除非有必要，我們一般都是通過tkprof工具來處理這個trace文件。

TKPROF工具是oracle自帶的一個工具，用於處理原始的trace文件，它的主要的作用就是合並匯總trace文件中的一些項，規范化文件的格式，是文件更具有可讀性。

TKPROF使用

oracle@entel2:[/oracle/diag/rdbms/cc/cc/trace]$tkprof cc_ora_305_mytest.trc mytest.txt TKPROF: Release 11.2.0.4.0 - Development on Wed Dec 14 18:45:34 2016 Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved. 

執行后，會生成mytest.txt文件，閱讀更加方便。

---

TKPROF參數

在命令行下直接輸入 tkprof ,回車，會看到tkprof支持的所有參數

---

下面重點說一下常用的幾個參數

explain=user/password

Connect to ORACLE and issue EXPLAIN PLAN.

在trace文件中輸入SQL的執行計划。

需要注意的是，如果不使用explain，在trace文件中，我們看到的是SQL實際的執行路徑。比如：

使用explain, tkprof在trace文件中不但輸入sql的實際執行路徑，還會生成該SQL的執行計划。

比如：

oracle@entel2:[/oracle/diag/rdbms/cc/cc/trace]$tkprof cc_ora_305_mytest.trc mytest_explain.txt explain=cc/xgongjiang TKPROF: Release 11.2.0.4.0 - Development on Wed Dec 14 19:26:15 2016 Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved. 

查看 mytest_explain.txt文件可以看到比上面的多了一個Execution Plan：

上面的信息中，第一部分是SQL的實際執行路徑，下面的部分是使用Explain for的方式生成的SQL執行計划。

---

sys=(yes|no)

如果設置為yes,在trace文件中將輸出所有SYS用戶的操作（也包含用戶SQL語句引發的遞歸SQL），如果為no,則不輸出。 默認為yes. 實際上設置為no,trace文件更具有可讀性。

oracle@entel2:[/oracle/diag/rdbms/cc/cc/trace]$tkprof cc_ora_305_mytest.trc mytest_explain_sysno.txt explain=cc/xgongjiang sys=no TKPROF: Release 11.2.0.4.0 - Development on Wed Dec 14 19:47:25 2016 Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.

左側為默認yes，右側為sys=no ,可以sys用戶的操作被過濾掉，清晰了很多。

---

aggregate=yes|no

默認情況下，tkprof工具將所有相同的sql在輸入文件中做合並，如果設置aggregate=no ,則分別列出每個sql的信息。

默認yes的情況：

上面就是合並后的SQL，這樣看起來比較簡潔，如果你需要每一個SQL的單獨信息，可以把aggregate設置為no ,如下所示：

設置為no的情況

---

TRACE文件解讀

我們通過以下命令(過濾掉sys用戶解析的sql,一般都是操作數據字典視圖的sql)生成一個tkprof工具分析過的文件

oracle@entel2:$ tkprof cc_ora_305_mytest.trc mytest_sysno.txt sys=no

trace文件的頭部信息描述了tkprof的版本，以及報告中一些列的含義。

在下面的報告中，每一條SQL都包含了這個SQL執行的所有信息，對於任何一條SQL都應該包含3個步驟（對應下表的call列）

• parse（分析） ：SQL的分析階段
• execute（執行）：SQL的執行階段
• fetch（數據提取）：數據的提取階段

橫向除了call(調用)之外，還包括

• Count：計數器，表示當前的操作被執行了多少次
• Cpu：當前的操作消耗CPU的時間（單位秒）
• Elapsed：當期的操作一共用時多少（包括CPU時間和等待時間）
• Disk：當前操作的物理讀（磁盤I/O次數）
• Query：通常是查詢的使用方式，當前操作的一致性方式讀取的數據塊數
• Current:通常是修改數據使用的方式，當前操作的current的方式讀取的數據塊數
• Rows：當前操作處理的數據記錄數

---

在SQL的解析過程中，需要訪問一些數據字典視圖，通常來講我們可能不需要用到，可以使用 tkprof sys=no的方式屏蔽掉它們。

---

下面的SQL我們可能需要注意一下。

上述SQL其實就是CBO在做動態采樣的SQL語句，如果我們看到這條SQL語句，就知道CBO在這里采用了動態采樣（另外一層的意思是說我們的表可能沒有做分析）。

---

下面才是我們真正需要的信息，我們執行的SQL的trace信息

從上圖中我們可以看到這條SQL 被分析了一次，被執行了一次，數據提取了1次（數據提取也有可能多次提取完成）。

其中消耗CPU的資源0S，總耗時0S，物理讀取了0個數據塊（說明是從內存中讀取的），一致性讀取了12個數據塊，沒有發生current方式的讀取（通常update的操作會發生current讀取），一共提取數據記錄數為3，正是查詢出來的結果數.

---

接下來我們繼續分析：

• Misses in library cache during parse: 1–shared pool中沒有命中，說明這是一次硬解析，軟解析這里為0
• Optimizer mode: ALL_ROWS–當前的優化器模式CBO All_ROWS
• Parsing user id: 49–分析用戶的id(根據user_id可以在all_user中查到對應的用戶)
• Number of plan statistics captured: 1 –統計到的分析計划統計數量

select a.* from all_users a where a.user_id = 49;

---

繼續，下面是這條SQL的具體執行計划和執行消耗的資源信息。需要注意的是，這個計划里面的信息不是CBO根據表分析數據算出來的數值，而是SQL語句執行過程中消耗的資源信息。

Rows (1st) —當前操作返回的實際返回的記錄數 
Row Source Operation–行源操作，表示當前操作的數據訪問方式 
cr—–consistent read 一致性防暑讀取的數據塊，相當於query列上Fetch步驟的值 
pr—–physical read 物理讀取的數據塊，相當於disk列上的Fetch步驟的值 
pw—–physical write 物理寫 
time=85 us —當前執行操作的時間 (微秒 )

1秒=1000毫秒(ms) 
1秒=1000000 微秒(μs) 
1秒=1000000000 納秒(ns)

…………

如果在使用tkprof工具添加explain=username/passwd可一在文件中看到執行計划，如下：

---

下面的部分是對這個SQL_TRACE期間所有非遞歸SQL（NON-RECURSIVE STATEMENTS）的執行信息統計匯總

遞歸SQL： 執行一條SQL語句衍生出執行的一些其他的SQL，這些衍生出來的SQL就叫做遞歸SQL。

比如對SQL進行分析，需要讀取一些數據字典來獲取相關的信息，比如是否有權限，對象是否存在，對象的存儲信息等，這些SQL都統稱為遞歸SQL語句

下面是所有遞歸SQL語句的統計信息

---

上面是一個完整的經過tkprof處理過的trace文件，它真是的統計了SQL語句在運行過程中的各種資源消耗，這個報告對於分析性能有問題的SQL語句非常重要。

但是這個報告只是一個匯總的結果集，入股想確切的知道SQL語句每一步的執行是如何操作的，就要分析原始的trace文件，雖然不易讀，但是它能夠讓你確切的知道SQL在哪個點在做什么，以及SQL是如何工作的。

---

原始TRACE文件解讀

原始文件開頭部分記錄了trace的文件路徑和名稱，trace生成時間，數據庫的版本，操作系統的版本，實例名等信息，

下面我們截取對應SQL的原始文件來做下說明：

=====================
PARSING IN CURSOR #140535085375432 len=138 dep=0 uid=49 oct=3 lid=49 tim=1481751318263300 hv=3651439770 ad='1c3714c98' sqlid='cjxrhfzcu934u' select a.*, a.rowid from price a where a.price_ver_id in (select a.price_ver_id from price_ver a where a.rate_plan_id = 11566) END OF STMT PARSE #140535085375432:c=13000,e=12343,p=0,cr=100,cu=0,mis=1,r=0,dep=0,og=1,plh=282154677,tim=1481751318263300 EXEC #140535085375432:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=282154677,tim=1481751318263369 FETCH #140535085375432:c=0,e=118,p=0,cr=6,cu=0,mis=0,r=3,dep=0,og=1,plh=282154677,tim=1481751318266947 STAT #140535085375432 id=1 cnt=3 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=6 pr=0 pw=0 time=85 us cost=1 size=906 card=2)' STAT #140535085375432 id=2 cnt=3 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=5 pr=0 pw=0 time=61 us cost=1 size=906 card=2)' STAT #140535085375432 id=3 cnt=1 pid=2 pos=1 obj=65903 op='TABLE ACCESS BY INDEX ROWID PRICE_VER (cr=3 pr=0 pw=0 time=32 us cost=1 size=26 card=1)' STAT #140535085375432 id=4 cnt=1 pid=3 pos=1 obj=67745 op='INDEX RANGE SCAN IDX_PRICE_VER_RATE_PLAN (cr=2 pr=0 pw=0 time=11 us cost=1 size=0 card=1)' STAT #140535085375432 id=5 cnt=3 pid=2 pos=2 obj=67731 op='INDEX RANGE SCAN IDX_PRICE_PRICE_VER_ID (cr=2 pr=0 pw=0 time=29 us cost=0 size=0 card=2)' STAT #140535085375432 id=6 cnt=3 pid=1 pos=2 obj=64267 op='TABLE ACCESS BY INDEX ROWID PRICE (cr=1 pr=0 pw=0 time=11 us cost=0 size=854 card=2)' CLOSE #140535085375432:c=0,e=6,dep=0,type=0,tim=1481751318315779 PARSE #140535085337488:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1481751318315871 EXEC #140535085337488:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1481751318315973 *** 2016-12-14 18:04:51.094 CLOSE #140535085337488:c=0,e=25,dep=0,type=3,tim=1481753091094976 =====================

我們看到Oracle對這條SQL語句進行分析，並且有一個游標號：CURSOR #140535085375432 ， 這個號在整個trace文件中並不是唯一的，當一條SQL語句執行完畢后，這個號會被另外的SQL語句重用。

我們還可以看到這個SQL語句被分析了一次，執行了一次，fetch了一次。

如果有多次，這里會有多條記錄。

STAT #140535085375432 是對這條SQL語句執行過程中的資源消耗的統計，trace文件中信息的輸出順序就是SQL的執行順序，通過這些順序就可以了解到SQL語句是如何一步一步的執行的。

---

下面對里面的一些指標信息進行注釋下，以便更好的理解原始的TRACE文件。

PARSING IN CURSOR 部分

len=138: 被分析SQL的長度 
dep=0 :產生遞歸SQL的深度 
uid=49 :user id 
oct=3 :Oracle command type 命令的類型 
lid=49 : 私有的用戶id 
tim=1481751318263300 :時間戳 
hv=3651439770 :hash value 
ad=’1c3714c98’ :SQL address 
sqlid=’cjxrhfzcu934u’ : SQL_ID

---

PARSE /EXEC /FETCH部分

c=13000 : 消耗的CPU時間, 
e=12343：elapsed time的操作用時, 
p=0：physical reads 物理讀的次數, 
cr=100：consistent reads 一致性方式讀取的數據塊, 
cu=0：current方式讀取的數據塊, 
mis=1：cursor miss in cache 硬分析的次數, 
r=0：rows處理的行數, 
dep=0：depth遞歸SQL的深度, 
og=1：optimizer goal優化器模式, 
plh=282154677：, 
tim=1481751318263300：時間戳

---

STATS部分

id=2 ：執行計划的行源號 
cnt=3 ：當前行源返回的行數 
pid=1 ：當前行源號的父號 
pos=1 ：執行計划中的位置 
obj=0 ：當前操作的對象id(如果當前行原始一個對象的話) 
op=’NESTED LOOPS ：當前行源的數據訪問操作