技術(shù)人生系列-我和數(shù)據(jù)中心的故事（第五期）清算/報(bào)表/日終跑批程序之性能優(yōu)化案例

前言

不知不覺，技術(shù)人生系列·我和數(shù)據(jù)中心的故事來到了第五期。小y又和大家見面了！

前幾期主要發(fā)了一些TroubleShooting的案例分享，其實(shí)小y最擅長的是性能優(yōu)化，所以從這期開始，小y會(huì)陸續(xù)的分享更多的數(shù)據(jù)庫性能優(yōu)化案例。

進(jìn)入正題，如果您的日終跑批 / 清算 / 報(bào)表等程序時(shí)快時(shí)慢，或者從某一天以后就一直變慢，作為運(yùn)維 DBA 或開發(fā)的您，會(huì)怎么下手？ 還有，除了解決問題外，你要如何解答領(lǐng)導(dǎo)最關(guān)心的一個(gè)問題，“為什么現(xiàn)在有問題，但是以前沒有問題呢”！

小 y 今天要和大家分享的就是這樣一個(gè)性能問題的分析和解決過程。

你們的點(diǎn)贊和轉(zhuǎn)發(fā)就是小 y 繼續(xù)堅(jiān)持分享的動(dòng)力。

更多Oracle數(shù)據(jù)庫實(shí)戰(zhàn)經(jīng)驗(yàn)分享的首發(fā)，盡在“中亦安圖”公眾號(hào)！歡迎關(guān)注。

另外，前陣子有部分朋友問，小y所在的團(tuán)隊(duì)是否可以提供對(duì)外的第三方Oracle服務(wù)，答案是YES！

有興趣的朋友可以加一下小y的個(gè)人微信，微信號(hào)是 shadow-huang-bj,希望可以交到更多的朋友，并幫助到更多有需要的人。

小y,有空么？一會(huì)一起看一個(gè)報(bào)表的性能問題。

 有個(gè)SQL語句一周前開始，性能急劇惡化，執(zhí)行時(shí)間從10分鐘以內(nèi)變成了10個(gè)小時(shí)以上。

剛在客戶現(xiàn)場(chǎng)做完Oracle的培訓(xùn)，問題來的正是時(shí)候，剛好可以讓客戶感受下理論如何融入實(shí)戰(zhàn)的魅力！小y的第一想法是SQL語句的執(zhí)行計(jì)劃發(fā)生了改變，通常從統(tǒng)計(jì)信息或者CBO對(duì)cardinality的估算情況中就可以快速找到線索，應(yīng)該很快就可以查明原因并解決！

環(huán)境介紹：

操作系統(tǒng) Redhat 64 bit

數(shù)據(jù)庫   Oracle 11.2.0.3 ,  2節(jié)點(diǎn)RAC

小y對(duì)這條SQL進(jìn)行了敏感信息處理和寫法的簡(jiǎn)化處理，可以看到：

?  該SQL對(duì)兩張表張進(jìn)行join，然后group by

?  參與關(guān)聯(lián)的兩張表一張是80M的小表，另外一張是3.5G的較大一些的表。記錄數(shù)分別是160萬和800萬

? SQL語句用了hint，提示優(yōu)化器表連接走h(yuǎn)ash join,單表訪問路徑小表走全表掃描。

這樣的一條SQL，按照小y的經(jīng)驗(yàn)，驅(qū)動(dòng)表只要選擇小表，那么整個(gè)HASH JOIN的執(zhí)行時(shí)間基本等同于兩張表的單表訪問時(shí)間，兩張表加起來不到4G，通常都可以在5分鐘內(nèi)完成。這和客戶描述的以前的執(zhí)行時(shí)間是相吻合的。

這里順便說一下：

很多開發(fā)寫 hint 往往寫的不完整，例如這個(gè) hint 只寫了表連接方式，單表訪問路徑只寫了一張表，表的連接順序沒有寫，其實(shí)并沒有完全固定死執(zhí)行計(jì)劃。

接下來，小y將查看執(zhí)行計(jì)劃是否發(fā)生變化，還有執(zhí)行計(jì)劃是否正確。

可以看到：

?  執(zhí)行計(jì)劃（oracle內(nèi)部的算法）確實(shí)如hint一樣

?  表連接方式走的是hash join

?  單表訪問路徑都是全表掃描(table access full)

?  表連接順序是小表做驅(qū)動(dòng)表(hash內(nèi)存表）

可以看到：

1、  每次執(zhí)行時(shí)間39615秒，超過10個(gè)小時(shí)

2、  每次執(zhí)行邏輯讀只有45276個(gè)block（塊）

3、  每次執(zhí)行物理讀451421個(gè)block（塊）

4、  時(shí)間基本都消耗在CPU上，達(dá)到38719秒，超過10個(gè)小時(shí)，而在IO/集群/應(yīng)用（鎖）/并發(fā)環(huán)節(jié)消耗時(shí)間很小

到了這里，經(jīng)驗(yàn)豐富的DBA應(yīng)該可以發(fā)現(xiàn)，該CASE出現(xiàn)了一些奇怪的現(xiàn)象。

不過還是要照顧一下大家，先來回答一些朋友心里可能的問題。

看到這里，也許有人會(huì)說:

是不是SQL語句執(zhí)行過程中有什么異常的等待事件？

也許有人會(huì)說：

執(zhí)行計(jì)劃出現(xiàn)了temp表空間的使用，是不是hash join One-pass/Muti-pass導(dǎo)致SQL執(zhí)行慢

答案是NO！

首先，執(zhí)行計(jì)劃中顯示會(huì)用到temp表空間(hash join one-pass/muti-pass)，這是CBO執(zhí)行前的評(píng)估而已，實(shí)際執(zhí)行很可能根本不會(huì)使用。

到這里，小y開始感覺到了這個(gè)case需要更專注來解決了！

執(zhí)行時(shí)間基本都耗在CPU上，這通常意味著所需要的數(shù)據(jù)基本都在內(nèi)存中。

一個(gè)常識(shí)是，如果所需要的BLOCK在內(nèi)存中，那么 CPU每秒可以處理10萬甚至幾十萬的邏輯讀！

但具體到這條SQL， 10的小時(shí)的CPU時(shí)間，處理的邏輯讀，才有45萬！

45萬的邏輯讀剛好對(duì)應(yīng)4G的大小，即兩張表的大小之和。

目前確實(shí)有一些奇怪的地方，小y接下來需要：

?  和歷史執(zhí)行時(shí)間的分解進(jìn)行比對(duì)

?  將這條SQL語句重新跑起來，獲取更多的線索。

可以看到：

?  一開始的時(shí)候，每個(gè)小時(shí)還可以處理44萬的邏輯讀，但是后來就慢了起來

?  后來的絕大部分時(shí)間里，每個(gè)小時(shí)才處理1000-3000的邏輯讀

?  執(zhí)行時(shí)間確實(shí)都在CPU上！

將這條SQL語句重新跑起來，然后開啟其他窗口觀察，一開始的1分鐘內(nèi)還算正常，先后讀取小表和大表，IO差不多到每秒30M，然后IO就急劇的下降了，這個(gè)時(shí)候等待事件是ON CPU。

小y立馬查看了SQL的執(zhí)行進(jìn)度，v$session_longops中表SMALL_TABLE已經(jīng)掃描完成，但另外一張表BIG_TABLE全表掃描的進(jìn)度進(jìn)本停留在82%的位置！但細(xì)看還是漲的，只是漲的比較慢！如下圖所示。

對(duì)BIG_TABLE的全表掃描，sofar基本上每5秒才漲1 ！

按照這個(gè)速度，還需要（442460-362690）*5=40萬秒，即10個(gè)小時(shí)以上！這和“歷史執(zhí)行情況比對(duì)和確認(rèn)”章節(jié)是可以對(duì)上的！

這里提示一下，漲的慢和IO性能沒關(guān)系，上面已經(jīng)分析過了，時(shí)間都消耗在CPU上

接下來，讀者朋友們，可以停一下，把上述現(xiàn)象總結(jié)一下，再思考個(gè)幾分鐘、

如果是您來接這個(gè)CASE，你會(huì)怎么繼續(xù)往下查呢？

↓

↓

↓

↓

↓

↓

↓

↓

↓

不要走開后邊還有.....

既然SQL執(zhí)行是在CPU上，那么就不會(huì)有什么等待事件的線索留出來，既然在CPU上，那么必然要去看call stack,這是小y多年養(yǎng)成的習(xí)慣了。

通過oradebug short_stack,間隔幾秒抓取了三次。如下圖所示：

到了這里，小y已經(jīng)做完了所有的檢查。

是時(shí)候出去抽一根煙了，需要把所有發(fā)現(xiàn)的線索在腦子里過一次。

幸運(yùn)的是，一根煙后，小y終于把所有問題都想明白了，所有看到的現(xiàn)象都可以說清楚了,還有領(lǐng)導(dǎo)最關(guān)心的一個(gè)問題—“為什么現(xiàn)在有問題，但是以前沒有問題呢”！，小y也有了答案。

建議朋友們，讀到這里也可以先停一下，思考個(gè)幾分鐘，看看自己是否已經(jīng)找到了問題原因。

到這里已經(jīng)找到答案的朋友，可以發(fā)小y發(fā)一份簡(jiǎn)歷，說明你有不錯(cuò)的思考能力和經(jīng)驗(yàn)！歡迎你加入中亦科技Oracle服務(wù)團(tuán)隊(duì)！簡(jiǎn)歷請(qǐng)發(fā) 51994106@qq.com

在出門抽煙的這一小會(huì)功夫里，小y不斷思考著幾個(gè)問題。

?  為什么每個(gè)小時(shí)才處理幾千個(gè)邏輯讀呢？

?  SQL執(zhí)行時(shí)間都消耗在CPU上，都在做什么呢？

?  為什么以前不出，現(xiàn)在出呢？

因此，小y重新縷了一下Hash Join原理，例如兩張表A和B表的整表關(guān)聯(lián)

SELECT * FROM A,B

WHERE A.ID=B.ID

ORACLE內(nèi)部的執(zhí)行過程，可以簡(jiǎn)化為：

?  SCAN A（掃描A表）

?  HASH(A.ID),打散到各個(gè)桶（BUCKET）中，呆在pga hash area中等待別人來匹配

?  SCAN B（掃描B表）

?  HASH(B.ID)

?  到相應(yīng)的Bucket中，比較表關(guān)聯(lián)字段的值是否相同，返回或丟棄

HASH的目的是為了打算數(shù)據(jù)到各個(gè)桶中。每個(gè)算法都有優(yōu)缺點(diǎn)。

那么HASH JOIN有什么缺點(diǎn)呢？

我們是否命中了該缺點(diǎn)呢？！

被驅(qū)動(dòng)表一個(gè)BLOCK可以存儲(chǔ)幾十到幾百條記錄，而一條記錄需要到一個(gè)記錄很多的桶里去比較很久，被驅(qū)動(dòng)表一個(gè)BLOCK有很多條記錄，自然就出現(xiàn)了每個(gè)小時(shí)只能處理幾千個(gè)邏輯讀的情況了！也就觀察到了v$session_longops.sofar漲的很慢的情況了！

同時(shí)，關(guān)聯(lián)字段大量比較的過程是很消耗CPU的 （當(dāng)驅(qū)動(dòng)表讀進(jìn)PGA里后就呆在PGA內(nèi)存中了）

在SQL語句中加入small_table.id != 0的過濾條件，small_table的數(shù)據(jù)從160萬減少到143萬，變化不大的情況下，執(zhí)行上述SQL，執(zhí)行時(shí)間在3分鐘左右就完成了！

這就驗(yàn)證了hash join不適合驅(qū)動(dòng)表表關(guān)聯(lián)字段分布不均勻的一個(gè)缺點(diǎn) ！

知道原因了，那么解決方案就多種多樣了！

hash join不適合驅(qū)動(dòng)表表關(guān)聯(lián)字段分布不均勻的情況，因此解決方案有多種

1）  采用use_merge的hint而非use_hash，無法修改程序的情況可以通過sql profile指定執(zhí)行計(jì)劃。這里兩張表都不大，排序合并連接也很快。

2）  對(duì)驅(qū)動(dòng)表small_table.id=0的數(shù)據(jù)進(jìn)行調(diào)查、確認(rèn)和處理，為什么會(huì)在某一天突然出現(xiàn)大量id=0的數(shù)據(jù)，是否可以刪除

……

可以看到：

?  掌握原理是必須的

?  什么樣的架構(gòu)、算法和存儲(chǔ)結(jié)構(gòu)決定了他可以做什么樣的事情，不可以做什么樣的事情

?  但你思考過他的缺點(diǎn)是什么么？以前沒有的話，小y建議嘗試，讓你有更多收獲