可觀測(cè)性能力是IT運(yùn)維的強(qiáng)有力的支撐。日志告警、指標(biāo)是兩種在運(yùn)維中很常用的可觀測(cè)性指標(biāo)。而對(duì)于數(shù)據(jù)庫(kù)這樣復(fù)雜的IT組件來(lái)說(shuō)，有時(shí)候僅僅依靠日志和指標(biāo)還是不夠的。

跟蹤是解決數(shù)據(jù)庫(kù)復(fù)雜問(wèn)題的十分常用和有效的方法。今年的openGauss 開(kāi)發(fā)者大會(huì)上，華為的黃凱耀分享的案例就是使用了eBPF進(jìn)行跟蹤，最終精準(zhǔn)定位了一個(gè)比較復(fù)雜的性能問(wèn)題。在跟蹤方面，國(guó)產(chǎn)數(shù)據(jù)庫(kù)與Oracle等傳統(tǒng)商用國(guó)數(shù)據(jù)庫(kù)還有這很大的技術(shù)差距。做好跟蹤并不容易，讓運(yùn)維人員或者售后服務(wù)人員能夠很方便的跟蹤數(shù)據(jù)庫(kù)的某種運(yùn)行行為可以幫助提升運(yùn)維，加快BUG定位。

Oracle提供了十分強(qiáng)大的分析功能，特別是EVENT設(shè)置。我剛剛開(kāi)始學(xué)習(xí)Oracle不久，就學(xué)會(huì)了使用event 10046去跟蹤SQL語(yǔ)句的執(zhí)行。這對(duì)于我剛剛開(kāi)始接觸Oracle這個(gè)黑匣子的說(shuō)話幫助巨大。在缺乏必要的資料，甚至連一個(gè)METALINK賬號(hào)都沒(méi)有的時(shí)期，學(xué)習(xí)Oracle數(shù)據(jù)字典的基本原理，以及數(shù)據(jù)庫(kù)啟動(dòng)時(shí)的主要?jiǎng)幼鞯龋际峭ㄟ^(guò)10046 trace文件完成的。后來(lái)也經(jīng)常使用10046/10053等事件分析，來(lái)解決用戶的SQL語(yǔ)句性能問(wèn)題。后來(lái)我學(xué)習(xí)一些Oracle新特性的說(shuō)話，還是經(jīng)常會(huì)使用event做一些trace。

前兩天研究了一下Oracle的LGWR worker新機(jī)制，我后來(lái)也問(wèn)了一些客戶，在一些系統(tǒng)規(guī)模不是很大的場(chǎng)景，好像客戶都沒(méi)有感受到這個(gè)新的變化。也有寫(xiě)負(fù)載較大的用戶遇到了LOG FILE SYNC延時(shí)過(guò)高的問(wèn)題，后來(lái)通過(guò)將LGWR改為原來(lái)的寫(xiě)模式解決了問(wèn)題。于是我昨天寫(xiě)了一篇相關(guān)的文章，猜測(cè)了一下Oracle實(shí)現(xiàn)這個(gè)功能的原理。當(dāng)天下午和一個(gè)朋友聊起這個(gè)事情，他希望我能夠進(jìn)一步確認(rèn)一下我的猜測(cè)是否靠譜。在網(wǎng)上能夠找到的資料極少，于是我只能再次使用起5、6年沒(méi)用過(guò)的跟蹤大法來(lái)做一個(gè)分析。

分析Oracle數(shù)據(jù)庫(kù)的后臺(tái)進(jìn)程功能有一種十分常用的方法，這個(gè)是我從Poder大師那邊學(xué)來(lái)的。結(jié)合10046和LINUX的strace，可以比較清晰的分析Oracle后臺(tái)進(jìn)程的一些行為。因?yàn)?0046中會(huì)輸出某個(gè)會(huì)話執(zhí)行過(guò)的SQL語(yǔ)句，產(chǎn)生過(guò)的各種等待事件，利用這個(gè)TRACE上的時(shí)間戳，結(jié)合strace對(duì)于調(diào)用堆棧的跟蹤，就很容易進(jìn)行問(wèn)題定位了。這個(gè)方法歸納起來(lái)很簡(jiǎn)單：首先對(duì)需要跟蹤的后臺(tái)進(jìn)程設(shè)置8級(jí)的10046 TRACE，然后開(kāi)啟壓測(cè)腳本，同事啟用strace對(duì)調(diào)用堆棧進(jìn)行跟蹤就可以了。我們來(lái)看看這個(gè)完整的過(guò)程。

首先我們找到要跟蹤的進(jìn)程，我們準(zhǔn)備跟蹤lgwr和lg00。然后分別針對(duì)這兩個(gè)進(jìn)程設(shè)置10046 trace。

在兩個(gè)窗口中分別通過(guò)oradebug設(shè)置好之后。我們就可以啟用一個(gè)壓測(cè)工具slob去產(chǎn)生一些寫(xiě)負(fù)載了。為了減少跟蹤的日志量，我們把slob設(shè)置為1個(gè)進(jìn)程，并且只啟動(dòng)一個(gè)并發(fā)。

啟動(dòng)好壓測(cè)負(fù)載后，我們就可以分別在兩個(gè)窗口中對(duì)lgwr/lg00進(jìn)行strace跟蹤了：

對(duì)于strace不太熟悉的朋友我可以解釋一下，-T -tt是在每個(gè)調(diào)用前顯示時(shí)間戳，-s是對(duì)于每個(gè)調(diào)用的數(shù)據(jù)，最多顯示512字節(jié)。-p -o我就不解釋了，估計(jì)地球人都明白。跑上幾十秒鐘后，我們就可以停止跟蹤了，因?yàn)榇蟛糠值男袨槎际诸愃疲瑳](méi)必要跑太久。

我們先來(lái)看看lg00的strace跟蹤信息，因?yàn)槲壹由狭?s參數(shù)，因此在trace里可以看到所有寫(xiě)入lg00 trace文件的數(shù)據(jù)的前面512字節(jié)。因此我不需要去查看orcl1_lg00_15626.trc文件了。

上面這段trace的開(kāi)始是lg00完成了一個(gè)日志寫(xiě)入的工作，進(jìn)入Idle等待狀態(tài)。隨后就收到了寫(xiě)任務(wù)，開(kāi)始寫(xiě)入REDO文件，大家注意看因?yàn)槭褂昧水惒絀O，因此lg00通過(guò)io_submit來(lái)提交IO。我們往下看，可以發(fā)現(xiàn)lg00隨后發(fā)生了ASM IO for non-blocking poll等待，這是因?yàn)橄駻SM發(fā)出了IO。然后lg00產(chǎn)生了我們熟悉的log file parallel write等待。到收到io_getevents為止，異步寫(xiě)完成。于是lg00記錄了log file parallel write等待完成。

從日志中我們可以梳理出一個(gè)大致的脈絡(luò)。可以看出在Oracle等待事件的統(tǒng)計(jì)時(shí)長(zhǎng)與實(shí)際情況并不完全一致。事實(shí)上數(shù)據(jù)庫(kù)也沒(méi)必要十分精確的統(tǒng)計(jì)等待時(shí)長(zhǎng)，只要是一個(gè)大致的就足夠了。只要誤差都是差不多的，對(duì)于實(shí)際分析來(lái)說(shuō)并沒(méi)有太大的問(wèn)題。

我們?cè)賮?lái)看看lgwr的相關(guān)時(shí)段的跟蹤信息。為了方便查看，我梳理了一個(gè)表格，從中可以看出整個(gè)過(guò)程。

我們先來(lái)看lgwr，收到寫(xiě)請(qǐng)求后，找到了一個(gè)空閑的worker，然后發(fā)出寫(xiě)任務(wù)。同時(shí)發(fā)現(xiàn)所有的worker都處于忙的狀態(tài)。此時(shí)正好沒(méi)有寫(xiě)任務(wù)，于是發(fā)出一個(gè)本地IPC消息，等待ipc消息回復(fù)。

而lg00收到寫(xiě)任務(wù)后，首先異步提交了IO，然后產(chǎn)生了一系列預(yù)期的寫(xiě)日志的等待。完成后先通知lgwr，然后再給等待著發(fā)通知。這個(gè)算法是比較合理的，由lg00直接發(fā)消息給log file sync等待的會(huì)話，而不是通過(guò)lgwr，這樣會(huì)有更高的效率。和我由lgwr發(fā)消息，lgwr worker無(wú)阻塞寫(xiě)的想法不一致。二者可能在面對(duì)不同場(chǎng)景時(shí)各有優(yōu)勢(shì)，到底哪種更好也不太好判斷，也不在我們今天討論的范圍內(nèi)。今天我們重點(diǎn)要介紹的是跟蹤數(shù)據(jù)庫(kù)后臺(tái)進(jìn)程行為的方法。