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

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

Oracle提供了十分強(qiáng)大的分析功能，特別是EVENT設(shè)置。我剛剛開始學(xué)習(xí)Oracle不久，就學(xué)會了使用event 10046去跟蹤SQL語句的執(zhí)行。這對于我剛剛開始接觸Oracle這個黑匣子的說話幫助巨大。在缺乏必要的資料，甚至連一個METALINK賬號都沒有的時(shí)期，學(xué)習(xí)Oracle數(shù)據(jù)字典的基本原理，以及數(shù)據(jù)庫啟動時(shí)的主要動作等，都是通過10046 trace文件完成的。后來也經(jīng)常使用10046/10053等事件分析，來解決用戶的SQL語句性能問題。后來我學(xué)習(xí)一些Oracle新特性的說話，還是經(jīng)常會使用event做一些trace。

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

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

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

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

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

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

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

上面這段trace的開始是lg00完成了一個日志寫入的工作，進(jìn)入Idle等待狀態(tài)。隨后就收到了寫任務(wù)，開始寫入REDO文件，大家注意看因?yàn)槭褂昧水惒絀O，因此lg00通過io_submit來提交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為止，異步寫完成。于是lg00記錄了log file parallel write等待完成。

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

我們再來看看lgwr的相關(guān)時(shí)段的跟蹤信息。為了方便查看，我梳理了一個表格，從中可以看出整個過程。

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

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