云和恩墨大講堂一條執(zhí)行時間小于1秒SQL引發(fā)性能問題

某客戶軟件操作人員反應很慢不能操作，管理人員登錄小機系統(tǒng)后發(fā)現(xiàn)CPU使用到了96%，而且這種情況持續(xù)了幾個月。以下是登錄后小機后載取的topas圖，而且是周末，并沒有什么人使用系統(tǒng)。小機是IBM的550，配置是2顆6核的CPU，內(nèi)存是48G。從nmon收集的磁盤IO來看在快照時間段(15:00到16:00)之間的磁盤IO并因為不在現(xiàn)場，要客戶的管理員登錄數(shù)據(jù)庫執(zhí)行以下來查看當前數(shù)據(jù)庫消耗CPU最多的進程在執(zhí)行什么。從上面的查詢結果可以看到等待為kksfbcchildcompletion，SQLID從上面的查詢結果可以看到等待變成了ksdxexeotherwait，SQLIDkksfbc意為K[Kernel]K[Kompile]S[Shared]F[Find]B[Best]C[Child]該函數(shù)用于在軟解析時找尋合適的子游標，在10.2.0.2以后引入了mutex互斥體來取代原有的CursorPin機制，Mutex較Latch更為輕量級。雖然mutex的引入改變了眾多cursorpin的內(nèi)部機制，但kksfbc仍需要持有l(wèi)ibrarycachelatches才能掃描librarycachehashchains。另一方面當kksfbc函數(shù)針對某個parentcursor找到合適childcursor后，可能使用KKSCHLPINx方法將該childcursorpin住，這個時候就需要exclusive地持有該childcursor相應的mutex。當有一個進程執(zhí)行kksfbc，而其他進程可能需要陷入‘kksfbcchildcompletion’等待中。SQL_ID(063cu7y841kmc不存在高版本游標，因此出現(xiàn)kksfbcchildcompletion，ksdxexeotherwait如是我猜測會不會是BUG引起的，以KKSFBCCHILDCOMPLETION為關鍵字到MOS查詢找到<Bug –Sessionspins/OERIafter‘kksfbcchildcompletion’wait–superceded[ID .8]>，該Bug的癥狀為進程不斷spin且hang住、出現(xiàn)‘KKSFBCCHILDCOMPLETION’等待、還可能伴有‘Waitsfor“cursor:pinS”’等待，直接影響的版本有11.1.0.6、10.2.0.3和10.2.0.4。而我這里的版本是10.2.0.1，所以需要對于該Bug的描述是在發(fā)生‘kksfbc pletion’等待后會話陷入無休止的自旋(spins)中，這種自旋(spins)發(fā)生在由堆棧調(diào)用(stackcall)kksSearchChildList->kkshgnc陷入對kksSearchChildList函數(shù)的SQL>oradebugsetospidOraclepid:40,Unixprocesspid:90116,image:oracleorcl@dbservSQL>oradebugunlimit;SQL>oradebugksdxfstk+002c<-ksdxcb+04e4<-sspuser+0068<- <-kksfbc+0bb0<- <-startSQL>oradebugdumpprocessstate10;Statementprocessed.SQL>oradebugdumpsystemstate266;Statementprocessed.SQL>oradebug ab188,type:4,owner:70000014346c5a8,flag:INIT/-/-/0x00(session)sid:1020trans:0,creator:70000014346c5a8,flag:(41)USR/-BSY/-/-/-/-/-,short-termDID:txnbranch:oct:0,prv:0,dcf10,ac0c8,user:O/Sinfo:user:gtp-default,term:WIN-AUQ43P0UU9L,ospid:6708:12196,machine:program:lastwaitfor'kksfbcchildcompletion'blockingsess=0x0seq=2831wait_time=48850secondssincewaitstarted=572057=0,=0,DumSessionWait=0,=0,從以上trace內(nèi)容中紅色部分信息可以看到會話確實曾長時間處于‘kksfbcpletion’等待中，之后陷入無限自旋（spins）中消耗了大量時間。但這里實際的表現(xiàn)又存有差異，無限循環(huán)的函數(shù)是kksfbc而不kksSearchChildList（常規(guī)的調(diào)用序列是：kksParseCursor->kkspsc0-從前面的信息是Oracle的BUG的可能性極大。Oracle在10.2.0.4上提供了該Bug的one-offPatch ，其在10.2.0.4psu4以后的等價補丁為(Equivalentpatch)為mergepatch Bothfixesareneeded. supercededby whichincludesextrafilessomaycause s。但merge目前僅有Linuxx86/64平臺上的版本，而問題數(shù)據(jù)庫所在平臺為IBMAIXonPOWERSystems(64-bit)，而且版本是10.2.0.1。那么要解決這個問題是不是沒有辦法了，其實不然，我們可以將數(shù)據(jù)庫從10.2.0.1升級到loadprofilesql從上面的top等待來看主要是CPUtime，而logfilesync的平均等待時間是6ms，logfileparallelwrite的平均等待時間是7ms，logfilesync的平均等待時間是6ms，controlfileparallelwrite的平均等待時間是13ms。這些等待占TotalCallTime的時間百分比都在百分之一以下，而且這些等待都屬于SystemI/O，與升級之前對比并沒有什么變化。ADDM是植入Oracle數(shù)據(jù)庫的一個自診斷引擎。ADDM通過檢查和分析AWR獲取的數(shù)據(jù)來判斷Oracle數(shù)據(jù)庫中可能存在的問題，然后ADDM會定AWR快照（默認一小時一次）后，將會執(zhí)行一次ADDM分析，分析結果存ADDM分析的執(zhí)行是從上到下的。首先確定狀況，然后分析找到性能問題的根源。ADDM是用DBtime統(tǒng)計來確定性能問題的。DBtime是數(shù)據(jù)庫處理sessionCPU時間。性能診斷的目標就是對于特定的工作量減少系統(tǒng)的DBtime，通過減少DBtime，數(shù)據(jù)庫使用同樣的資源能夠支撐的用戶請求。ADDM報告的問題區(qū)域指的就是顯著占用了DBtime的系統(tǒng)資源，它們是按照相關的DBtime按從大到小的順序列出的。除了診斷性能問題，ADDM也會建議可能的解決方案，可以的話，ADDM會推薦多種方案供選擇。ysisPeriod:20-DEC-2015from09:00:33to10:00:34 HostName:dbservSnapshotRange:from26245to26246DatabaseTime:16644secondsAverageDatabaseLoad:4.6activeFINDING1:93%impact(15444SQLstatementsconsumingsignificantdatabasetimeMENDATION1:SQLTuning,100%benefit(38004seconds)ACTION:RunSQLTuningAdvisorontheSQLstatementwithSQL_IDRELEVANTOBJECT:SQLstatementwithSQL_IDfb44z8kbnu8wgandSELECTCOUNT(Detail.F__DETAIL_ID)ASUnReadCountFROMT_LK__GROUPGroupLEFTOUTERJOINT_LK__DETAILIDAND(Detail.F_RECEIVER_ID=:param0OR Detail.F_SENDER_ID=:param0AND Detail.F_RECEIVER_IDISNULL))ANDDetail.F__STATE='0'ANDDetail.F_RECORD_STATE='0'WHEREGroup.F_PARENT_ID=0AND ACTION:InvestigatetheSQLstatementwithSQL_ID"fb44z8kbnu8wg"forpossibleperformanceimprovements.RELEVANTOBJECT:SQLstatementwithSQL_IDfb44z8kbnu8wgandSELECTCOUNT(Detail.F__DETAIL_ID)ASUnReadCountFROMT_LK__GROUPGroupLEFTOUTERJOINT_LK__DETAILDetailONGroup.F__GROUP_ID=Detail.F__GROUP_IDAND(Detail.F_RECEIVER_ID=:param0OR(Detail.F_SENDER_ID=:param0ANDDetail.F_RECEIVER_IDISNULL))ANDDetail.F__STATE='0'ANDDetail.F_RECORD_STATE='0'WHEREGroup.F_PARENT_ID=0AND Group.F__GROUP_ID!=4OR( RATIONALE:SQLstatementwithSQL_ID"fb44z8kbnu8wg"wasexecuted16029timesandhadanaverageelapsedtimeof0.93seconds.FINDING2:76%impact(12602TimespentontheCPUbytheinstancewasresponsibleforasubstantialpartofdatabasetime.MENDATION1:SQLTuning,100%benefit(38004seconds)ACTION:RunSQLTuningAdvisorontheSQLstatementwithSQL_IDRELEVANTOBJECT:SQLstatementwithSQL_IDfb44z8kbnu8wgandSELECTCOUNT(Detail.F__DETAIL_ID)ASUnReadCountFROM GroupLEFTOUTERJOINT_LK__DETAILDetailON IDAND( Detail.F_RECEIVER_ID=:param0OR Detail.F_SENDER_ID=:param0AND Detail.F_RECEIVER_IDISNULL))AND Detail.F__STATE='0'AND ACTION:InvestigatetheSQLstatementwithSQL_ID"fb44z8kbnu8wg"forpossibleperformanceimprovements.RELEVANTOBJECT:SQLstatementwithSQL_IDfb44z8kbnu8wgandSELECTCOUNT(Detail.F__DETAIL_ID)ASUnReadCountFROMT_LK__GROUPGroupLEFTOUTERJOINT_LK__DETAILDetailONGroup.F__GROUP_ID=Detail.F__GROUP_IDAND(Detail.F_RECEIVER_ID=:param0OR(Detail.F_SENDER_ID=:param0ANDDetail.F_RECEIVER_IDISNULL))ANDDetail.F__STATE='0'ANDDetail.F_RECORD_STATE='0'WHEREGroup.F_PARENT_ID=0AND Group.F__GROUP_ID!=4OR( RATIONALE:SQLstatementwithSQL_ID"fb44z8kbnu8wg"wasexecuted16029timesandhadanaverageelapsedtimeof0.93seconds.Waitclass"Application"wasnotconsumingsignificantdatabasetime.Waitclass"Commit"wasnotconsumingsignificantdatabasetime.Waitclass"Concurrency"wasnotconsumingsignificantdatabasetime.Waitclass"Configuration"wasnotconsumingsignificantdatabasetime.Waitclass"Network"wasnotconsumingsignificantdatabasetime.Waitclass"UserI/O"wasnotconsumingsignificantdatabaseSessionconnectanddisconnectcallswerenotconsumingsignificantdatabaseHardparsingofSQLstatementswasnotconsumingsignificantdatabasetime.Thedatabase'smaintenancewindowswereactiveduring99%oftheysis ysisofI/Operformanceisbasedonthedefaultassumptionthattheaveragereadtimeforonedatabaseblockis10000micro-seconds.Anexnationoftheterminologyusedinthisreportisavailablewhenyourunthereportwiththe'ALL'levelofdetail.2624526246DatabaseTime16644秒。而找到的一條SQL消耗了76%的CPU時間。如果對這兩條SQL執(zhí)行優(yōu)消耗的CPU時間有0.76秒。FROMT_LK__GROUP Detail.F__STATE='0' Group.F_PARENT_ID=AND(Group.F__GROUP_ID!=4OR(Group.F_GROUP_TYPE='USER'ANDGroup.F_USER_ID=23402));nestedloopsouter對進行優(yōu)化就需要對Oracle表連接的類型與方法有所了解。那么這里就介紹外連接（outerjoin）是對內(nèi)連接的一種擴展，它是指表連接的連接結果除了左連接（leftouterjoin）1leftouterjoin2on（連接條件）1leftouterjoin2using（連接列集合“目標表1leftouterjoin目標表2on（連接條件）”的含義為目標表1和目標表2按括號中的連接條件來做表連接，位于關鍵字“l(fā)eftouterjoin”左邊的目標表1會作為該表連接的驅動表（關鍵字“l(fā)eftouter”即表明位置處于left的表就是outertable，這里的outertable就是指驅動表）。此時的12包含驅動表（即目標表1）中所有不滿足該連接條件的記錄，同時，驅動表中 會以NULL值來填充。1rightouterjoin2on或1rightouterjoin2using“目標表1rightouterjoin2on（連接條件）1和2“rightouterjoin”右邊的目標表2會作為該表連接的驅動表（“rightouterjoin”中的關鍵字“rightouter”即表明位置處于right的表就是outertable，即驅動表）。還會包含驅動表（即目標表2）中所有不滿足該連接條件的記錄，同時，驅動表中所有不滿足該連接條件的記錄所對應的被驅動表（即目標表1）中的查詢列均會以NULL值來填充。全連接（fullouter1fullouterjoin2on（連接條件）1fullouterjoin2using（連接列集合“目標表1fullouterjoin目標表2on（連接條件）”的含義為目標表1和2和目標表21和目標表12連接條件的記錄所對應的另一個表中的查詢列均會以NULL值來填充。如果兩個表（這里將它們分別命名為表t1和表t2）在做表連接時使用的是嵌套循環(huán)連接，則Oracle會依次順序執(zhí)行如下步驟。首先，優(yōu)化器會按照一定的規(guī)則來決定表t1和t2中誰是驅動表，誰是被驅動表。驅動表用于外層循環(huán)，被驅動表用于內(nèi)層嵌循環(huán)。這里假設驅動表是t1，被驅動表是t2。接著以目標SQL中指定的謂詞條件（如果有的話）去表t1，驅動然后遍歷驅動結果集1并同時遍歷被驅動表t2，即先取出驅動結果集1中的第1條記錄，接著遍歷被驅動表22然后再取出驅動結果集1中的第2條記錄，按照同樣的連接條件再去遍歷被驅動表t2t21中所有的記錄為止。這里的外層循環(huán)是指遍歷驅動結果集1所對應的循環(huán)，內(nèi)層循環(huán)是指遍歷被驅動表t2所對應的循環(huán)。顯然，外層循環(huán)所對應的驅動結果集1有多少條記錄，遍歷被驅動表t2的內(nèi)層循環(huán)就要做多少次，這就是所謂的“嵌套動結果集是在對驅動表應用了目標SQL中指定的謂詞條件（如果有的話）后得到的結果集，所以大表也可以作為嵌