Upload File

Download - Interpreting Wait Events

Transcript

  • InterpretingWaitEventsWhatareWaitEvents?CommonWaitEventsCollectingWaitEventsTracingWaitEvents10gWaitInterfaceEnhanmentsEventWaitAnalysiswithStatspackHowWaitEventscanbeusedtoimproveperformance(withgoodexamples)Moreexampleson10g

    WhatareWaitEvents?

    "WaitEvent"Defined

    Atanygivenmoment,everyOracleprocessiseitherbusyservicingarequestorwaitingforsomethingspecifictohappen.By"busy"wemeanthattheprocesswishestousetheCPU.Forexample,adedicatedserverprocessmightbesearchingthebuffercachetoseeifacertaindatablockisinmemory.Thisprocesswouldbesaidtobebusyandnotwaiting.TheARC0process,meanwhile,mightbewaitingforLGWRtosignalthatanonlineredologneedsarchiving.Inthiscase,theARC0processiswaiting.ThekerneldevelopersatOraclehavedefinedalistofeverypossibleeventthatanOracleprocesscouldbewaitingfor.Atanymoment,everyOracleprocessthatisnotbusyiswaitingforoneoftheseeventstooccur.SupposeanapplicationhassubmittedaCOMMITstatementandtheserverprocessiswaitingfortheLGWRprocesstosignalthattheredologbufferhasbeenflushedtodisk.Thiswaiteventiscalled"logfilesync."AnotherdedicatedserverprocessmightbewaitingforarowlevellockontheINVOICEStabletobefreedsothataSELECTFORUPDATEstatementcancontinue.Thatwaiteventiscalled"enqueue."Byqueryingv$views,wecanseewhateventsprocessesarewaitingontoanamazinglevelofdetail.Forexample,wemightlearnthatadedicatedserverprocesshasbeenwaiting30millisecondsfortheoperatingsystemtoreadeightblocksfromdatafile42,startingatblock18042.WecanalsoseesummaryinformationofhowmuchtimeeachOracleprocesshasspentwaitingoneachtypeofwaiteventforthedurationoftheprocess.Inaddition,wecandirectanOracleprocesstowritedetailedwaiteventdatatoatracefileforlateranalysisusingTKPROF.

    WhyWaitEventInformationisUseful

    Usingthewaiteventinterface,youcangetinsightsintowheretimeisbeingspent.Ifareporttakesfourhourstocomplete,forexample,thewaiteventinterfacewilltellyouhowmuchofthatfourhourswasspentwaitingfordiskreadscausedbyfulltablescans,diskreadscausedbyindexlookups,latchcontention,andsoon.Thewaiteventinterfaceprovidesmuchmoreinformationtoworkwiththancachehitratiosdo.YougetdatathatcantouchuponsomanydifferentareasofyourdatabasesuchasdiskI/O,latches,parallelprocessing,networktraffic,checkpoints,androwlevellocking.Atthesametime,yougetincredibledetailsuchasthefilenumberandblocknumberofablockbeingreadfromdisk,orthenameofalatchbeingwaitedonalongwiththenumberofretries.Thewaiteventinterfacewillnotalwaysgiveyoualloftheinformationyouneedinordertodiagnoseandsolveaproblem,butitwillcertainlypointyouintherightdirection.Youmightthinkthebuffercacheistoosmallbecausethecachehitratioisonly70%,butinfact,theapplication'sslowresponsetimecouldbecausedbylatchcontentioninthesharedpool,abottleneckinthelogwriter,oranyofanumberofotherthings.

    PriortoOracle10g,Oracle'sdefaultoptimizermodewascalledchoose.Inthechooseoptimizermode,Oraclewillexecutetherulebasedoptimizeriftherearenostatisticspresentforthetableitwillexecutethecostbasedoptimizerifstatisticsarepresent.ThedangerwithusingthechooseoptimizermodeisthatproblemscanoccurincaseswhereoneOracletableinacomplexqueryhasstatisticsandtheothertablesdonot.StartinginOracle10g,thedefaultoptimizermodeisall_rows,favoringfulltablescansoverindexaccess.Theall_rowsoptimizermodeisdesignedtominimizecomputingresourcesanditfavorsfulltablescans.Indexaccess(first_rows)addsadditionalI/Ooverhead,buttheyreturnrowsfaster.WhenonlysometablescontainCBOstatistics,Oraclewillusethecostbasedoptimizationandestimatestatisticsfortheothertablesinthequeryatruntime.Thiscancausesignificantslowdownintheperformanceoftheindividualquery.

    CommonWaitEventNamesandWhatTheyMean

    Althoughtherearemanydifferenttypesofwaitevents,themajorityofthemcomeupveryinfrequentlyortendnottobesignificant.Inpractice,onlyafewdozenwaiteventstendtobeofinteresttomostDBAs.You'llseedifferentwaiteventssurfacingindifferentenvironmentsbasedonwhichOraclefeatureshavebeenimplementedandwhichcapabilitiesofthedatabasearebeingtaxedthemost.Forexample,thePXwaiteventswon'tappearifyouaren'tusingparallelquery,andthevirtualcircuitstatuswaiteventwon'tappearifyouarenotusingthemultithreadedserverarchitecture(orsharedserverarchitectureasitismorerecentlycalled).Alongthoselines,thelogfilesyncandenqueuewaiteventsprobablywon'tbeprevalentinaprimarilyreadonlysystem.Herearesomeofthemostcommonwaiteventsandwhattheymean:

    Thereareseveralwaiteventsthatwecall"idleevents"becauseeachofthesewaiteventstypicallyoccurswhentheOracleprocesshasnothingtodoandiswaitingforsomebodytogiveitatask.Idleeventsareusuallynotveryinterestingfromatuningstandpoint,soweusuallyoverlookthemwhenevaluatingdataextractedfromthewaiteventinterface.Thecommonidleeventsareasfollows:

    WhatWaitEventInformationDoesNotProvide

    IfanOracleprocesshasworktodobut,mustwaitforsomethingtohappenbeforeitcancontinue,thentheprocesswillbewaitingonanonidlewaitevent.Ifaprocesshasnothingtodo,itwillbewaitingonanidlewaitevent.Sowhathappensifaprocesshasworktodoandisbusydoingit?Whenaprocessisbusy,therewillbenoinformationinthewaiteventinterfacesincetheprocessisnotwaiting.

    WhenwelookatthewaiteventinformationextractedfromanOracleinstance,weseedetailedinformationabouthowmanytimesandhowmuchtimewasspentwaitingforspecificeventstooccur.ButwedonotseeanythingaboutthetimeperiodsinwhichtheprocessrequesteduseoftheCPU.Thismeansthatthewaiteventinterfaceisnotabletoprovideinformationaboutthefollowing:

    l TimespentusingtheCPUl TimespentwaitingforaCPUtobecomeavailablel Timespentwaitingforrequestedmemorytobeswappedbackintophysicalmemory

    Thisisimportanttokeepinmindbecausethereisaneasytraptofallinto.YoucouldbetroubleshootingaveryslowSELECTstatementandlearnfromthewaiteventinterfacethattheprocessdoesnothavesignificantwaiteventswhenrunningthequery.Thiscouldleadyoutothinkthatthestatementisoptimal,andthatitjusttakesalongtimetorun.Infact,however,thequerymightbeperforminghugenumbersoflogicalreadsandthenumberofbuffergetscouldbereducedbyrewritingthequery.

    WhenOracleneedstoaccessadatablockandtheblockisalreadyinthebuffercache,alogicalreadoccurswithnophysicalread.Theprocessisabletoreadtheblockwithouttheoccurrenceofanywaitevents.LargeamountsofCPUtimecouldbeconsumedonsignificantnumbersoflogicalreads,andthewaiteventinterfacewillhavenothingtoshowfortheelapsedtime.Statementparsingandspinningwhilewaitingforalatchtobecomeavailablearetwootherexamplesofactivitiesnotaccountedforbythewaiteventinterface.AnOracleprocessusesCPUtimewhileparsingastatementorspinningonabusylatchsincenowaitingisinvolved,thewaiteventinterfacedoesnothaveanythingtoreport.BeginninginOracle9i,theportionoftheStatspackreportthatlistswaiteventinformationalsolistsCPUusage.Thisisveryhelpfulinformation.Itallowsustoeasilycomparetimespentwaitingtotimespentprocessing,soweknowwheretofocusourtuningefforts.However,itshouldbepointedoutthattheCPUusageinformationinthissectionoftheStatspackreportdoesnotcomefromthewaiteventinterface.Instead,StatspackmergesdatacollectedfromthewaiteventinterfacewithCPUusageinformationcollectedfromthev$sysstatdynamicperformanceview.

    ANoteAboutthetimed_statisticsParameter

    TheOraclekerneliscapableoftimingmanyactivitiesincludingwaitevents.InOracle9iRelease2timedstatisticsarecollectedbydefault,andsometimingsarecollectedinunitsofmicroseconds.Thetimed_statisticsinstanceparameterisusedtoenableanddisabletimedstatisticscollection.Whentimed_statisticsissettoFALSE,alltimesinthewaiteventinterfacewillappearaszero.Youmayenabletimedstatisticscollectionattheinstanceorthesessionlevelwiththefollowingcommands:

    l ALTERSYSTEMSETtimed_statistics=TRUEl ALTERSESSIONSETtimed_statistics=TRUE

    Youmayenabletimedstatisticsattheinstancelevelonthenextandallsubsequentinstancerestartsbyaddingthefollowinglinetotheinstanceparameterfile:

    timed_statistics=true

    Inpractice,theoverheadofcollectingtimedstatisticsisextremelysmall.Inmostcases,thebenefityou'llgetfromhavingtiminginformationatyourdisposalwilloutweightheperformanceoverhead.Forseveralyears,manyDBAshavebeenrunningtheirproductionsystemswithtimedstatisticsenabledatalltimes.WithOracle9iRelease2,thisisnowthedefaultbehavior.

    CollectingWaitEventInformation

    Therearetwocommonwaysofcollectingwaiteventinformation:theOracleextendedtrace(10046event)andusingV$viewswhichisthemaintopicofthisarticle.AnyuserwiththeSELECTANYTABLEsystemprivilegeortheSELECT_CATALOG_ROLErolecanquerythev$views.OnlyuserswhocanconnecttothedatabaseasSYSDBAorexecutetheDBMS_SUPPORTorDBMS_SYSTEMpackagescanactivatewaiteventtracinginotherdatabasesessions.Inatypicalenvironment,DBAshaveaccesstothewaiteventinterfacebutgeneralusersdonot.Oracleprovidesanumberofviewstoaidintuningafeware:*V$SYSTEM_EVENT,whichgivesyoutotalsystemwaitsforaneventsincedatabasestartup.*V$SESSION_EVENT,whichisatthesessionlevel.*V$SESSION_WAITgivesyouwhatanactivesessioniswaitingonatthatpointintime.*V$SESSION,whichgivesyousessioninformationandhasacolumnROW_WAIT_OBJ#thattellsyoutheobjectinvolvedwhenjoinedwithOBJECT_IDorDATA_OBJECT_IDinDBA_OBJECTS.Version10ghassomemoreV$viewsfortrackinghistorycalledV$%_HISTORY,includingV$ACTIVE_SESSION_HISTORY(ASH),whichsamplesnonidlewaiteventseverysecondandnewcolumnsinV$SESSIONtocombineinformationinV$SESSION_WAIT.

    Inadditiontothefourdynamicperformanceviews,Oracleprovidesatracingfacilitywhereextremelydetailedwaiteventinformationiswrittentoatracefileforlaterevaluation.InmorerecentreleasesofOracle,aPL/SQLpackageisprovidedforactivatingthewaiteventtracingfacility.InolderreleasesofOracle,thewaiteventtracingfacilityisactivatedbysettingdebugeventnumber10046(nottobeconfusedwithawaitevent).

    TheV$SYSTEM_EVENTViewThev$system_eventviewshowsonerowforeachwaiteventname,alongwiththetotalnumberoftimesaprocesshaswaitedforthisevent,thenumberoftimeouts,thetotalamountoftimewaited,andtheaveragewaittime.AllofthesefiguresarecumulativeforallOracleprocessessincetheinstancestarted.Waiteventsthathavenotoccurredatleastoncesinceinstancestartupdonotappearinthisview.Thev$system_eventviewhasthefollowingcolumns:

    NameNull?TypeEVENTVARCHAR2(64)TOTAL_WAITSNUMBERTOTAL_TIMEOUTSNUMBERTIME_WAITEDNUMBERAVERAGE_WAITNUMBERTIME_WAITED_MICRONUMBER

    EVENTisthenameofthewaitevent.YoucanseealistofallwaiteventnamesknowntoyourOraclekernelwiththefollowingquery:SELECTnameFROMv$event_nameTOTAL_WAITSisthetotalnumberoftimesaprocesshaswaitedforthiseventsinceinstancestartup.TOTAL_TIMEOUTSisthetotalnumberoftimesaprocessencounteredatimeoutwhilewaitingforanevent.Whenaprocessbeginstowaitforanevent,itspecifiesatimeoutperiodafterwhichtheoperatingsystemshouldwakeitupiftheeventhasnotyettranspired.Forexample,whenanOracleprocessissuesanI/Orequesttoreadablockfromadatafile(thedbfilesequentialreadwaitevent),theprocesssetsatimeoutofonesecond.UsuallytheI/Orequestwillcompleteinlessthanonesecondandnotimeoutwilloccur.Butifthereadshouldtakelongerthanonesecondforwhateverreason,atimeoutwilloccurandtheprocesswillwakeup.Theprocessmightdosomeminorhousekeeping,butitwilllikelyjustbeginanothertimeoutperiodofonesecondandcontinuewaitingforthesameevent.TIME_WAITEDandAVERAGE_WAITshowthecumulative(sum)andaveragetimespentbyprocesseswaitingforthisevent,incentiseconds.Dividethesefiguresby100inordertogetthewaittimeinseconds.Thesetwocolumnswillshowaszeroiftimedstatisticsarenotenabled.TIME_WAITED_MICROisthesameasTIME_WAITED,exceptthatthetimeisinmicroseconds.Dividethisfigureby1000000inordertogetthewaittimeinseconds.

    Considerthefollowingqueryfromv$system_event:

    SELECTevent,time_waitedFROMv$system_eventWHEREeventIN('SQL*Netmessagefromclient','smontimer','dbfilesequentialread','logfileparallelwrite')EVENTTIME_WAITED(sec)logfileparallelwrite1596.92dbfilesequentialread286.57smontimer1306738.37SQL*Netmessagefromclient165289.89Sinceinstancestartup,processesonthissystemhavewaitedatotalof286.57secondswhilereadingsingledatafileblocksfromdisk,andover1,596seconds(26minutes)

    TheV$SESSION_EVENTViewThev$session_eventviewisalotlikethev$system_eventview,exceptthatitshowsseparaterowsofinformationforeachOracleprocess.Aswithv$system_event,eventnamesdonotappearinthisviewiftheprocesshasnotwaitedforthematleastonce.Also,whenanOracleprocessterminates(asinthecaseofwhenauserlogsoffthedatabase)alloftherowsinv$session_eventforthatprocesspermanentlydisappear.Thev$session_eventviewhasthefollowingcolumns:

    NameNull?TypeSIDNUMBEREVENTVARCHAR2(64)TOTAL_WAITSNUMBERTOTAL_TIMEOUTSNUMBERTIME_WAITEDNUMBERAVERAGE_WAITNUMBERMAX_WAITNUMBERTIME_WAITED_MICRONUMBER

    SIDindicatesthesessionIDoftheprocesswaitingfortheevent.Youcanqueryv$sessioninordertodeterminetheSIDofthesessionwhosewaiteventsyouwanttoinvestigate.Thenextfivecolumnsinthev$session_eventviewarethesameasinthev$system_eventview,exceptthatnowtheypertaintotheonespecificprocessinsteadofallprocesses.MAX_WAITindicatesthemaximumamountoftimetheprocesshadtowaitfortheevent.LikeTIME_WAITEDandAVERAGE_WAIT,theunitofmeasureiscentisecondsandwilldisplayaszeroiftimedstatisticsarenotenabled.

    ConsiderthefollowingquerywhichdisplaysallwaiteventinformationforthecurrentSQL*Plussession:

    SELECTevent,total_waits,time_waited_micro,max_waitFROMv$session_eventWHERESID=(SELECTsidFROMv$sessionWHEREaudsid=USERENV('sessionid'))EVENTTOTAL_WAITSTIME_WAITED_MICROMAX_WAITlogfilesync1196292dbfilesequentialread3261281dbfilescatteredread67811546328SQL*Netmessagetoclient763520SQL*Netmoredatatoclient1630SQL*Netmessagefromclient75111865627926930SQL*Netbreak/resettoclient4222812YoucanseethattheOracleprocessservingthissessionhasspent1.180760secondswaitingfordiskI/O.Althoughtherehavebeen76instanceswheretheprocesswaited

    Ifyourunthequeryagainstv$session_eventshownaboveandgetbacknorows,itispossiblethatyouareencounteringOraclebugnumber2429929.InsomereleasesofOracle9i,including9.2.0.1,theSIDcolumninv$session_eventactuallyshowstheSIDminusoneinsteadoftheSID.

    TheV$SESSION_WAITViewThev$session_waitviewshowsonerowforeachOracleprocess.Therowindicatesthenameofthewaiteventandadditionalparametersthatprovidefurtherinformationaboutexactlywhattheprocessiswaitingfor(orinformationaboutthemostrecentwaiteventiftheprocessisnotcurrentlywaiting).Whilethev$system_eventandv$session_eventviewsshowcumulativewaiteventinformation,thev$session_waitviewshowsinformationasofthepresentmomentonly.Thev$session_waitviewhasthefollowingcolumns:

    NameNull?TypeSIDNUMBERSEQ#NUMBEREVENTVARCHAR2(64)P1TEXTVARCHAR2(64)P1NUMBERP1RAWRAW(8)P2TEXTVARCHAR2(64)P2NUMBERP2RAWRAW(8)P3TEXTVARCHAR2(64)P3NUMBERP3RAWRAW(8)WAIT_TIMENUMBERSECONDS_IN_WAITNUMBERSTATEVARCHAR2(19)

    SIDSessionID.SEQ#Sequencenumberthatuniquelyidentifiesthewaitevent.Thissequenceisincrementedwitheachwaiteventcompletion.EVENTNameofwaitevent.P1TEXTAdescriptionofwhattheP1valueisusedfor.Notreliable,usePARAMETER(n)valuefromV$EVENT_NAMEtodetermine.P1Thisvaluedefinitionisdependentontheevent.UsePARAMETER1valuefromV$EVENT_NAMEtodescribewhatthisvalueisusedfor.P1RAWSamevalueasP1exceptinhexadecimalformat.P2TEXTAdescriptionofwhattheP2valueisusedfor.Notreliable,usePARAMETER(n)valuefromV$EVENT_NAMEtodetermine.P2Thisvaluedefinitionisdependentontheevent.UsePARAMETER2valuefromV$EVENT_NAMEtodescribewhatthisvalueisusedfor.P2RAWSamevalueasP2exceptinhexadecimalformat.P3TEXTAdescriptionofwhattheP3valueisusedfor.Notreliable,usePARAMETER(n)valuefromV$EVENT_NAMEtodetermine.P3Thisvaluedefinitionisdependentontheevent.UsePARAMETER3valuefromV$EVENT_NAMEtodescribewhatthisvalueisusedfor.P3RAWSamevalueasP3exceptinhexadecimalformat.WAIT_CLASS_IDIDofthewaitclass.Columnisin10g.WAIT_CLASS#Numberoftheclass.Columnisin10g.WAIT_CLASSThenameofthewaitclass(Idle,Network,SystemI/O,etc.).Columnisin10g.WAIT_TIMEThelastamountoftimethatthesessionwaitedforanevent.A0valuemeansthesessioniscurrentlywaitingontheevent.Thisvalueof0willnotincreaseuntilthesessioncompletesthewaitevent.Timeisincentiseconds.SECONDS_IN_WAITIfWAIT_TIMEequals0,thenthisisthenumberofsecondsspentwaitingontheeventsofar.Thiscangiveyoucomplicatedresultswhenatimeoutoccurslikewithenqueuesbecauseitwillresetto0,butthisisbeyondthescopeofthisarticle.STATEStateofthewaitevent:WAIT_TIME=0WAITING,theprocessisinthestateofwaitingonanevent.WAIT_TIME=1WAITEDSHORTTIME,waittimecompletedinlessthanacentisecond.WAIT_TIME=2WAITEDUNKOWNTIME,durationofwaitisunknownbecauseTIME_STATISTICSwassettofalse.WAIT_TIME>0WAITEDKNOWNTIME,waitcompleted.WAIT_TIMEisthedurationofthewaiteventincentiseconds.

    Thefollowingqueryshowstheparametersassociatedwiththedbfilescatteredreadwaitevent:

    SELECT*FROMv$event_nameWHEREname='dbfilescatteredread'EVENT#NAMEPARAMETER1PARAMETER2PARAMETER3188dbfilescatteredreadfile#block#blocksThistellsusthatwhenaprocessiswaitingforamultiblockreadfromdisktocomplete(asinthecaseofafulltablescanwherethedatablockswerenotalreadyinthebuff

    Thefollowingquerywasrunwhileasessionwasperformingafulltablescan:

    setlinesize32000SELECTsid,seq#,substr(event,1,35)event,p1text,p1,p2text,p2,p3text,p3,wait_time,seconds_in_wait,stateFROMv$session_waitWHEREsid=442SIDSEQ#EVENTP1TEXTP1P1RAWP2TEXTP2P2RAWP3TEXTP3P3RAWWAIT_TIMESECONDS_IN_WAITSTATE442303dbfilescatteredreadfile#1700000011block#272100000AA1blocks80000000810WAITEDSHORTTIMEYoucanseethattheprocesswasnotwaitingatthemomentthisquerywasrun,butitslastwaithadbeenforanI/Orequesttoreadeightblocksfromfile17startingatblocFormostwaiteventsthisviewissufficient,butitishardlyarobusttuningtoolforatleasttwoimportantreasons:*Theviewisasnapshotofthepresent.Whenthewaitsceasetoexist,thehistoryofthosewaitsexperiencedbythesessionearlierdisappearstoo,makingaftereffectdiagnosisdifficult.V$SESSION_EVENTprovidescumulativebutnotverydetaileddata.*V$SESSION_WAITcontainsinformationonlyaboutwaiteventsforallotherrelevantinformationsuchastheuseridandterminalyouhavetojoinitwiththeviewV$SESSION.InOracleDatabase10g,thewaitinterfacehasbeenradicallyredesignedtoprovidemoreinformationwithlessDBAintervention.Inthisarticle,wewillexplorethosenewfeaturesandseehowtheyaidusinthediagnosisofperformanceproblems.Formostoftheperformanceproblems,youwillgetanextendedanalysisfromAutomaticDatabaseDiagnosticManager(ADDM),butforimmediateproblemsnotyetcapturedbyADDM,thewaitinterfaceprovidesvaluabledatafordiagnosis.

    TheV$SESSIONViewSessiondetails,theonlylistingcolumnusedinthescopeofthisarticle.ROW_WAIT_OBJ#ThisistheobjectidoftheobjectinvolvedandisjoinedtotheDBA_OBJECTS.OBJECT_IDorDBA_OBJECTS.DATA_OBJECT_IDcolumn.Thiscolumnisonlypopulatedinversion9iandabove.Avaluethatisnot1meansthatthesessioniswaitingonalockforthisobject.PreviousversionsofthedatabasewillneedtouseP(n)valuesfromV$SESSION_WAITtofindobjectsinDBA_EXTENTS.

    Thev$event_nameViewThev$event_nameviewshowsreferenceinformationratherthanuptothemomentinformationaboutinstanceperformance.ThisviewshowsonerowforeachwaiteventknowntotheOraclekernel.Associatedwitheachwaiteventareuptothreeparametersadditionalpiecesofinformationthatprovidemoredetailaboutawaitsituation.ThisviewdisplaysthedefinitionofP(n)columnsfromV$SESSION_WAITandcanbejoinedontheNAMEcolumn.Thev$event_nameviewhasthefollowingcolumns:

    NameNull?TypeEVENT#NUMBERNAMEVARCHAR2(64)PARAMETER1VARCHAR2(64)PARAMETER2VARCHAR2(64)PARAMETER3VARCHAR2(64)

    EVENT#Numberofthewaitevent.NAMENameoftheevent.PARAMETER1DescriptionofthevalueforP1.PARAMETER2DescriptionofthevalueforP2.PARAMETER3DescriptionofthevalueforP3.WAIT_CLASS_IDIDofthewaitclass.Columnisin10g.WAIT_CLASS#Numberoftheclass.Columnisin10g.WAIT_CLASSThenameofthewaitclass(Idle,Network,SystemI/O,etc.).Columnisin10g.

    Thev$system_eventandv$session_eventviewsshowcumulativeinformationaboutpastwaitsinsummaryform,leavingoutparameterinformationfromeachindividualwait.Aswewillseeinthenextsections,waiteventparameterscomeintoplayinthev$session_waitviewandwaiteventtracefiles.

    TracingWaitEventActivity(SYSTEMEVENT10046)DBAsshouldbefamiliarwiththeSQLtracefacilitybuiltintoOracle.Byusingthecommandsbelow,youcanenableSQLtraceforyoursessionoranothersession:

    l ALTERSESSIONSETsql_trace=TRUE

    l EXECUTESYS.dbms_system.set_sql_trace_in_session(sid,serial#,TRUE)

    WhenSQLtraceisenabledforasession,theOracleprocesswritesdetailedtraceinformation(includingtimingdataiftimedstatisticsareenabled)toatracefileinadirectoryspecifiedbytheuser_dump_destinstanceparameter.Thesetracefilesareplaintextfilesandhumanreadable,butrathertediousandrepetitive.YoucanoptionallyruntracefilesthroughaprocessorsuchasTKPROFinsteadoflookingatthemdirectly.Oraclehastheabilitytodirectaprocesstoincludeadditionalinformationinthetracefile,includingwaiteventinformation.InearlierreleasesofOracle,weactivatedthewaiteventtracingfacilitybysettingdebugevent10046.Debugevent10046stillworksinOracle9i,butrecentreleasesofOracleincludeaPL/SQLpackagebuiltinthatgivesamorefriendlymeansforactivatingwaiteventtracing.SettingdebugeventsallowsaDBAtoinstructanOracleinstancetotakeonaspecial,atypicalbehavior.Debugeventscanbeused,forexample,tocauseOracletowriteasystemleveldumpfilewheneveranORA0600erroroccursorskipovercorruptedblocksinatablewhenperformingafulltablescan.MostdebugeventsshouldneverbesetunlessyouaredirectedtodosobyOracleSupport.Somedebugeventscanputyourdatabaseatrisk.Debugevent10046affectstheamountofinformationwrittentotracefiles.Itisaverysafedebugevent,andoneofthefewthatyouareallowedtosetwithoutspecialpermissionfromOracleSupport.Debugevent10046canbesettothefollowingvalues:

    Youcansetthe10046debugeventtotraceyoursessionandcollectwaiteventinformationinthetracefilewitheitherofthefollowingcommands:

    l EXECUTESYS.DBMS_SUPPORT.START_TRACE

    l ALTERSESSIONSETevents'10046tracenamecontextforever,level8'

    Youcansetthe10046debugeventtotraceanothersessiononthedatabasewithanyofthefollowingcommands:Findthesession:setlinesize150columnNameformata14columnSIDformat9999columnPIDformat99999columnTERMformata15columnOSUSERformata15columnProgramformata15columnStatsformata10columnLogon_timeformata20selecta.usernameName,a.sidSID,a.serial#,b.spidPID,SUBSTR(A.TERMINAL,1,9)TERM,SUBSTR(A.OSUSER,1,9)OSUSER,substr(a.program,1,10)Program,a.statusStatus,to_char(a.logon_time,'MM/DD/YYYYhh24:mi')Logon_timefromv$sessiona,v$processbwherea.paddr=b.addranda.serial#'1'anda.status='ACTIVE'anda.usernamelikeupper('%&user%')ifyouwanttofilterbyusernameorderbya.logon_time

    OnceyouhavetheSIDandSERIAL#ofthesessionyoucanusesomeOraclesuppliedpackages. settimedstatisticsatusersessionlevelifnotsetatsystemlevel.executesys.dbms_system.set_boo_param_in_session(&&SID,&&SERIAL,'timed_statistics',true)

    setmaxdumpfilesizeifnotsetatsystemlevel.executesys.dbms_system.set_in_param_in_session(&&SID,&&SERIAL,'max_dump_file_size',10000000) activatelevel8extendedSQLtracing.executesys.dbms_system.set_ev(&&SID,&&SERIAL,10046,8,'')orexecutesys.dbms_support.start_trace_in_session(&&SID,&&SERIAL)

    *******runallofyourprocessinghere*******

    disablesextendedSQLtracing.executesys.dbms_system.set_ev(&&SID,&&SERIAL,10046,0,'')orexecutesys.dbms_support.stop_trace_in_session(&&SID,&&SERIAL)

    CallingDBMS_SUPPORTasshownhereisequivalenttoactivatingdebugevent10046atlevel8.Youmayincludeoptionaladditionalparametersintheprocedurecalltoactivatelevel4or12.TheDBMS_SUPPORTpackageisnotinstalledinthedatabasebydefault.Youneedtorunthedbmssupp.sqlscriptfoundintherdbms/admindirectoryasSYSbeforeyoucancallDBMS_SUPPORT.ItshouldalsobepointedoutthattheSET_EVprocedureintheDBMS_SYSTEMpackageisnotofficiallysupportedbyOracleCorporationtheypreferthatyouuseDBMS_SUPPORTinstead.ThereasonisthatDBMS_SYSTEM.SET_EVallowsyoutosetanydebugeventinanysession.Asmentionedabovesomedebugeventscanpotentiallybedangerous,andDBMS_SYSTEM.SET_EVletsyousetsucheventsinanysession.Unliketimedstatistics,tracingconsumesasignificantamountofsystemresources.Thereforeitisimportanttousethetracingfacilitysparingly.Traceonlythesessionsyouneedtotrace,andonlyforaslongasyouneed.Turnofftracingassoonasitisnolongerneededwithanyofthefollowingcommands:

    l EXECUTESYS.DBMS_SUPPORT.STOP_TRACE

    l ALTERSESSIONSETEVENTS'10046TRACENAMECONTEXTOFF'

    l ALTERSESSIONSETsql_trace=FALSE

    l EXECUTESYS.DBMS_SUPPORT.STOP_TRACE_IN_SESSION(sid,serial#)

    l oradebugsetorapid[OraclePIDfromv$process]oradebugsession_event10046tracenamecontextforever,level0

    l EXECUTESYS.DBMS_SYSTEM.SET_EV(sid,serial#,10046,0,'')

    Whenyousetdebugevent10046toalevelof8or12(orcallSTART_TRACEorSTART_TRACE_IN_SESSIONinDBMS_SUPPORT),theOracleprocesswillwritealineintothetracefileeverytimeitfinisheswaitingforanevent.Thelineinthetracefilewillcontainalmostthesameinformationthatwouldhaveappearedinthev$session_waitview,butperhapsinaslightlylessfriendlyformat.Youcanalsoseeinthetracefilewhichcursor(andthereforewhichSQLstatement)thewaiteventwasassociatedwith.Hereisanexcerptfromatracefilegeneratedbysettingdebugevent10046tolevel12onanOracle8idatabase:

    =====================PARSINGINCURSOR#1len=80dep=0uid=502oct=3lid=502tim=2293771931hv=2293373707ad='511dca20'SELECT/*+FULL*/SUM(LENGTH(notes))FROMcustomer_callsWHEREstatus=:xENDOFSTMTPARSE#1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=2293771931BINDS#1:bind0:dty=2mxl=22(22)mal=00scl=00pre=00oacflg=03oacfl2=0size=24offset=0bfp=09717724bln=22avl=02flg=05value=43EXEC#1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2293771931WAIT#1:nam='SQL*Netmessagetoclient'ela=0p1=675562835p2=1p3=0WAIT#1:nam='dbfilescatteredread'ela=3p1=17p2=923p3=8WAIT#1:nam='dbfilescatteredread'ela=1p1=17p2=931p3=8WAIT#1:nam='dbfilescatteredread'ela=2p1=17p2=939p3=8WAIT#1:nam='dbfilesequentialread'ela=0p1=17p2=947p3=1WAIT#1:nam='dbfilescatteredread'ela=3p1=17p2=1657p3=8WAIT#1:nam='dbfilescatteredread'ela=1p1=17p2=1665p3=8WAIT#1:nam='dbfilescatteredread'ela=2p1=17p2=1673p3=8WAIT#1:nam='dbfilescatteredread'ela=0p1=17p2=1681p3=8WAIT#1:nam='dbfilescatteredread'ela=3p1=17p2=1761p3=8WAIT#1:nam='dbfilescatteredread'ela=1p1=17p2=1769p3=8WAIT#1:nam='dbfilescatteredread'ela=1p1=17p2=1777p3=8WAIT#1:nam='dbfilescatteredread'ela=0p1=17p2=1785p3=8WAIT#1:nam='dbfilescatteredread'ela=2p1=17p2=1841p3=8WAIT#1:nam='dbfilescatteredread'ela=1p1=17p2=1849p3=8

    The"ela="figuresindicatethedurationofthewait.IntracefilesgeneratedbyOracle8iandearlier,theelapsedtimeisshownincentiseconds.BeginninginOracle9i,theelapsedtimeisshowninmicroseconds.Youcanseethatwhenthesessionexecutedthequery,therewasawaitshorterthanonecentisecondforamessagetobesenttotheclient,followedbyabunchofwaitsforI/Orequestsagainstfile17.MostoftheI/Orequestsweremultiblockreads,readingeightblocksatatimewhileperformingafulltablescanoftheCUSTOMER_CALLStable.Youcanprobablyimaginehowlargeandoverwhelmingtracefilescangetwhenanythingbutatrivialapplicationistraced.ThisiswhyOracleprovidestheTKPROFutility.TKPROFtakesatracefileasinputandgeneratesanicelyformatted,easytoreadreport.Unfortunately,theTKPROFthatcomeswithOracle8iandearlierreleasesignoreswaiteventinformationwritteninthetracefile.ToanalyzethewaiteventinformationcollectedbyatraceinanOracle8iorearlierenvironment,youwillneedtoeitherporethroughthetracefilemanuallyorwriteyourowntracefileparserandformatter.(We'veheardofpeoplewritingperlscriptstodothis,butwehavenevercomeacrossthem.)TheTKPROFutilitythatcomeswithOracle9iiscapableofreportingwaiteventinformationsummarizedbydistinctstatement.BydefaultOracle9iTKPROFignoreswaiteventinformationinthetracefileasearlierreleasesdid.However,ifthe"waits=yes"commandlineargumentisprovided,aseparatetableofwaiteventstatisticswillappearinthereportforeachdistinctstatement.HereisasampleexcerptfromaTKPROFreportshowingwaiteventinformation:

    ********************************************************************************SELECTA.customer_id,A.customer_name,COUNT(*)purchases,MAX(B.transaction_date)last_purchase_dateFROMcustomersA,purchase_historyBWHEREB.customer_id=A.customer_idGROUPBYA.customer_id,A.customer_nameORDERBYA.customer_idcallcountcpuelapseddiskquerycurrentrowsParse10.060.1202700Execute10.000.000000Fetch146121.4125.8078015905521893total146321.4725.9378015932521893Missesinlibrarycacheduringparse:1Optimizergoal:CHOOSEParsinguserid:17RowsRowSourceOperation21893SORTGROUPBY1525494HASHJOIN31212TABLEACCESSFULLCUSTOMERS1525494INDEXFASTFULLSCANPURCHASE_HISTORY_PK(objectid7824)Elapsedtimesincludewaitingonfollowingevents:EventwaitedonTimesMax.WaitTotalWaitedWaitedSQL*Netmessagetoclient14610.000.00dbfilesequentialread40.000.01dbfilescatteredread7500.072.25directpathwrite2710.832.79directpathread2540.000.01SQL*Netmessagefromclient14611.2822.40********************************************************************************

    Youcanseethatthequerywasparsedandexecutedonce,andtherewere1461fetchestoread21893rows.TheOracleprocessused21.47CPUsecondsand25.93secondsofelapsedtimetoparse,execute,andfetchthequery.TheelapsedtimewasgreaterthantheCPUtimebecausetheOracleprocesshadtowaitonseveralwaitevents.Thelistingatthebottomofthereportshowstheprocesswaitedonnetworkroundtripstotheclientandreadsandwritestodisk.Allofthesewaitsseemtomakesense:Therewasonenetworkroundtriptotheclientforeachfetchcall,andittookSQL*Plusalongtime(over22seconds)todisplaythe21,893rowsofdataonmydisplay.Thedbfilesequentialreadsanddbfilescatteredreadsresultedfromthetableaccessandindexfastfullscan.Thedirectpathwritesandreadsresultedfromthehashjoinandsortoperations.IfyouaddtheCPUtimeof21.47secondsandthewaittimes(5.06secondsnotincludingtheSQL*Netmessagefromclientwaits)youcomeupwithanelapsedtimeof26.53seconds.However,thereportshowsthetotalelapsedtimeas25.93seconds.Thisisagoodexampleoftheroundofferrorthatisnotunusualwhenthousandsofveryshorttimeintervalsareaddedtogether.Insomesituationsyoumaynotbeabletoidentifyexactlywhichsessiontotrace.Thishappensfrequentlywhenyourdatabaseissupportingawebapplicationthathasfrequentshortconnections,oranapplicationservertierthatmaintainsapoolofdatabaseconnectionsallloggedonasthesameOracleuser.Youmayhaveaspecificqueryyouwanttocollectwaiteventinformationfor,butyoumaynotknowwhichsessionwillbeexecutingthequery.Onewaytodealwiththissituationistotraceallofthesessionsbeingstartedbyyourapplicationforabriefperiod.ThiscanbedoneeasilywiththefollowingSQL*Plusscript:

    SPOOLtraceall.sqlSETHEADINGOFFFEEDBACKOFFSELECT'EXECUTESYS.dbms_system.set_ev('||TO_CHAR(sid)||','||TO_CHAR(serial#)||',10046,8,'''')'FROMv$sessionWHEREusername='WEB_USER'[email protected]

    ThisscriptwillstartwaiteventtracingonallsessionsconnectedtothedatabaseastheWEB_USERuser.Tostoptracingsimplychangethe8afterthe10046toa0andrunthescriptagain.Youshouldthinkabouthowmanysessionsthisscriptwilltraceandhowthatwillaffectserverloadbeforerunningonaproductionsystem.Afteryou'vetracedanumberofsessions,youcanscanthetracefilesforoccurrencesofaspecificquerywithacommandlikethefollowing:

    grepn1234567890*.trc

    Replace1234567890withthehashvalueoraddressofthestatementyouareinterestedin.(Youcangetthesevaluesbyqueryingv$sql.)Theoutputoftheabovegrepcommandwilltellyouwhichtracefilesthequeryappearsinandonwhichlines.Youcanthengotothatpointinthetracefilesandgetdetailedwaiteventinformation. Tracefilesareeasiesttoworkwithwhenyouuseadedicatedserverconnectiontothedatabase.IfyouconnecttothedatabaseusingOracle'ssharedserverarchitecturethendifferentSQLstatementsmaybeexecutedbydifferentserverprocesses.Eachserverprocesswritestoitsowntracefile.Thusthetraceinformationforthesessioncanbespreadoverseveraltracefiles.

    WaitEventEnhancementsinOracle10gOracle10gbringsmoresignificantchangetothewaiteventinterfacethanwehaveseeninyears.Nowthereareover800waiteventsandnamesaremoredescriptive,waiteventsarecategorizedintoclasses,severalv$viewshavebeenadded,helpfulcolumnshavebeenaddedtoexistingv$views,builtinstatisticscollectionbyActiveSessionHistoryandtheAutomaticWorkloadRepositoryhasbeenintroduced,anewtimemodelconceptforlookingathowsessionsspendtheirtimehasappeared,andimprovementshavebeenmadetothesessiontracingfacility.Inthissection,wewillintroducewhatweseeasthetopdozenareasinwhichwaiteventsandthewaiteventinterfacehavebeenenhancedinOracle10g.Wevelistedtheseenhancementsinnoparticularorder.

    MoreDescriptiveWaitEventNames

    PriortoOracle10g,somewaiteventnameswerequitevagueandnotveryusefulwithoutlookingattheparametervaluesforaspecificoccurrenceoftheevent.Forexample,anenqueuewaitcouldindicatevarioussituationsrangingfromcontentionforarowinatabletowaitingonauserdefinedlock.WaiteventnamesinOracle10garemoredescriptiveintheareasoflatches,enqueues,andbufferbusywaits.

    ThereisstillalatchfreewaiteventinOracle10g,buttherearealso26morespecificlatchrelatedevents.Thesecoverthemostcommonlatchesthatexperiencecontention.Inthepast,ifwesawasessionwaitingonthelatchfreeevent,wewouldhaveoutputlikethefollowing:

    SQL>SELECTevent,state,p1,p2,p32FROMv$session_wait3WHEREsid=162EVENTSTATEP1P2P3latchfreeWAITING15113593728975

    Wewouldthenhavetoqueryv$event_nametodeterminethemeaningoftheparametersp1,p2,andp3:

    SQL>SELECT*FROMv$event_nameWHEREname='latchfree'EVENT#NAMEPARAMETER1PARAMETER2PARAMETER33latchfreeaddressnumbertries

    And,seeingthatp2isthelatchnumber,wewouldneedtoqueryv$latchtofindoutwhichlatchwasbeingwaitedupon:

    SQL>SELECTname2FROMv$latch3WHERElatch#=97NAMEcachebufferschains

    InOracle10gwesimplysee:

    SQL>SELECTevent,state2FROMv$session_wait3WHEREsid=162EVENTSTATElatch:cachebufferschainsWAITING

    Thedescriptiveeventnamesavesustwostepsindeterminingwhichlatchiscausingthewait.Themoredetaileddescriptionenablesonetomorequicklydrilldowntotherootcauseofthewait.

    ThenamesofenqueuerelatedwaiteventshavealsobeenmademoredescriptiveinOracle10g.Thereisnolongeranenqueuewaiteventithasbeenreplacedby184eventswithmoredetailednames.Inthepast,ifsessionswerewaitingonenqueues,wewouldhavetodecodethetypeoflockfromthep1parameter:

    SQL>SELECTevent,state,seconds_in_waitsiw2FROMv$session_wait3WHEREsid=96EVENTSTATESIWenqueueWAITING24SQL>SELECTsid,2CHR(BITAND(p1,16777216)/16777215)||3CHR(BITAND(p1,16711680)/65535)enq,4DECODE(CHR(BITAND(p1,16777216)/16777215)||5CHR(BITAND(p1,16711680)/65535),6'TX','Transaction(RBS)',7'TM','DMLTransaction',8'TS','TablespaceandTempSeg',9'TT','TemporaryTable',10'ST','SpaceMgt(e.g.,uet$,fet$)',11'UL','UserDefined',12CHR(BITAND(p1,16777216)/16777215)||13CHR(BITAND(p1,16711680)/65535))enqueue_name,14DECODE(BITAND(p1,65535),1,'Null',2,'SubShare',153,'SubExclusive',4,'Share',5,'Share/SubExclusive',166,'Exclusive','Other')lock_mode17FROMv$session_wait18WHEREsid=96SIDENQENQUEUE_NAMELOCK_MODE96TXTransaction(RBS)Exclusive

    InOracle10gwegetmoreinformationdirectlyfromtheenqueuename:

    SQL>SELECTevent,state,seconds_in_waitsiw2FROMv$session_wait3WHEREsid=143EVENTSTATESIWenq:TXrowlockcontentionWAITING495

    Additionally,moreinformationisavailableinsomecasesfromthep1,p2,andp3parameters,whosemeaningsvarywiththedifferentenqueuerelatedwaitevents.(SeetheAppendixforalistingofallwaiteventsandtheirassociatedparametermeanings.)

    WaitEventClasses

    InOracle10gwaiteventsareclassifiedintocategorieswhichcanhelptheDBAtomoreeasilydeterminethelikelyrootcauseofthewait.Thecategoriesare:

    Whilenearly70%ofthewaiteventsareintheOthercategory(557outof811inrelease10.1.0.3),themostfrequentlyencounteredonesareinwaitclasseswithhelpfulnames.Letslookatthewaitclassdesignationsofsomeenqueueeventsasanexample:

    SQL>SELECTwait_class,name2FROMv$event_name3WHEREnameLIKE'enq%'4ANDwait_class'Other'5ORDERBYwait_classWAIT_CLASSNAMEAdministrativeenq:TWcontentionAdministrativeenq:DBcontentionApplicationenq:PWflushprewarmbuffersApplicationenq:ROcontentionApplicationenq:ROfastobjectreuseApplicationenq:TMcontentionApplicationenq:TXrowlockcontentionApplicationenq:ULcontentionConcurrencyenq:TXindexcontentionConfigurationenq:STcontentionConfigurationenq:TXallocateITLentryConfigurationenq:SQcontentionConfigurationenq:HWcontention

    WeseethatTXenqueues(rowlocks)andTMenqueues(tablelocks)areintheApplicationclass,whichmakessensesincethesewaiteventsgenerallyoccurbecauseofapplicationbehavior.Meanwhile,ST(spacemanagement),HW(highwatermarkextension),andSQ(sequencenumber)enqueuesareintheConfigurationclass,asthesecanusuallybealleviatedbychangesinobjectanddatabasesettings.

    TheUserI/Oclassincludesthedbfilescatteredread,dbfilesequentialread,directpathread,anddirectpathwriteeventsasonemightexpect,whiletheSystemI/Oclassincludesmanywaitsrelatedtoreadingandwritingofredologsandarchivelogs.TheCommitclasshasonemember,logfilesync,asthatwaitiscausedbycommits.AndtheIdleclassismadeupofvariouswaiteventswhichhavetraditionallybeenconsideredidleevents,suchasSQL*Netmessagefromclient.Itshouldbenotedthatsometimessuchidleeventscanactuallybesymptomsoftherootcauseofpoorperformance,sotheyshouldnotbedisregardedwithoutconsideration.

    Ingeneral,theadditionofwaitclasseshelpsdirecttheDBAmorequicklytowardtherootcauseofperformanceproblems.

    v$ViewEnhancements

    InOracle10gtherearequiteafewnewv$viewsthatpertaintowaitevents,andhelpfulnewcolumnshavebeenaddedtoexistingv$views.Wewilldiscussseveraloftheenhancementsinthissection,althoughsomenewv$viewsarepartofmajornewOracle10gfunctionalityandwillbediscussedinseparatesectionslateron.

    v$event_name

    Threecolumnshavebeenaddedtothev$event_nameviewinOracle10g:wait_class_id,wait_class#,andwait_class.Thesecolumnsshowwhichwaitclassthewaiteventispartof.Wesawintheprevioussectionhowthisnewinformationmightbeused.Thecolumnsinv$event_namenoware:

    SQL>DESCRIBEv$event_nameNameNull?TypeEVENT#NUMBEREVENT_IDNUMBERNAMEVARCHAR2(64)PARAMETER1VARCHAR2(64)PARAMETER2VARCHAR2(64)PARAMETER3VARCHAR2(64)WAIT_CLASS_IDNUMBERWAIT_CLASS#NUMBERWAIT_CLASSVARCHAR2(64)

    v$sqlandv$sqlarea

    Thev$sqlandv$sqlareaviewshavesixnewcolumnsinOracle10gthatrelatetowaitevents:

    ThesecolumnsaredesignedtoidentifytheamountoftimeaSQLstatementspendsinPL/SQLorJavacodeexecution,orwaitinginfourspecificwaitclasses.Wewilluseanexampletodemonstratethebehaviorandvalueofthesenewcolumns.

    Supposewecreateatablecalledtesttabwithaboutamillionrows.Wethenrunthefollowingstatementfromonesessionwithoutcommitting,andthenrunthesamestatementfromanothersession:

    SQL>UPDATEtesttabSETnumcol=numcol+1WHEREROWNUMUPDATEtesttabSETnumcol=numcol+1

    Theinstancewereusinghasasmallbuffercache,soquiteabitofphysicalI/Oiscausedbythestatement.AftertheUPDATEcompleteswelookatv$sqlarea:

    SQL>SELECTsql_id,application_wait_timeappl,concurrency_wait_timeconcurr,2user_io_wait_timeuser_io3FROMv$sqlarea4WHEREsql_textLIKE'UPDATEtesttabSETnumcol%'SQL_IDAPPLCONCURRUSER_IO038m56cp4am0c178500000020000fd5mxhdbf09ny010000105040000SQL>SELECTsql_id,sql_text2FROMv$sqlarea3WHEREsql_idIN('fd5mxhdbf09ny','038m56cp4am0c')SQL_IDSQL_TEXT038m56cp4am0cUPDATEtesttabSETnumcol=numcol+1WHEREROWNUMSELECTsid,seq#,event,wait_time,p1,p2,p32FROMv$session_wait_history3WHEREsid=1544ORDERBYseq#SIDSEQ#EVENTWAIT_TIMEP1P2P31541dbfilesequentialread284354711542logbufferspace180001543logbufferspace360001544dbfilesequentialread04355911545dbfilesequentialread04127211546dbfilesequentialread04355511547logbufferspace90001548dbfilesequentialread04355111549dbfilesequentialread641268115410logbufferspace8000

    Theseq#columnissupposedtoshowthechronologicalsequenceofthewaitevents,with1beingthemostrecentwaiteventinthesession.Notethatthisseq#valuediffersfromtheseq#columninv$session,whichisincrementedforeachwaitexperiencedbythesessionthroughoutthelifeofthesession.

    Intheabovequery,weseethatthesessionsmostrecentwaitsalternatedbetweensingleblockdiskreadsandlogbufferspace.Thismakessense,sincetheSQLthatthesessionwasperforminglookedlike:

    INSERTINTOtable1(column1,column2)SELECTcolumn1,column2FROMtable2WHERE...

    Fromthislistofrecentwaits,wecanalsodrilldowntogetmoredetail.Thep1andp2valuesfordbfilesequentialreadindicatethefileandblocknumbersbeingread,sowecanquicklydeterminewhatsegmentwasbeingread.

    Thecolumnsinv$session_wait_historyare:

    SQL>DESCRIBEv$session_wait_historyNameNull?TypeSIDNUMBERSEQ#NUMBEREVENT#NUMBEREVENTVARCHAR2(64)P1TEXTVARCHAR2(64)P1NUMBERP2TEXTVARCHAR2(64)P2NUMBERP3TEXTVARCHAR2(64)P3NUMBERWAIT_TIMENUMBERWAIT_COUNTNUMBER

    v$session

    Thev$sessionviewhasbeenenhancedinOracle10gwithseveralnewcolumnswhicharequiteuseful.Thewaiteventcolumnsfromv$session_waithavebeenaddedtov$session.InpreviousreleasesofOracle,togetmoredetailedinformationaboutasessionexperiencingwaits(suchaswhatSQLthewaitingsessionisexecuting),wehadtojoinv$session_waitwithv$session,asin:

    SQL>SELECTs.sid,w.state,w.event,w.seconds_in_waitsiw,2s.sql_address,s.sql_hash_valuehash_value,w.p1,w.p2,w.p33FROMv$sessions,v$session_waitw4WHEREs.sid=w.sid5ANDs.sid=154

    InOracle10gwecangetallofthisinformationfromv$session:

    SQL>SELECTsid,state,event,seconds_in_waitsiw,2sql_address,sql_hash_valuehash_value,p1,p2,p33FROMv$session4WHEREsid=154SIDSTATEEVENTSIWSQL_ADDRESSHASH_VALUEP1P2P3154WAITINGdbfilesequentialread1000000038551E8203625097388498131

    Twoadditionalcolumnshavebeenaddedtov$sessionthatarehelpfulforwaiteventanalysis:blocking_sessionandblocking_session_status.Theblocking_sessioncolumncontainsthesessionid(SID)oftheholderoftheresourcethatthewaitingsessioniswaitingfor.Theblocking_session_statuscolumnindicatesthevalidityofthecontentsoftheblocking_sessioncolumn.Ifblocking_session_statusisVALID,avalidSIDispresentintheblocking_sessioncolumn.Inthepast,ifwesawthatasessionwaswaitingforaresource,wewouldhavetodoadditionalqueriestodeterminewhowasholdingtheresource.Iftheresourcewasanenqueuelock,wewouldhavetoqueryv$lock(sometimesaveryexpensivequery)todeterminewhowasholdingthelock.Nowwecanfindoutwhoisholdingthelockmuchmorequickly:

    SQL>SELECTsid,blocking_session,username,2blocking_session_statusstatus3FROMv$session4WHEREblocking_session_status='VALID'SIDBLOCKING_SESSIONUSERNAMESTATUS154157TSUTTONVALID

    Ifwecombinethiswiththewaiteventinformationnowavailableinv$session,wesee:

    SQL>SELECTsid,blocking_session,username,2event,seconds_in_waitsiw3FROMv$session4WHEREblocking_session_status='VALID'SIDBLOCKING_SESSIONUSERNAMEEVENTSIW154157TSUTTONenq:TXrowlockcontention318

    v$event_histogram

    Thev$system_eventviewshowsthenumberofwaits,totaltimewaited,andaveragewaittimeforagivenwaiteventname(systemwidesinceinstancestartup).However,thisaggregationcancloudthepicture,becauseasmallnumberoflongwaitscanskewthedata.Forexample,considerthefollowingqueryfromv$system_event:

    SQL>SELECTevent,total_waits,time_waited,average_wait2FROMv$system_event3WHEREevent='enq:TXrowlockcontention'EVENTTOTAL_WAITSTIME_WAITEDAVERAGE_WAITenq:TXrowlockcontention172182101966122

    Weseethattherehavebeen17,218waitsandthattheaveragewaittimewas1.22seconds,butwehavenoideahowthewaittimesaredistributed.Wereallofthesewaitsroughlythesamelength?Weremostofthemunderonesecondlongandafewreallylongwaitsthrewofftheaverage?Wecanttellfromv$system_event.However,inOracle10gwecanlookatv$event_histogramforamorecompletepicture:

    SQL>SELECTevent,wait_time_milli,wait_count2FROMv$event_histogram3WHEREevent='enq:TXrowlockcontention'EVENTWAIT_TIME_MILLIWAIT_COUNTenq:TXrowlockcontention1833enq:TXrowlockcontention2635enq:TXrowlockcontention4372enq:TXrowlockcontention8395enq:TXrowlockcontention16781enq:TXrowlockcontention323729enq:TXrowlockcontention643050enq:TXrowlockcontention128410enq:TXrowlockcontention25647enq:TXrowlockcontention51246enq:TXrowlockcontention102437enq:TXrowlockcontention20483enq:TXrowlockcontention40966880

    Weseethatveryfewofthewaitswereanywherenear1.22seconds.Nearly60%ofthewaitswerelessthan0.128seconds(withmostofthosebetween16millisecondsand64milliseconds),andmostoftheremainingwaitswerebetween2.048secondsand4.096seconds(atwhichpointsometimedoutandstartednewwaits).Inthisway,thev$event_histogramviewgivesusamoreaccuratepictureofwaittimessummarizedbyeventname.

    Thecolumnsofv$event_histogramare:

    SQL>DESCRIBEv$event_histogramNameNull?TypeEVENT#NUMBEREVENTVARCHAR2(64)WAIT_TIME_MILLINUMBERWAIT_COUNTNUMBER

    v$system_wait_classandv$session_wait_class

    Thetwonewviewsv$system_wait_classandv$session_wait_classenableustogetsystemandsessionwaitinformationsummarizedbywaitclasses.Thisgivesusahigherlevelviewofwhatishappeninginthesystemorsession,ratherthanfocusingonindividualevents.Theviewsareroughlyequivalenttotheviewsv$system_eventandv$session_event,exceptthattheyrolluptheeventsbywaitclass.Thewaittimesareexpressedincentisecondssinceinstancestartupforv$system_wait_classandcentisecondssincesessionconnectionforv$session_wait_class.

    Thefollowingqueriesshowhowmuchtime(incentiseconds)hasbeenspentonwaitsineachclassacrossthesystemsinceinstancestartandforonespecificsessionsincethatsessionbegan:

    SQL>SELECTwait_class,time_waited2FROMv$system_wait_class3ORDERBYtime_waitedDESCWAIT_CLASSTIME_WAITEDIdle777450022SystemI/O1261584UserI/O116667Configuration116481Application72301Other12432Commit3496Concurrency319Network1SQL>SELECTwait_class,time_waited2FROMv$session_wait_class3WHEREsid=1544ORDERBYtime_waitedDESCWAIT_CLASSTIME_WAITEDIdle612453UserI/O1500Configuration28Commit11Other0Application0Network0

    Sincethewaittimesshownintheseviewsareaggregationssincesystemorsessionstartup,theseviewsarebestusedbytakingsamplesandcomparingtheresultstodeterminewaitsoveraperiodoftime.Forinstance,youcouldgetdatafortheentireinstanceattimeT1:

    DROPTABLEswc_snapCREATETABLEswc_snapASSELECTwait_class,total_waits,time_waitedFROMv$system_wait_class

    Andthen,attimeT2awhilelater,getasummaryofwaitsbetweenT1andT2:

    SELECTa.wait_class,(a.time_waitedb.time_waited)tm_waitedFROMv$system_wait_classa,swc_snapbWHEREa.wait_class=b.wait_classANDa.total_waits>NVL(b.total_waits,0)ORDERBYtm_waitedDESCWAIT_CLASSTM_WAITEDIdle255767Application171SystemI/O156UserI/O44Other21Commit13Network1

    ActiveSessionHistory

    InpreviousreleasesofOracle,thedetailedinformationdisplayedinv$session_waitcouldproveextremelyhelpfulindiagnosingperformanceproblemsifyouqueriedtheviewattherighttime.Thev$session_wait_historyviewinOracle10gmakesitalittleeasiertocatchdetailedinformationbypreservingthelasttenwaitsforeachsession.Butwhatifyouwantdetailedinformationaboutasessionswaitsforaperiodfurtherbackintime?ThisiswheretheActiveSessionHistoryfeatureofOracle10gASHforshortcomesinhandy.ASHmakesdetailedinformationaboutasamplingofwaitsencounteredbyallsessionsavailabletousforaverylongtime.

    InOracle10g,anewbackgrounddaemonprocesscalledMMNLqueriesv$sessiononceeachsecondandstoresinformationaboutallactivesessionsinacircularbufferinmemoryaccessiblebyanewviewcalledv$active_session_history.HowfarbackyoucanlookatsessionsinthisviewdependsonsessionactivityandhowmuchmemoryOracleallocatedforASH.Oraclesgoalistokeepatleastafewhoursofsessiondataavailableinthisview.Thev$active_session_historyviewincludesmuchofthedetailedwaiteventinformationshowninv$session:

    SQL>DESCRIBEv$active_session_historyNameNull?TypeSAMPLE_IDNUMBERSAMPLE_TIMETIMESTAMP(3)SESSION_IDNUMBERSESSION_SERIAL#NUMBERUSER_IDNUMBERSQL_IDVARCHAR2(13)SQL_CHILD_NUMBERNUMBERSQL_PLAN_HASH_VALUENUMBERSQL_OPCODENUMBERSERVICE_HASHNUMBERSESSION_TYPEVARCHAR2(10)SESSION_STATEVARCHAR2(7)QC_SESSION_IDNUMBERQC_INSTANCE_IDNUMBEREVENTVARCHAR2(64)EVENT_IDNUMBEREVENT#NUMBERSEQ#NUMBERP1NUMBERP2NUMBERP3NUMBERWAIT_TIMENUMBERTIME_WAITEDNUMBERCURRENT_OBJ#NUMBERCURRENT_FILE#NUMBERCURRENT_BLOCK#NUMBERPROGRAMVARCHAR2(48)MODULEVARCHAR2(48)ACTIONVARCHAR2(32)CLIENT_IDVARCHAR2(64)

    Asyoucansee,v$active_session_historycapturestheessentialwaitrelateddatafromv$session.ItalsocapturesusefulinformationabouttheSQLstatementcurrentlybeingexecuted,aswellascurrentobjectnumber,file,andblockbeingaccessed.WhenawaitthatwassampledbyASHcompletes,Oraclefillsinthetime_waitedcolumnfortherowinv$active_session_historywiththeactualdurationofthewait.

    TheAutomaticWorkloadRepository,whichwewilldiscussinthenextsection,writesdatafromv$active_session_historytodiskatregularintervals,preservingonesampleeverytensecondsfromeachactivesession.So,activesessioninformationremainsaccessiblealthoughwithlessdetailevenafterthedatahasagedoutofv$active_session_history.

    BecauseASHisalwayson,youalwayshaveaccesstodetailedinformationaboutwaitsencounteredinsessionswithinthelastfewhours.Thismeansthatifausercomplainsaboutaperformanceproblem,youmaybeabletoqueryv$active_session_historyandgaininsightintotheproblemwithouthavingtoinitiateanextendedSQLtraceorstartaclosewatchofv$sessionwhiletheyreproducetheproblem.

    Animportantthingtokeepinmindaboutv$active_session_history,however,isthatitispopulatedbysamplingv$sessiononceeachsecond.Asessionmayencountermanydifferentwaitsduringaonesecondperiod,butonlytheonewaitthatwasinprogresswhenASHcollecteditssamplewillberecordedinv$active_session_history.Forthisreason,ASHisvaluableforgeneralaggregatequeriesbutnotforprecisecountingofindividualeventsordeterminingminimumormaximumwaittimes.Statisticallyspeaking,thedatacollectedbyASHisprobablymoreaccurateoveralargertimeintervaland/ornumberofsessions.

    Forexample,youmightqueryv$active_session_historytoseewhatpercentageoftimeoverthelasttwohoursaparticulargroupofsessionsspentwaitingondiskreads.However,usingthisviewtodeterminehowmanydiskreadwaitsasessionencounteredinthelastminuteprobablywillnotyieldveryaccurateresults.

    EventhoughASHdataisonlyasamplingofactivesessions,theinformationcanprovetobequiteuseful.Forexample,thefollowingqueryshowsthatsessionsrunningtheARXENVapplicationoverthelasttwohoursencounteredagreatdealofrowlevellockcontention:

    SQL>SELECTDECODE(session_state,'WAITING',event,NULL)event,2session_state,COUNT(*),SUM(time_waited)time_waited3FROMv$active_session_history4WHEREmodule='ARXENV'5ANDsample_time>SYSDATE(2/24)6GROUPBYDECODE(session_state,'WAITING',event,NULL),7session_stateEVENTSESSION_STATECOUNT(*)TIME_WAITEDONCPU1240logfilesyncWAITING252686dbfilescatteredreadWAITING228254dbfilesequentialreadWAITING16059controlfilesequentialreadWAITING19206SQL*Netbreak/resettoclientWAITING19140enq:TXrowlockcontentionWAITING922930864016

    Inadditiontorunningqueriesagainstthev$active_session_historyview,youcanuseEnterpriseManagertorunreportsthatwilldisplayASHdata.

    AlthoughASHrunsonallOracle10gdatabasesbydefault,youarenotallowedtoquerythev$active_session_historyview(orrunthecorrespondingreportsinEnterpriseManager)unlessyouhavepurchasedtheDiagnosticPack.

    AutomaticWorkloadRepository

    Oracle10gincludesanothersignificantfacilityrelevanttothewaiteventinterface.ItsknownastheAutomaticWorkloadRepositoryorAWRforshort.AWRisbasicallyanextgenerationStatspack.Bydefault,AWRcollectsanhourlysnapshotofdatabaseperformanceinformation,storingthedataintablesintheSYSschema.AWRisconfiguredautomaticallywhenyoucreateanOracle10gdatabase.Youcancallthedbms_workload_repositorypackagetocollectasnapshotondemand,purgeasnapshotorrangeofsnapshots,orchangethesnapshotintervalorretentionperiod.(Bydefaultsnapshotsarecollectedatthetopofeachhourandarepurgedaftersevendays.)

    AWRcollectsthesametypeofdatathatStatspackdoesincludingsystemlevelstatistics,resourceintensiveSQL,andofcourseinstancewidewaiteventinformation.AWRalsocollectsdatathatisnewforOracle10g,suchastimemodelstatistics(whichwewilldiscussinthenextsection).Asanaside,theOracle10gversionofStatspackalsocollectsalotofthisnewinformation,includingtimemodelstatistics.

    YoucangenerateanAWRreportofdatabaseactivitybetweentwosnapshotsbyrunningtheawrrpt.sqlscriptintherdbms/admindirectoryunder$ORACLE_HOME.ThisscriptoffersreportsformattedasplaintextorHTML.ThereportswilllookfamiliarifyouhaveusedStatspackbefore.YoucanuseEnterpriseManagertogenerateAWRreportsaswell.

    AWRoffersmanybenefitsoverStatspack.Forone,itismoretightlyintegratedintotheOraclekernel,reducingresourcerequirementsandoverheadwhencollectingsnapshots.AWRsnapshotsalsoincludeASHdatafromv$active_session_history,providingsessionlevelinformationtocomplementthesystemleveldatacollectionfamiliartoStatspackusers.

    DatacollectedbyAWRismadeeasilyaccessibleviaviewswithnamesthatstartDBA_HIST.Thisenablesyoutowriteyourownreportsthatextractjustthedatayouneedtoaddressaspecificsituation,ifforsomereasonyoudontfindwhatyouneedinthestandardAWRreport.Forexample,thefollowingquerydisplaysthetwomostrecentsnapshotIDs:

    SQL>SELECTsnap_id,begin_interval_time,end_interval_time2FROM(3SELECTsnap_id,begin_interval_time,end_interval_time4FROMdba_hist_snapshot5ORDERBYend_interval_timeDESC6)7WHEREROWNUMDESCRIBEv$sys_time_modelNameNull?TypeSTAT_IDNUMBERSTAT_NAMEVARCHAR2(64)VALUENUMBERSQL>DESCRIBEv$sess_time_modelNameNull?TypeSIDNUMBERSTAT_IDNUMBERSTAT_NAMEVARCHAR2(64)VALUENUMBER

    Asamplequeryfromv$sys_time_modelshowsthefollowing:

    SQL>SELECTstat_name,value/1000000seconds2FROMv$sys_time_model3ORDERBYsecondsDESCSTAT_NAMESECONDSDBtime80970.190sqlexecuteelapsedtime75057.271DBCPU44448.628backgroundelapsedtime29333.160PL/SQLexecutionelapsedtime8824.538backgroundcputime5170.311parsetimeelapsed1270.147hardparseelapsedtime838.068PL/SQLcompilationelapsedtime176.731sequenceloadelapsedtime112.334connectionmanagementcallelapsedtime44.644failedparseelapsedtime11.946hardparse(sharingcriteria)elapsedtime5.579hardparse(bindmismatch)elapsedtime4.610failedparse(outofsharedmemory)elapsedtime0.000Javaexecutionelapsedtime0.000inboundPL/SQLrpcelapsedtime0.000

    ThisqueryshowsusalotmoreinformationabouthowOraclesessionshavespenttheirtime(categorically)thanv$sysstatandv$sesstatdo.Ofcourse,wehavetoknowhowtointerpretthisinformationbeforewecanputittoworkforus.Valuesintheseviewsareshowninmicroseconds,andtheydonotincludebackgroundprocessesunlessbackgroundappearsinthestatisticname.TheDBtimestatisticshowselapsedtimespentondatabasecalls(userprocessesonly).ThisamountstotimespentontheCPUorwaitingonnonidlewaitevents.Foradescriptionoftheothertimemodelstatistics,seethev$sess_time_modelviewlistingintheOracle10gDatabaseReferencemanual.

    Fromthisquery,amongmanyotherusefulfacts,wecanseethatnotimehasbeenspentexecutingJava,verylittletimehasbeenspenthardparsingorcompilingPL/SQL,backgroundprocesseshaveusedabout10%oftheCPUtime,andabout11%oftheelapsedtimeforusersessionswasspentonPL/SQLexecution.

    TracingFacilityImprovements

    TheextendedSQLtracefacility,alsoknownasevent10046,allowsustocaptureinatracefiledetailedinformationabouteverywaiteventencounteredbyadatabasesession.ThisfeaturehasbeenavailableinOracleforalongtime.However,Oracle10gofferssomehelpfulimprovementsinthisarea.

    EnablingextendedSQLtracehasalwaysbeenabitofanuisance.InearlierreleasesofOracle,youhadtouseaclumsyALTERSESSIONSETEVENTSstatementorworseyetcalltheundocumenteddbms_system.set_evproceduretosetthe10046eventinanotheruserssession.InOracle8ithedbms_supportpackagewasintroducedtomakethisstepeasier,butthepackagewasmissingfrommanyreleasesofOracleandusuallywasnotinstalledbydefault.

    Oracle10gintroducesthenewdbms_monitorpackage.Thispackage,amongmanyotherthings,makesitveryeasytoturnextendedSQLtraceonandoffinanyOraclesession.Withoneeasytoremembercall,youcanturnextendedSQLtraceonoroff,withwaiteventsand/orbindvariablescapturedinthetracefile:

    SQL>DESCRIBEdbms_monitor...PROCEDURESESSION_TRACE_DISABLEArgumentNameTypeIn/OutDefault?SESSION_IDBINARY_INTEGERINDEFAULTSERIAL_NUMBINARY_INTEGERINDEFAULTPROCEDURESESSION_TRACE_ENABLEArgumentNameTypeIn/OutDefault?SESSION_IDBINARY_INTEGERINDEFAULTSERIAL_NUMBINARY_INTEGERINDEFAULTWAITSBOOLEANINDEFAULTBINDSBOOLEANINDEFAULT

    Ifthesession_idparameterisnotspecifiedorsettoNULL,yourownsessionwillbetraced.Thus,thefollowingtwostatementsshouldbeequivalent:

    l ALTERSESSIONSETevents'10046tracenamecontextforever,level12'

    l EXECUTEdbms_monitor.session_trace_enable(waits=>TRUE,binds=>TRUE)

    InOracle9iandearlier,extendedSQLtracewaseasytouseifyourapplicationconnectedtotheOracledatabaseviaadedicatedserverconnection.Ifthesharedserverarchitecturewasused,eachsharedserverprocessthatservicedarequestfromthesessionbeingtracedwouldwriteitsdatatoaseparatetracefile.Furthermore,tracingsessionsinaconnectionpoolenvironmentbecamedifficultbecauseoneOraclesessioncouldactuallyprocessrequestsformanydifferentendusersessions.

    Thedbms_monitorpackageinOracle10gaddressesthisproblem.InsteadofenablingextendedSQLtraceforaspecificOraclesession,youcanenableitforaspecificclientidentifierorcombinationofservice,module,andaction.AnytimeanyOraclesessionhasthespecifiedclientidentifierorcombinationofservice,module,andaction,thesessionwillbetraced.Sessionscansetorcleartheirclientidentifieratwillbycallingthedbms_sessionpackage,andtheycansettheirmoduleandactionbycallingthedbms_application_infopackage.

    Supposeawebbasedapplicationusesapoolof30databaseconnectionstoserveuserrequestsandmaintainsacurrent_sessionstabletokeeptrackofthestateofeachendusersession.Whenauserclicksabuttonintheirbrowserwindow,theapplicationserverreceivestheHTTPrequestandhandsitofftoanapplicationserverprocess.Theapplicationserverprocessgrabsafreedatabaseconnectionfromthepoolandaccessesthedatabaseasnecessarytoservicetherequest.Itislikelythatsubsequentrequestsfromthesameuserwillbeprocessedusingdifferentdatabaseconnections.

    InOracle9iandearlieritwouldhavebeenverydifficulttotracetheoneusersdatabaseactivityinthisenvironment.TheusersdatabaseaccessesarespreadamongmultipleOracleserverprocessesintheconnectionpool.Moreover,eachofthoseOracleprocessesishandlingrequestsfrommanydifferentendusers.

    Withdbms_monitorinOracle10g,theapplicationcouldbemodifiedinawaytomakeextendedSQLtraceawholeloteasier.Wementionedthattheapplicationusesthecurrent_sessionstabletomaintainstateforeachendusersession.Eachtimetheapplicationservergrabsadatabaseconnectionfromthepool,itcouldsettheclientidentifierfortheOraclesessiontothesession_idfromthecurrent_sessionstablebeforedoinganydatabaseaccessforthatendusersession.Thentheapplicationcouldcleartheclientidentifierbeforereturningthedatabaseconnectiontothepool.TheOraclecallscouldlooklikethis:

    EXECUTEdbms_session.set_identifier('session_id174837492748')...dotheworkforthisendusersession...EXECUTEdbms_session.clear_identifier

    Totracethisendusersession,wecouldnowcallthedbms_monitorpackagelikethis:

    SQL>EXECUTEdbms_monitor.client_id_trace_enable>('session_id174837492748',waits=>TRUE,binds=>TRUE)

    Thiscalltodbms_monitorwillcauseeachOracleprocesstowriteextendedSQLtracedatatoatracefileforallcallsthatoccurwhiletheclientidentifierforthesessionissettothespecifiedvalue.However,eachOracleprocesswillwritetoitsowntracefile.Thiswillcausethetracedatatobesplitovermultiplefiles.Toaddressthisproblem,Oracle10gprovidesanewcommandlineutilitycalledtrcsess.ThetrcsessutilityreadsmultipletracefilesandconsolidatesentriesfromthevariousfilesthatmeetthespecifiedcriteriaintoonetracefilethatcanbeprocessedbyTKPROF.Toconsolidatethetracedataforourcurrentexample,wecouldusethefollowingcommands:

    $cd$ORACLE_BASE/admin/$ORACLE_SID/udump$trcsessoutput=/home/rschrag/case1403/case1403trial1.trc\clientid=session_id174837492748

    Inthiswaythedbms_monitorpackageandtrcsessutilityinOracle10gmakeitaloteasiertocollectextendedSQLtracedatafromanenduserssessionwhenconnectionpoolingorothersessionaggregationtechniquesareusedbytheapplicationservertier.

    Conclusion

    Oracle10gincludesmanyenhancementstothewaiteventinterfacethatshouldmakeperformancemanagementusingwaiteventmethodologieseasierthanever.Someenhancements,suchasdescriptivewaiteventnames,waitclasses,andthesession_trace_enableprocedureinthedbms_monitorpackage,aresimpleconveniencesthatmakeourjobseasier.Theseenhancementsdontgiveusanyinformationorpowerthatwedidnthavebefore.Otherenhancements,however,suchastimemodelstatistics,v$event_histogram,andnewcolumnsinv$sqlandv$sqlarea,provideuswithhelpfultimingandwaitinformationthatwaspreviouslyunavailable.

    AlthoughasofthiswritingdocumentationonthesenewfeaturesisincompleteanddiscussiononMetalinkissurprisinglysparse,manyoftheseenhancementswilllikelyprovequitevaluabletotheOracleDBAresponsibleforperformancemanagementofacomplexOraclesystem.

    EventWaitAnalysiswithSTATSPACK

    InSTATSPACK,youcangetasnapshotofOraclewaiteventseveryhourandplotchangesinwaitbehaviorovertime.Youcanalsosetthresholds,andreportonlyonwaiteventsthatexceedyourpredefinedthreshold.Hereisthescriptthatiscommonlyusedforexceptionreportingofwaitevents.

    Hereistheoutputfromthisscript.Aswecansee,wegetatimeseriesresult,showingusthosedaysandhourswhenourthresholdsareexceeded.Ifwelookatthislisting,weseethateveryeveningbetween10:00p.m.and11:00p.m.,weexperiencehighwaitsontheredologs.

    UsingQueriesAgainstv$event_wait

    Hereisthemostcommonlyusedscriptfordisplayingsystemwideevents,calledcurrent_waits.sql.

    Belowistheoutputfromthisscript.Aswesee,thereportshowsallcumulativewaitssinceinstancestartuptime.

    Thisshouldgivealistof"current"waitevents,butsomeeventsaremoreimportantthanothers.Thesearetheone'stowatchoutfor:

    l asyncdiskIOl controlfileparallelwritel controlfilesequentialreadl dbfileparallelwritel dbfilescatteredreadl dbfilesequentialreadl directpathreadl directpathwritel logfileparallelwritel logfilesync

    Oncewehaveasystemwidepictureofwaitevents,wecandrilldownintowaiteventsthataredirectlyassociatedwithbackgroundprocesses.

    Hereistheoutputfromthisscript.HereweseeeachbackgroundprocessandthetimeeachhasspentwaitingwithinOracle.

    Fromalloftheabovereports,weseethefollowingareasforimprovement:

    1Eventwaitsforparallelquerydequeues.Weneedtocheckthedefaultdegreeofparallelismfordatabaseobjectsandturnoffparallelismatthesystemlevel.

    2Eventwaitsfor"dbfilesequentialreads."Thisismostlikelyduetosegmentheadercontentionontheindexes,butitcouldalsobeduetodiskcontention.Wewillstartbyincreasingthenumberoffreelistsontheindexes.Ifthewaitspersist,theoffendingindexshouldbestripedacrossmultiplediskspindles.

    Theseareverygeneralwaitconditions,buttheycansometimesbefixedbychangingparametersorobjectcharacteristics.Somepossiblesolutionsinclude:

    l Improvetheoptimizers'propensitytouseindexesbyadjustingoptimizer_index_cost_adjtoavaluelessthan10,therebyreducingunnecessaryfulltablescans

    l Checkandadjustthevalueofparallel_threads_per_cputoreduceparallelquery

    Checkforsegmentheadercontention/waitsonindexheaders

    Createmultiplesegmentheaderblocksforstressedindexes(usingalterindexxxxstorage(freelists1))

    l Distributeheavyimpacttablesandindexesontoafasterdisk,orstripetheobjectacrossmultipledisks.

    SessionDetailEventWaitsOncewehavecoveredthesystemandbackgroundwaits,wecanfindtasksthatarecurrentlywaiting.Thisscriptistrickybecauseitmustberunningattheexactmomentofawait.SomeOracleprofessionalsrunthisscriptevery60seconds,sendinganemailwhenanimportantwaitoccurs:

    wait_detail_process.sqlscript.

    Hereistheoutputfromthisscript.Hereweseetwotypesofwaitconditions:

    WaitEvent Description

    bufferbusywaits Thesessionwantstoaccessadatablockthatiseither1)currentlynotinmemory,butanotherprocesshasalreadyissuedanI/Orequesttoreadtheblockintomemory,or2)inmemorybutinanincompatiblemode(currentversusconsistent,forexample).Forexampleanothersessionisusingthatblockviaaninsert,updateordelete.

    controlfileparallelwrite ThesessionhasissuedmultipleI/Orequestsinparalleltowriteblockstoallcontrolfiles,andiswaitingforallofthewritestocomplete.

    controlfilesequentialread Thesessioniswaitingforblockstobereadfromacontrolfile.

    dbfileparallelread ThesessionhasissuedmultipleI/Orequestsinparalleltoreadblocksfromdatafilesintomemoryandiswaitingforallrequeststocomplete.ThismayoccurduringrecoveryorduringregularactivitywhenasessionbatchesmanysingleblockI/Orequeststogetherandissuestheminparallel.

    dbfileparallelwrite Theprocess,typicallyDBWR,hasissuedmultipleI/Orequestsinparalleltowritedirtyblocksfromthebuffercachetodiskandiswaitingforallrequeststocomplete.

    dbfilescatteredread ThesessionhasissuedanI/Orequesttoreadaseriesofcontiguousblocksfromadatafileintothebuffercacheandiswaitingfortheoperationtocomplete.Thistypicallyhappensduringafulltablescanorfastfullindexscan.OraclereadsuptoDB_FILE_MULTIBLOCK_READ_COUNTconsecutiveblocksatatimeandscattersthemintobuffersinthebuffercache

    dbfilesequentialread ThesessionhasissuedanI/Orequesttoreadoneblockfromadatafileintothebuffercacheandiswaitingfortheoperationtocomplete.ThistypicallyhappensduringanindexlookuporafetchfromatablebyROWIDwhentherequireddatablockisnotalreadyinmemory.Thiscalldiffersfrom"dbfilescatteredread"inthatasequentialreadreadsdataintocontiguousmemory(whilstascatteredreadreadsmultipleblocksandscattersthemintodifferentbuffersintheSGA).

    directpathread,directpathwrite

    ThesessionhasissuedasynchronousI/Orequeststhatbypassthebuffercacheandiswaitingforthemtocomplete.Thesewaiteventsofteninvolvetemporarysegments,sortingactivity,parallelqueryorhashjoins.

    enqueue Thesessioniswaitingonanenqueue(alockyoucanseeinv$lock).Thiscommonlyoccurswhenoneuseristryingtoupdatearowinatablethatiscurrentlybeingupdatedbyanotheruser.

    freebufferwaits Thesessionneedsafreebuffersoitcanbringadatablockintothebuffercacheandiswaitingforabufferthatisnotdirtytobecomeavailable.ThiscanoccurifDBWRisnotwritingdirtybufferstodiskfastenough.

    latchfree Thesessioniswaitingforalatchheldbyanothersession.(Thiseventdoesnotapplytoprocessesthatarespinningwhilewaitingforalatchwhenaprocessisspinning,itisnotwaiting.)

    librarycacheloadlock Thesessioniswaitingfortheopportunitytoloadanobjectorapieceofanobjectintothelibrarycache.(Onlyoneprocesscanloadanobjectorapieceofanobjectatatime.)

    librarycachepin Thesessionwantstopinanobjectinmemoryinthelibrarycacheforexamination,ensuringnootherprocessescanupdatetheobjectatthesametime.ThishappenswhenyouarecompilingorparsingaPL/SQLobjectoraview.

    logbufferspace Thesessioniswaitingforspaceinthelogbuffer.(SpacebecomesavailableonlyafterLGWRhaswrittenthecurrentcontentsofthelogbuffertodisk.)ThistypicallyhappenswhenapplicationsgenerateredofasterthanLGWRcanwriteittodisk.

    logfileparallelwrite Thesessioniswaitingforblockstobewrittentoallonlineredologmembersinonegroup.LGWRistypicallytheonlyprocesstoseethiswaitevent.Itwillwaituntilallblockshavebeenwrittentoallmembers.

    logfilesequentialread Thesessioniswaitingforblockstobereadfromtheonlineredologintomemory.ThisprimarilyoccursatinstancestartupandwhentheARCHprocessarchivesfilledonlineredologs.

    logfileswitchcompletion Thesessioniswaitingforalogfileswitchtocomplete,typicallysomoreredocanbegenerated.

    logfilesync ThesessioniswaitingforLGWRtofinishflushingthelogbuffertodisk.Thisoccurswhenausercommitsatransaction.(Atransactionisnotconsideredcommitteduntilalloftheredotorecoverthetransactionhasbeensuccessfullywrittentodisk).Probablyyouarecommitingtoooften

    undosegmentextension Thesessioniswaitingforanundosegmenttobeextendedorshrunk.

    writecompletewaits Thesessioniswaitingforarequestedbuffertobewrittentodiskthebuffercannotbeusedwhileitisbeingwritten.

    IdleEvents

    clientmessage PXDeq:ExecuteReply

    dispatchertimer PXDeq:ExecutionMsg

    gcsforaction PXDeq:SignalACK

    gcsremotemessage PXDeq:TableQNormal

    gesremotemessage PXDequewait

    i/oslavewait PXIdleWait

    jobqslavewait queuemessages

    lockmanagerwaitforremotemessage rdbmsipcmessage

    nullevent slavewait

    parallelquerydequeue smontimer

    pipeget SQL*Netmessagefromclient

    PL/SQLlocktimer SQL*Netmessagetoclient

    pmontimer SQL*Netmoredatafromclient

    PXDeqCredit:needbuffer virtualcircuitstatus

    PXDeqCredit:sendblkd wakeuptimemanager

    DebugEventSetting Effect

    10046tracenamecontextforever,level1 EnablesordinarySQLtrace

    10046tracenamecontextforever,level4 EnablesSQLtracewithbindvariablevaluesincludedintracefile

    10046tracenamecontextforever,level8 EnablesSQLtracewithwaiteventinformationincludedintracefile

    10046tracenamecontextforever,level12 Equivalentoflevel4andlevel8together

    10046tracenamecontextoff Turnsofftracing

    Administrative IdleApplication NetworkCluster SchedulerCommit SystemI/OConcurrency UserI/OConfiguration Other

    application_wait_timeconcurrency_wait_timecluster_wait_timeuser_io_wait_timeplsql_exec_timejava_exec_time

    promptpromptprompt***********************************************************promptExcessivewaitsonbackgroundeventsprompt***********************************************************promptttitle'Highwaitsonbackgroundevents|Rollupbyhour'columnmydateheading'Yr.MoDyHr'formata13columneventformata30columntotal_waitsheading'totwaits'format999,999columntime_waitedheading'timewait'format999,999columntotal_timeoutsheading'timeouts'format9,999breakonto_char(snap_time,'yyyymmdd')skip1selectto_char(snap_time,'yyyymmddHH24')mydate,e.event,e.total_waitsnvl(b.total_waits,0)total_waits,e.time_waitednvl(b.time_waited,0)time_waited,e.total_timeoutsnvl(b.total_timeouts,0)total_timeoutsfromstats$bg_event_summaryb,stats$bg_event_summarye,stats$snapshotsnwheresnap_time>sysdate&1ande.eventnotlike'%timer'ande.eventnotlike'%message%'ande.eventnotlike'%slavewait%'ande.snap_id=sn.snap_idandb.snap_id=e.snap_id1andb.event=e.eventande.total_timeouts>100and(e.total_waitsb.total_waits>100ore.time_waitedb.time_waited>100)

    WedAug21page1HighwaitsonbackgroundeventsRollupbyhourYr.MoDyHrEVENTtotwaitstimewaittimeouts2002081822LGWRwaitforredocopy9,3261,1092862002081823LGWRwaitforredocopy8,50631682002081823bufferbusywaits21421,3882062002081900LGWRwaitforredocopy498502002081901LGWRwaitforredocopy4971502002081922LGWRwaitforredocopy9,2071,4334272002081922bufferbusywaits52953,4125152002081923LGWRwaitforredocopy9,06636792002081923bufferbusywaits25024,4792362002082000LGWRwaitforredocopy7711602002082022LGWRwaitforredocopy8,0302,0136342002082022bufferbusywaits35635,5833432002082023LGWRwaitforredocopy8,021579862002082023bufferbusywaits44144,6774322002082100LGWRwaitforredocopy1,0132612002082100rdbmsipcreply16030,9861492002082101LGWRwaitforredocopy541170

    setpages999setlines90columnc1heading'Event|Name'formata30columnc2heading'Total|Waits'format999,999,999columnc3heading'Seconds|Waiting'format999,999columnc4heading'Total|Timeouts'format999,999,999columnc5heading'Average|Wait|(insecs)'format99.999ttitle'SystemwideWaitAnalysis|forcurrentwaitevents'selecteventc1,total_waitsc2,time_waited/100c3,total_timeoutsc4,average_wait/100c5fromsys.v_$system_eventwhereeventnotin('dispatchertimer','lockelementcleanup','Nullevent','parallelquerydequeuewait','parallelqueryidlewaitSlaves','pipeget','PL/SQLlocktimer','pmontimer','rdbmsipcmessage','slavewait','smontimer','SQL*Netbreak/resettoclient','SQL*Netmessagefromclient','SQL*Netmessagetoclient','SQL*Netmoredatatoclient','virtualcircuitstatus','WMONgoestosleep')ANDeventnotlike'DFS%'andeventnotlike'%done%'andeventnotlike'%Idle%'ANDeventnotlike'KXFX%'orderbyc2desc

    TueAug20page1SystemwideWaitAnalysisforcurrentwaiteventsAverageEventTotalSecondsTotalWaitNameWaitsWaitingTimeouts(insecs)dbfilesequentialread2,902,8503,8290.001latchfree2,248,8644961,524,235.000PXDeq:TableQNormal2,080,4634,469248.002PXDeqCredit:sendblkd1,321,01952,25123,032.040directpathread986,9516,9310.007PXDeqCredit:needbuffer800,9701,09184.001logfileparallelwrite415,1755,0782.012directpathwrite321,0969,3420.029PXDeq:ExecutionMsg198,76856,38426,020.284logfilesequentialread118,4801640.001PXDeq:ExecuteReply92,4875,6282,407.061logfilesync87,2951,3277.015dbfilescatteredread70,1121620.002enqueue44,3351,468354.033PXDeq:JoinACK42,503770.002fileopen28,54580.000PXDeq:SignalACK26,7532536,705.009logfileswitchcompletion54185.341controlfileparallelwrite23,7853400.014SQL*Netmoredatafromclient19,8478780.044PXDeq:ParseReply17,885260.001dbfileparallelwrite17,7451,2934.073PXDeq:MsgFragment15,612188.001rdbmsipcreply11,01316766.015PXDeq:TableQqref7,77820.000LGWRwaitforredocopy7,608243.000controlfilesequentialread4,09810.000bufferbusywaits2,97090.003PXDeq:TableQSample2,0532527.012librarycachepin1,35360.004PXDeq:TableQGetKeys53010.001localwritewait317177163.560fileidentify31500.000refreshcontrolfilecommand21400.002PXqreflatch135105102.780logfilesinglewrite8020.021immop6700.000processstartup6120.036writecompletewaits3334331.032librarycacheloadlock2562.256logbufferspace2060.286dbfilesinglewrite600.007rowcachelock500.006dbfileparallelread200.010instancestatechange200.000reliablemessage100.010librarycachelock100.020

    setpages999setlines90columnc1heading'System|ID'format999columnc2heading'Prcs'formata10columnc3heading'Event|Name'formata30columnc4heading'Total|Waits'format999,999columnc5heading'Time|Waited|(insecs)'format999,999columnc6heading'Avg|Wait|secs'format999columnc7heading'Avg|Wait|secs'format999columnc8heading'Max|Wait|(insecs)'format999ttitle'SystemwideWaitAnalysis|DetailAnalysis|forcurrentwaitevents'selectb.sidc1,decode(b.username,NULL,c.name,b.username)c2,eventc3,a.total_waitsc4,round((a.time_waited/100),2)c5,a.total_timeoutsc6,round((average_wait/100),2)c7,round((a.max_wait/100),2)c8fromsys.v_$session_eventa,sys.v_$sessionb,sys.v_$bgprocesscwhereeventNOTLIKE'DFS%'andeventNOTLIKE'KXFX%'anda.sid=b.sidandb.paddr=c.paddr(+)andeventNOTIN('lockelementcleanup','pmontimer','rdbmsipcmessage','smontimer','SQL*Netmessagefromclient','SQL*Netbreak/resettoclient','SQL*Netmessagetoclient','SQL*Netmoredatatoclient','dispatchertimer','Nullevent','iodone','parallelquerydequeuewait','parallelqueryidlewaitSlaves','pipeget','PL/SQLlocktimer','slavewait','virtualcircuitstatus','WMONgoestosleep')orderby4desc

    TueAug20page1SystemwideWaitAnalysisDetailAnalysisforcurrentwaiteventsTimeAvgAvgMaxSystemEventTotalWaitedWaitWaitWaitIDPrcsNameWaits(insecs)secssecs(insecs)3LGWRlogfileparallelwrite415,0825,07620111ARC0logfilesequentialread108,8341390004CKPTcontrolfileparallelwrite23,0353270014CKPTfileopen20,84240002DBW0dbfileparallelwrite17,6841,2924014CKPTdirectpathread9,74510600625ARC1logfilesequentialread9,603250003LGWRLGWRwaitforredocopy7,608243004CKPTdirectpathwrite3,74320005SMONdbfilescatteredread1,82470004CKPTcontrolfilesequentialread1,35500005SMONdbfilesequentialread7942000156CPA1_OWNERdbfilesequentialread67730003LGWRcontrolfilesequentialread468000011ARC0controlfilesequentialread43300003LGWRcontrolfileparallelwrite27160002DBW0controlfilesequentialread25300003LGWRfileopen1900000160CPA1_USERlogfilesync152200025ARC1controlfilesequentialread14300002DBW0fileopen11200005SMONfileopen11100002DBW0directpathread10800003LGWRdirectpathread10820002DBW0fileidentify10800003LGWRdirectpathwrite107000011ARC0controlfileparallelwrite103200011ARC0fileidentify102000012fileopen91000016fileopen90100020fileopen8910003LGWRlogfilesinglewrite8020003LGWRfileidentify800000183CPA1_USERlogfilesync73100011ARC0fileopen7000003LGWRimmop6700003LGWRlogfilesequentialread43000015fileopen3800006RECOdbfilesequentialread360000156CPA1_OWNERlatchfree3402100160CPA1_USERlatchfree30020002DBW0latchfree29129005SMONlatchfree1701100125SYSlatchfree140700183CPA1_USERlatchfree1409003LGWRlatchfree1101100156CPA1_OWNERfileopen11000025ARC1controlfileparallelwrite90000183CPA1_USERdbfilesequentialread9000025ARC1fileidentify90000115CPA1_USERlogfilesync8000025ARC1fileopen800004CKPTfileidentify4000015latchfree303002DBW0processstartup30000160CPA1_USERdbfilesequentialread3000011ARC0enqueue24023132CPA1_USERlogfilesync20000125SYSdbfilesequentialread200004CKPTlatchfree1010012latchfree1010011ARC0processstartup100003LGWRenqueue130336RECOfileopen10000183CPA1_USERfileopen10000125SYSfileopen10000160CPA1_USERfileopen10000166ANANDfileopen10000166ANANDdbfilesequentialread10000125SYSlogfilesync100005SMONbufferbusywaits1000025ARC1enqueue100003LGWRprocessstartup1000016latchfree101006RECOlatchfree10100

    TueAug20page1SystemwideWaitAnalysisDetailAnalysisforcurrentwaiteventsTimeAvgAvgMaxSystemEventTotalWaitedWaitWaitWaitIDPrcsNameWaits(insecs)secssecs(insecs)3LGWRlogfileparallelwrite415,0825,07620111ARC0logfilesequentialread108,8341390004CKPTcontrolfileparallelwrite23,0353270014CKPTfileopen20,84240002DBW0dbfileparallelwrite17,6841,2924014CKPTdirectpathread9,74510600625ARC1logfilesequentialread9,603250003LGWRLGWRwaitforredocopy7,608243004CKPTdirectpathwrite3,74320005SMONdbfilescatteredread1,82470004CKPTcontrolfilesequentialread1,35500005SMONdbfilesequentialread7942000156CPA1_OWNERdbfilesequentialread67730003LGWRcontrolfilesequentialread468000011ARC0controlfilesequentialread43300003LGWRcontrolfileparallelwrite27160002DBW0controlfilesequentialread25300003LGWRfileopen1900000160CPA1_USERlogfilesync152200025ARC1controlfilesequentialread14300002DBW0fileopen11200005SMONfileopen11100002DBW0directpathread10800003LGWRdirectpathread10820002DBW0fileidentify10800003LGWRdirectpathwrite107000011ARC0controlfileparallelwrite103200011ARC0fileidentify102000012fileopen91000016fileopen90100020fileopen8910003LGWRlogfilesinglewrite8020003LGWRfileidentify800000183CPA1_USERlogfilesync73100011ARC0fileopen7000003LGWRimmop6700003LGWRlogfilesequentialread43000015fileopen3800006RECOdbfilesequentialread360000156CPA1_OWNERlatchfree3402100160CPA1_USERlatchfree30020002DBW0latchfree29129005SMONlatchfree1701100125SYSlatchfree140700183CPA1_USERlatchfree1409003LGWRlatchfree1101100156CPA1_OWNERfileopen11000025ARC1controlfileparallelwrite90000183CPA1_USERdbfilesequentialread9000025ARC1fileidentify90000115CPA1_USERlogfilesync8000025ARC1fileopen800004CKPTfileidentify4000015latchfree303002DBW0processstartup30000160CPA1_USERdbfilesequentialread3000011ARC0enqueue24023132CPA1_USERlogfilesync20000125SYSdbfilesequentialread200004CKPTlatchfree1010012latchfree1010011ARC0processstartup100003LGWRenqueue130336RECOfileopen10000183CPA1_USERfileopen10000125SYSfileopen10000160CPA1_USERfileopen10000166ANANDfileopen10000166ANANDdbfilesequentialread10000125SYSlogfilesync100005SMONbufferbusywaits1000025ARC1enqueue100003LGWRprocessstartup1000016latchfree101006RECOlatchfree10100

  • InterpretingWaitEventsWhatareWaitEvents?CommonWaitEventsCollectingWaitEventsTracingWaitEvents10gWaitInterfaceEnhanmentsEventWaitAnalysiswithStatspackHowWaitEventscanbeusedtoimproveperformance(withgoodexamples)Moreexampleson10g

    WhatareWaitEvents?

    "WaitEvent"Defined

    Atanygivenmoment,everyOracleprocessiseitherbusyservicingarequestorwaitingforsomethingspecifictohappen.By"busy"wemeanthattheprocesswishestousetheCPU.Forexample,adedicatedserverprocessmightbesearchingthebuffercachetoseeifacertaindatablockisinmemory.Thisprocesswouldbesaidtobebusyandnotwaiting.TheARC0process,meanwhile,mightbewaitingforLGWRtosignalthatanonlineredologneedsarchiving.Inthiscase,theARC0processiswaiting.ThekerneldevelopersatOraclehavedefinedalistofeverypossibleeventthatanOracleprocesscouldbewaitingfor.Atanymoment,everyOracleprocessthatisnotbusyiswaitingforoneoftheseeventstooccur.SupposeanapplicationhassubmittedaCOMMITstatementandtheserverprocessiswaitingfortheLGWRprocesstosignalthattheredologbufferhasbeenflushedtodisk.Thiswaiteventiscalled"logfilesync."AnotherdedicatedserverprocessmightbewaitingforarowlevellockontheINVOICEStabletobefreedsothataSELECTFORUPDATEstatementcancontinue.Thatwaiteventiscalled"enqueue."Byqueryingv$views,wecanseewhateventsprocessesarewaitingontoanamazinglevelofdetail.Forexample,wemightlearnthatadedicatedserverprocesshasbeenwaiting30millisecondsfortheoperatingsystemtoreadeightblocksfromdatafile42,startingatblock18042.WecanalsoseesummaryinformationofhowmuchtimeeachOracleprocesshasspentwaitingoneachtypeofwaiteventforthedurationoftheprocess.Inaddition,wecandirectanOracleprocesstowritedetailedwaiteventdatatoatracefileforlateranalysisusingTKPROF.

    WhyWaitEventInformationisUseful

    Usingthewaiteventinterface,youcangetinsightsintowheretimeisbeingspent.Ifareporttakesfourhourstocomplete,forexample,thewaiteventinterfacewilltellyouhowmuchofthatfourhourswasspentwaitingfordiskreadscausedbyfulltablescans,diskreadscausedbyindexlookups,latchcontention,andsoon.Thewaiteventinterfaceprovidesmuchmoreinformationtoworkwiththancachehitratiosdo.YougetdatathatcantouchuponsomanydifferentareasofyourdatabasesuchasdiskI/O,latches,parallelprocessing,networktraffic,checkpoints,androwlevellocking.Atthesametime,yougetincredibledetailsuchasthefilenumberandblocknumberofablockbeingreadfromdisk,orthenameofalatchbeingwaitedonalongwiththenumberofretries.Thewaiteventinterfacewillnotalwaysgiveyoualloftheinformationyouneedinordertodiagnoseandsolveaproblem,butitwillcertainlypointyouintherightdirection.Youmightthinkthebuffercacheistoosmallbecausethecachehitratioisonly70%,butinfact,theapplication'sslowresponsetimecouldbecausedbylatchcontentioninthesharedpool,abottleneckinthelogwriter,oranyofanumberofotherthings.

    PriortoOracle10g,Oracle'sdefaultoptimizermodewascalledchoose.Inthechooseoptimizermode,Oraclewillexecutetherulebasedoptimizeriftherearenostatisticspresentforthetableitwillexecutethecostbasedoptimizerifstatisticsarepresent.ThedangerwithusingthechooseoptimizermodeisthatproblemscanoccurincaseswhereoneOracletableinacomplexqueryhasstatisticsandtheothertablesdonot.StartinginOracle10g,thedefaultoptimizermodeisall_rows,favoringfulltablescansoverindexaccess.Theall_rowsoptimizermodeisdesignedtominimizecomputingresourcesanditfavorsfulltablescans.Indexaccess(first_rows)addsadditionalI/Ooverhead,buttheyreturnrowsfaster.WhenonlysometablescontainCBOstatistics,Oraclewillusethecostbasedoptimizationandestimatestatisticsfortheothertablesinthequeryatruntime.Thiscancausesignificantslowdownintheperformanceoftheindividualquery.

    CommonWaitEventNamesandWhatTheyMean

    Althoughtherearemanydifferenttypesofwaitevents,themajorityofthemcomeupveryinfrequentlyortendnottobesignificant.Inpractice,onlyafewdozenwaiteventstendtobeofinteresttomostDBAs.You'llseedifferentwaiteventssurfacingindifferentenvironmentsbasedonwhichOraclefeatureshavebeenimplementedandwhichcapabilitiesofthedatabasearebeingtaxedthemost.Forexample,thePXwaiteventswon'tappearifyouaren'tusingparallelquery,andthevirtualcircuitstatuswaiteventwon'tappearifyouarenotusingthemultithreadedserverarchitecture(orsharedserverarchitectureasitismorerecentlycalled).Alongthoselines,thelogfilesyncandenqueuewaiteventsprobablywon'tbeprevalentinaprimarilyreadonlysystem.Herearesomeofthemostcommonwaiteventsandwhattheymean:

    Thereareseveralwaiteventsthatwecall"idleevents"becauseeachofthesewaiteventstypicallyoccurswhentheOracleprocesshasnothingtodoandiswaitingforsomebodytogiveitatask.Idleeventsareusuallynotveryinterestingfromatuningstandpoint,soweusuallyoverlookthemwhenevaluatingdataextractedfromthewaiteventinterface.Thecommonidleeventsareasfollows:

    WhatWaitEventInformationDoesNotProvide

    IfanOracleprocesshasworktodobut,mustwaitforsomethingtohappenbeforeitcancontinue,thentheprocesswillbewaitingonanonidlewaitevent.Ifaprocesshasnothingtodo,itwillbewaitingonanidlewaitevent.Sowhathappensifaprocesshasworktodoandisbusydoingit?Whenaprocessisbusy,therewillbenoinformationinthewaiteventinterfacesincetheprocessisnotwaiting.

    WhenwelookatthewaiteventinformationextractedfromanOracleinstance,weseedetailedinformationabouthowmanytimesandhowmuchtimewasspentwaitingforspecificeventstooccur.ButwedonotseeanythingaboutthetimeperiodsinwhichtheprocessrequesteduseoftheCPU.Thismeansthatthewaiteventinterfaceisnotabletoprovideinformationaboutthefollowing:

    l TimespentusingtheCPUl TimespentwaitingforaCPUtobecomeavailablel Timespentwaitingforrequestedmemorytobeswappedbackintophysicalmemory

    Thisisimportanttokeepinmindbecausethereisaneasytraptofallinto.YoucouldbetroubleshootingaveryslowSELECTstatementandlearnfromthewaiteventinterfacethattheprocessdoesnothavesignificantwaiteventswhenrunningthequery.Thiscouldleadyoutothinkthatthestatementisoptimal,andthatitjusttakesalongtimetorun.Infact,however,thequerymightbeperforminghugenumbersoflogicalreadsandthenumberofbuffergetscouldbereducedbyrewritingthequery.

    WhenOracleneedstoaccessadatablockandtheblockisalreadyinthebuffercache,alogicalreadoccurswithnophysicalread.Theprocessisabletoreadtheblockwithouttheoccurrenceofanywaitevents.LargeamountsofCPUtimecouldbeconsumedonsignificantnumbersoflogicalreads,andthewaiteventinterfacewillhavenothingtoshowfortheelapsedtime.Statementparsingandspinningwhilewaitingforalatchtobecomeavailablearetwootherexamplesofactivitiesnotaccountedforbythewaiteventinterface.AnOracleprocessusesCPUtimewhileparsingastatementorspinningonabusylatchsincenowaitingisinvolved,thewaiteventinterfacedoesnothaveanythingtoreport.BeginninginOracle9i,theportionoftheStatspackreportthatlistswaiteventinformationalsolistsCPUusage.Thisisveryhelpfulinformation.Itallowsustoeasilycomparetimespentwaitingtotimespentprocessing,soweknowwheretofocusourtuningefforts.However,itshouldbepointedoutthattheCPUusageinformationinthissectionoftheStatspackreportdoesnotcomefromthewaiteventinterface.Instead,StatspackmergesdatacollectedfromthewaiteventinterfacewithCPUusageinformationcollectedfromthev$sysstatdynamicperformanceview.

    ANoteAboutthetimed_statisticsParameter

    TheOraclekerneliscapableoftimingmanyactivitiesincludingwaitevents.InOracle9iRelease2timedstatisticsarecollectedbydefault,andsometimingsarecollectedinunitsofmicroseconds.Thetimed_statisticsinstanceparameterisusedtoenableanddisabletimedstatisticscollection.Whentimed_statisticsissettoFALSE,alltimesinthewaiteventinterfacewillappearaszero.Youmayenabletimedstatisticscollectionattheinstanceorthesessionlevelwiththefollowingcommands:

    l ALTERSYSTEMSETtimed_statistics=TRUEl ALTERSESSIONSETtimed_statistics=TRUE

    Youmayenabletimedstatisticsattheinstancelevelonthenextandallsubsequentinstancerestartsbyaddingthefollowinglinetotheinstanceparameterfile:

    timed_statistics=true

    Inpractice,theoverheadofcollectingtimedstatisticsisextremelysmall.Inmostcases,thebenefityou'llgetfromhavingtiminginformationatyourdisposalwilloutweightheperformanceoverhead.Forseveralyears,manyDBAshavebeenrunningtheirproductionsystemswithtimedstatisticsenabledatalltimes.WithOracle9iRelease2,thisisnowthedefaultbehavior.

    CollectingWaitEventInformation

    Therearetwocommonwaysofcollectingwaiteventinformation:theOracleextendedtrace(10046event)andusingV$viewswhichisthemaintopicofthisarticle.AnyuserwiththeSELECTANYTABLEsystemprivilegeortheSELECT_CATALOG_ROLErolecanquerythev$views.OnlyuserswhocanconnecttothedatabaseasSYSDBAorexecutetheDBMS_SUPPORTorDBMS_SYSTEMpackagescanactivatewaiteventtracinginotherdatabasesessions.Inatypicalenvironment,DBAshaveaccesstothewaiteventinterfacebutgeneralusersdonot.Oracleprovidesanumberofviewstoaidintuningafeware:*V$SYSTEM_EVENT,whichgivesyoutotalsystemwaitsforaneventsincedatabasestartup.*V$SESSION_EVENT,whichisatthesessionlevel.*V$SESSION_WAITgivesyouwhatanactivesessioniswaitingonatthatpointintime.*V$SESSION,whichgivesyousessioninformationandhasacolumnROW_WAIT_OBJ#thattellsyoutheobjectinvolvedwhenjoinedwithOBJECT_IDorDATA_OBJECT_IDinDBA_OBJECTS.Version10ghassomemoreV$viewsfortrackinghistorycalledV$%_HISTORY,includingV$ACTIVE_SESSION_HISTORY(ASH),whichsamplesnonidlewaiteventseverysecondandnewcolumnsinV$SESSIONtocombineinformationinV$SESSION_WAIT.

    Inadditiontothefourdynamicperformanceviews,Oracleprovidesatracingfacilitywhereextremelydetailedwaiteventinformationiswrittentoatracefileforlaterevaluation.InmorerecentreleasesofOracle,aPL/SQLpackageisprovidedforactivatingthewaiteventtracingfacility.InolderreleasesofOracle,thewaiteventtracingfacilityisactivatedbysettingdebugeventnumber10046(nottobeconfusedwithawaitevent).

    TheV$SYSTEM_EVENTViewThev$system_eventviewshowsonerowforeachwaiteventname,alongwiththetotalnumberoftimesaprocesshaswaitedforthisevent,thenumberoftimeouts,thetotalamountoftimewaited,andtheaveragewaittime.AllofthesefiguresarecumulativeforallOracleprocessessincetheinstancestarted.Waiteventsthathavenotoccurredatleastoncesinceinstancestartupdonotappearinthisview.Thev$system_eventviewhasthefollowingcolumns:

    NameNull?TypeEVENTVARCHAR2(64)TOTAL_WAITSNUMBERTOTAL_TIMEOUTSNUMBERTIME_WAITEDNUMBERAVERAGE_WAITNUMBERTIME_WAITED_MICRONUMBER

    EVENTisthenameofthewaitevent.YoucanseealistofallwaiteventnamesknowntoyourOraclekernelwiththefollowingquery:SELECTnameFROMv$event_nameTOTAL_WAITSisthetotalnumberoftimesaprocesshaswaitedforthiseventsinceinstancestartup.TOTAL_TIMEOUTSisthetotalnumberoftimesaprocessencounteredatimeoutwhilewaitingforanevent.Whenaprocessbeginstowaitforanevent,itspecifiesatimeoutperiodafterwhichtheoperatingsystemshouldwakeitupiftheeventhasnotyettranspired.Forexample,whenanOracleprocessissuesanI/Orequesttoreadablockfromadatafile(thedbfilesequentialreadwaitevent),theprocesssetsatimeoutofonesecond.UsuallytheI/Orequestwillcompleteinlessthanonesecondandnotimeoutwilloccur.Butifthereadshouldtakelongerthanonesecondforwhateverreason,atimeoutwilloccurandtheprocesswillwakeup.Theprocessmightdosomeminorhousekeeping,butitwilllikelyjustbeginanothertimeoutperiodofonesecondandcontinuewaitingforthesameevent.TIME_WAITEDandAVERAGE_WAITshowthecumulative(sum)andaveragetimespentbyprocesseswaitingforthisevent,incentiseconds.Dividethesefiguresby100inordertogetthewaittimeinseconds.Thesetwocolumnswillshowaszeroiftimedstatisticsarenotenabled.TIME_WAITED_MICROisthesameasTIME_WAITED,exceptthatthetimeisinmicroseconds.Dividethisfigureby1000000inordertogetthewaittimeinseconds.

    Considerthefollowingqueryfromv$system_event:

    SELECTevent,time_waitedFROMv$system_eventWHEREeventIN('SQL*Netmessagefromclient','smontimer','dbfilesequentialread','logfileparallelwrite')EVENTTIME_WAITED(sec)logfileparallelwrite1596.92dbfilesequentialread286.57smontimer1306738.37SQL*Netmessagefromclient165289.89Sinceinstancestartup,processesonthissystemhavewaitedatotalof286.57secondswhilereadingsingledatafileblocksfromdisk,andover1,596seconds(26minutes)

    TheV$SESSION_EVENTViewThev$session_eventviewisalotlikethev$system_eventview,exceptthatitshowsseparaterowsofinformationforeachOracleprocess.Aswithv$system_event,eventnamesdonotappearinthisviewiftheprocesshasnotwaitedforthematleastonce.Also,whenanOracleprocessterminates(asinthecaseofwhenauserlogsoffthedatabase)alloftherowsinv$session_eventforthatprocesspermanentlydisappear.Thev$session_eventviewhasthefollowingcolumns:

    NameNull?TypeSIDNUMBEREVENTVARCHAR2(64)TOTAL_WAITSNUMBERTOTAL_TIMEOUTSNUMBERTIME_WAITEDNUMBERAVERAGE_WAITNUMBERMAX_WAITNUMBERTIME_WAITED_MICRONUMBER

    SIDindicatesthesessionIDoftheprocesswaitingfortheevent.Youcanqueryv$sessioninordertodeterminetheSIDofthesessionwhosewaiteventsyouwanttoinvestigate.Thenextfivecolumnsinthev$session_eventviewarethesameasinthev$system_eventview,exceptthatnowtheypertaintotheonespecificprocessinsteadofallprocesses.MAX_WAITindicatesthemaximumamountoftimetheprocesshadtowaitfortheevent.LikeTIM


Top Related

Wednesday morning Accounting. Accounting -- Recording, classifying, summarizing and interpreting of financial events and transactions in an organization
Wednesday morning Accounting. Accounting -- Recording, classifying, summarizing and interpreting of financial events and transactions in an organization
Getting it Right Interpreting - Interlingua Events · Interpreting Getting it Right A guide to buying interpreting services INTER GIR F COLOUR.indd 1 20/9/11 7:31:38 pm
Getting it Right Interpreting - Interlingua Events · Interpreting Getting it Right A guide to buying interpreting services INTER GIR F COLOUR.indd 1 20/9/11 7:31:38 pm
Wait Events 10g
Wait Events 10g
Package Menu 2020 - creativecateringperth.com · 100-150 guests - 1 chef, 3 wait staff - $555 150+ guests - 2 chefs, 4 wait staff - $840 Sit down / share style events Chefs and kitchen
Package Menu 2020 - creativecateringperth.com · 100-150 guests - 1 chef, 3 wait staff - $555 150+ guests - 2 chefs, 4 wait staff - $840 Sit down / share style events Chefs and kitchen
Cognitive Therapy Cognitive therapy sees individuals as active participants in their environments, judging and evaluating stimuli, interpreting events
Cognitive Therapy Cognitive therapy sees individuals as active participants in their environments, judging and evaluating stimuli, interpreting events
Description of Oracle7 Wait Events and Enqueues
Description of Oracle7 Wait Events and Enqueues
Interpreting Heisenberg Interpreting Quantum Statesphilsci-archive.pitt.edu/9269/1/heisenbergpaper.pdf · Interpreting Heisenberg Interpreting Quantum States Simon Friederich
Interpreting Heisenberg Interpreting Quantum Statesphilsci-archive.pitt.edu/9269/1/heisenbergpaper.pdf · Interpreting Heisenberg Interpreting Quantum States Simon Friederich
Wait Events in Rac
Wait Events in Rac