【移动应用开发技术】Benchmarking And Profiling（性能评测和剖析）

【移动应用开发技术】BenchmarkingAndProfiling（性能评测和剖析）

Beingabletomeasureperformanceisrequired针对性能进行度量inordertodeterminewhetheroptimizationsareneeded是否需要优化,andwhethertheoptimizationsactuallyimprovedanything优化后是否有提升.

Performanceinmostcaseswillbemeasuredasafunctionofthetimeittakestocompleteanoperation.Forexample,theperformanceofagamewillveryoftenbemeasuredinhowmanyframespersecondcanberendered每秒渲染多少帧来度量,whichdirectlydependsonhowmuchtimeittakestorenderframes:toachieveaconstantframerate恒定数率of60framespersecond,eachframeshouldtakelessthan16.67millisecondstorenderanddisplay.Also,aswediscussedinChapter1,aresponsetimeof100millisecondsisoftendesiredinorderforresultstoappearinstantaneous有瞬时的感觉.

Inthischapteryoulearnthevariouswaysofmeasuringtimeinyourapplication.Youalsolearnhowtouseaprofilingtool剖析工具,Traceview,totraceJavacodeandnativecodeandeasilyidentifybottlenecks瓶颈inyourapplication.Finally,youlearnabouttheloggingmechanisminAndroidandhowtotakeadvantageofthefilteringcapabilities日志过滤机制的方法.6.1MeasuringTime测量时间

Howmuchtimeanoperation操作orsequenceofoperations操作序列takestocompleteisacriticalpieceofinformationwhenitistimetooptimizecode.Withoutknowinghowmuchtimeisspentdoingsomething,youroptimizationsareimpossibletomeasure.JavaandAndroidprovidethefollowingsimpleAPIsyourapplicationcanusetomeasuretimeandthereforeperformance:System.currentTimeMillisSystem.nanoTimeDebug.threadCpuTimeNanosSystemClock.currentThreadTimeMillisSystemClock.elapsedRealtimeSystemClock.uptimeMillis

Typically,yourapplicationneedstomaketwocallstothesemethodsasasinglecallishardlymeaningful.Tomeasuretime,yourapplicationneedsastarttimeandanendtime,andperformanceismeasuredasthedifferencebetweenthesetwovalues.Attheriskofsoundingoverlypatronizing,nowisagoodtimetostatethatthereare1,000,000,000nanosecondsinonesecond,orinotherwords,ananosecondisonebillionthofasecond.

NOTE:Eventhoughsomemethodsreturnatimeexpressedinnanoseconds,itdoesnotimplynanosecondaccuracy纳秒级的.Theactualaccuracydependsontheplatformandmaydifferbetweendevices.Similarly,System.currentTimeMillis()returnsanumberofmillisecondsbutdoesnotguaranteemillisecondaccuracy.

AtypicalusageisshowninListing6–1.Listing6–1.MeasuringTimelongstartTime=System.nanoTime();//performoperationyouwanttomeasureherelongduration=System.nanoTime()-startTime;System.out.println(“Duration:”+duration);

AnimportantdetailisthefactthatListing6–1doesnotuseanythingAndroid-specific.Asamatteroffact,thismeasurementcodeisonlyusingthejava.lang.System,java.lang.Stringandjava.io.PrintStreampackages.Consequently,youcouldusesimilarcodeinanotherJavaapplicationthatisnotmeanttorunonanAndroiddevice.TheDebugandSystemClockclassesare,ontheotherhand,Android-specific.WhileSystem.currentTimeMillis()waslistedasamethodtomeasuretime,itisactuallynotrecommendedtousethismethod,fortworeasons:

Itsprecisionandaccuracy精度准确度maynotbegoodenough.

Changingthesystemtimecanaffecttheresults.

Instead,yourapplicationshoulduseSystem.nanoTime()asitoffersbetterprecisionandaccuracy.6.1.1System.nanoTime()

Becausethereferencetimeisnotdefined,youshouldonlyuseSystem.nanoTime()tomeasuretimeintervals,asshowninListing6–1.Togetthetime(asaclock),useSystem.currentTimeMillis()asitdefinesthereturnvalueasthenumberofmillisecondssinceJanuary1,197000:00:00UTC.Listing6–2showsyouhowtomeasure,roughly,thetimeittakesforSystem.nanoTime()tocomplete.Listing6–2.MeasuringSystem.nanoTime()privatevoidmeasureNanoTime(){finalintITERATIONS=100000;longtotal=0;longmin=Long.MAX_VALUE;longmax=Long.MIN_VALUE;for(inti=0;i<ITERATIONS;i++){longstartTime=System.nanoTime();longtime=System.nanoTime()-startTime;total+=time;if(time<min){min=time;}if(time>max){max=time;}}Log.i(TAG,"Averagetime:"+((float)total/ITERATIONS)+"nanoseconds");Log.i(TAG,"Minimum:"+min);Log.i(TAG,"Maximum:"+max);}OnaSamsungGalaxyTab10.1,theaveragetimeisabout750nanoseconds.

NOTE:HowmuchtimeacalltoSystem.nanoTime()takesdependsontheimplementationandthedevice.

Becausethescheduler调度器isultimatelyresponsibleforschedulingthreadstorunontheprocessingunits,theoperationyouwanttomeasuremaysometimesbeinterrupted,possiblyseveraltimes,tomakeroomforanotherthread.Therefore,yourmeasurementmayincludetimespentonexecutingsomeothercode,whichcanmakeyourmeasurementincorrect,andthereforemisleading.

Tohaveabetterideaofhowmuchtimeyourowncodeneedstocomplete,youcanusetheAndroid-specificDebug.threadCpuTimeNanos()method.

6.1.2Debug.threadCpuTimeNanos()

Becauseitmeasuresonlythetimespentinthecurrentthread,

Debug.threadCpuTimeNanos()shouldgiveyouabetterideaofhowmuchtimeyourowncodetakestocomplete.However,ifwhatyouaremeasuringisexecutedinmultiplethreads,asinglecalltoDebug.threadCpuTimeNanos()won’tgiveyouanaccurateestimate,andyouwouldhavetocallthismethodfromallthethreadsofinterestandsumtheresults.Listing6–3showsasimpleexampleofhowDebug.threadCpuTimeNanos()canbeused.TheusageisnodifferentfromSystem.nanoTime()’s,anditshouldonlybeusedtomeasureatimeinterval.Listing6–3.UsingDebug.threadCpuTimeNanos()longstartTime=Debug.threadCpuTimeNanos();//warning:thismayreturn-1ifthesystemdoesnotsupportthisoperation//simplysleepforonesecond(otherthreadswillbescheduledtorunduringthattime)try{TimeUnit.SECONDS.sleep(1);//sameasThread.sleep(1000);}catch(InterruptedExceptione){e.printStackTrace();}longduration=Debug.threadCpuTimeNanos()-startTime;Log.i(TAG,"Duration:"+duration+"nanoseconds");

WhilethecodewilltakeaboutonesecondtocompletebecauseofthecalltoTimeUnit.SECONDS.sleep(),theactualtimespentexecutingcodeismuchless.Infact,runningthatcodeonaGalaxyTab10.1showsthatthedurationisonlyabout74microseconds.ThisisexpectedasnothingmuchisdoneinbetweenthetwocallstoDebug.threadCpuTimeNanos()otherthanputtingthethreadtosleepforonesecond.

NOTE:RefertotheTimeUnitclassdocumentation.TimeUnitoffersconvenientmethodsforconvertingtimebetweendifferentunitsandalsoperformingthread-relatedoperationssuchas

Thread.join()andObject.wait().Ofcourse,youcanalsomeasuretimeinyourapplication’sCcodeusing“standard”Ctimefunctions,asshowninListing6–4.Listing6–4.UsingCTimeFunction#include<time.h>voidfoo(){doubleduration;time_ttime=time(NULL);//dosomethinghereyouwanttomeasureduration=difftime(time(NULL),time);//durationinseconds}

6.2Tracing方法调用跟踪

Onceyouidentifywhatistakingtoomuchtime,youprobablywanttobeabletoknowinmoredetailwhichmethodsaretheculprits×××.Youcandothisbycreatingtracefileswiththehelpofatracing-specificmethod,andthenanalyzethemwiththeTraceviewtool.6.2.1Debug.startMethodTracing()

AndroidprovidestheDebug.startMethodTracing()methodtocreatetracefilesthatcanthenbeusedwiththeTraceviewtooltodebugandprofileyourapplication.ThereareactuallyfourvariantsoftheDebug.startMethodTracing()method:startMethodTracing()startMethodTracing(StringtraceName)startMethodTracing(StringtraceName,intbufferSize)startMethodTracing(StringtraceName,intbufferSize,intflags)

ThetraceNameparameterspecifiesthenameofthefiletowritethetraceinformationinto写入跟踪信息的文件名.(Ifthefilealreadyexistsitwillbetruncated.)Youneedtomakesureyourapplicationhaswriteaccesstothisfile.(Bydefault,thefilewillbecreatedinthesdcarddirectoryunlessanabsolutepathisgiven.)ThebufferSizeparameterspecifiesthemaximumsizeofthetracefile.Traceinformationcanuseafairamountofspaceandyourstoragecapacitymaybelimitedsotrytouseasensiblevalue(defaultis8MB).Androidcurrentlydefinesonlyoneflag,Debug.TRACE_COUNT_ALLOCS,sotheflagsparametershouldbesettoeither0orDebug.TRACE_COUNT_ALLOCS(toaddtheresultsfromDebug.startAllocCounting()tothetrace,thatis,thenumberandaggregatesizeofmemoryallocations).AndroidalsoprovidestheDebug.stopMethodTracing()method,which,youwouldhaveguessed,stopsthemethodtracing.Theusageisverysimilartotimemeasurementsseenearlier,asshowninListing6–5.Debug.startMethodTracing(“/sdcard/awesometrace.trace”);//performoperationyouwanttotracehereBigIntegerfN=FputeRecursivelyWithCache(100000);Debug.stopMethodTracing();//nowthereshouldbeafilenamedawesometrace.tracein/mnt/sdcard,getitinEclipseDDMS

ThetracefilewillbesavedontoyourAndroiddevice(ortheemulator),soyouwillneedtocopythefilefromthedevicetoyourhostmachine,forexampleinEclipse(usingDDMS)orwiththe“adbpull”command.6.2.2UsingtheTraceviewTool

TheAndroidSDKcomeswithatoolnamedTraceview,whichcanusethesetracefilesandgiveyouagraphicalrepresentationofthetrace,asshowninFigure6–1.YoucanfindtheTraceviewtoolintheSDK’stoolsdirectoryandsimplytypetraceviewawesometrace.traceonacommandlinetostartTraceview.Figure6–1.Traceviewwindow

Thetracebasicallycontainsthelistofallthefunctioncallstogetherwithhowmuchtimethesecallstookandhowmanyweremade.Sevencolumnsaredisplayed:Name:thenameofthemethodIncl%:thepercentageoftimespentinthatmethod(includingchildrenmethods)此方法中占的时间百分比Inclusive:thetimeinmillisecondsspentinthatmethod(includingchildrenmethods)Excl%:thepercentageoftimespentinthatmethod(excludingchildrenmethods)Exclusive独家新闻:thetimeinmillisecondsspentinthatmethod(excludingchildrenmethods)Calls+RecurCalls/Total:thenumberofcallsandrecursivecallsTime/Call:theaveragetimepercallinmillisecondsForexample,atotalof14callstoBigInteger.multiply()weremadeforatotalof10.431milliseconds,or745microsecondspercall.BecausetheVMwillrunmoreslowlywhentracingisenabled,youshouldnotconsiderthetimevaluesasdefinitivenumbers.Instead,usethesetimevaluessimplytodeterminewhichmethodorrunisfaster.Ifyouclickonamethodname,Traceviewwillshowyoumoredetailedinformationforthatspecificmethod,asshowninFigure6–2.Thisincludes:Parents(themethodscallingthismethod)Children(themethodscalledbythismethod)Parentswhilerecursive(ifmethodisrecursive)Childrenwhilerecursive(ifmethodisrecursive)AsyoucanseeinFigure6–2,mostofthetimeisspentonfourmethods:BigInteger.multiply()BigInteger.pow()BigInteger.add()BigInteger.shiftLeft()

EventhoughweestablishedwherethebottleneckswereinChapter1already,Traceviewallowsyoutoveryquicklydeterminewheretheycanbewithouthavingtoperformanyexpansiveresearch进一步花精力研究.Inthisparticularcase,youcanquicklyseethatBigInteger.multiply()iswheremostofthetimeisspent,followedbyBigInteger.pow().Thisisnotsurprisingasmultiplicationsareintuitively直观的morecomplicatedthanadditionsandshiftsdonebyBigInteger.add()andBigInteger.shiftLeft().Figure6–2.Amethod’sdetailedinformation

Atthetopofthewindow,youcanseethetimelineforthemainthread.Youcanzoom急速上升inbyselectingacertainregioninthistimeline,andzoomoutbydouble-clickingonthetimescale.FamiliarizeyourselfwiththeTraceviewtoolandlearnhowtonavigatefromonemethodtoanother.

Hint:it’seasy.Justclickonamethod’sname!

BecausetheJust-In-Timecompilerisdisabledwhentracingisenabled,theresultsyougetcanbesomewhatmisleading.Infact,youmaythinkamethodtakesacertaintimewheninrealityitcanbemuchfastersinceitcanbecompiledintonativecodebytheDalvikJust-In-Timecompiler.Also,thetracewon’tshowyouhowmuchtimeisspentinnativefunctions.Forexample,Figure6–1showscallstoNativeBN.BN_mul()andNativeBN.BN_exp(),butifyouclickonthesemethods,youwon’tseewhatothermethodstheymaycall.6.2.3TraceviewinDDMS

AnotherwaytotracecallsanduseTraceviewistogenerateatracefiledirectlyfromtheEclipseDDMSperspective观点（视图）.Afteryouselectaspecificprocess,youcanclickontheStartMethodProfilingicon,andthenclickagaintostopprofiling.Onceyoustopprofiling,thetracewillbevisibleintheDebugperspectiveinEclipseanditwillbelikeusingTraceview.Figure6–3showshowtostartmethodprofilingfromtheDDMSperspective,andFigure6–4showsyouthemethodprofilingviewintheDebugperspective.Figure6–3.StartingmethodprofilingfromtheDDMSperspectiveFigure6–4.MethodprofilingintheDebugperspectiveAsyoucanseeinFigure6–4,timelinesformultiplethreadscanbeshown.

Traceviewisnotperfect,howeveritcangiveyougreatinsightintowhatcodeisactuallyexecutedandwherethebottlenecksmaybe.Whenitistimetoachievebetterperformance,thisshouldbeoneofyourpreferredtoolstodetectwhereyoushouldfocusyourattention.

TIP:Remembertodeletethetracefileswhenyouaredonewithyourdebuggingandprofiling.YoucanusetheEclipseDDMSperspectivetodeletefilesfromyourdevice.6.2.4NativeTracing本地方法追踪

InadditiontoprofilingJavamethodswiththestartMethodTracing()APIs,Androidalsosupportsnativetracing(includingkernelcode).NativetracingisalsoreferredtoasQEMUtracing.InthissectionyoulearnhowtogeneratetheQEMUtracefilesandhowtoconvertthemintoafileTraceviewcaninterpret..TogenerateQEMUtraces,youhavetodotwothings:Starttheemulatorusingthe–traceoption(forexample,“emulator–tracemytrace–avdmyavd”).Startandthenstopnativetracing,eitherbycallingDebug.startNativeTracing()andDebug.stopNativeTracing(),orbypressingtheF9key(thefirsttimewillstarttracing,thesecondtimewillstoptracing).IntheAVD’stracesdirectoryonyourhostmachine,youwillthenfindamytracedirectorycontainingseveralQEMUemulatortracefiles:qtrace.bbqtrace.excqtrace.insnqtrace.methodqtrace.pidqtrace.staticNOTE:QEMUisanopen-sourceemulator.Refertoformoreinformation.GeneratingTraceFileForTraceviewTousethetracesinTraceviewlikewedidforJavamethods,youneedtogenerateatracefilethatTraceviewcanunderstand.Todothis,youwillusethetracedmdumpcommand(nottobeconfusedwiththedmtracedumpSDKtool,whichisatoolusedtocreatethecallstackasatreediagram).ThetracedmdumpcommandisdefinedintheAndroidsourcecode,inbuild/envsetup.sh.Foraccesstothiscommand,youhavetodownloadtheAndroidsourcecodeandcompileAndroid.TodownloadthefullAndroidcode,followtheinstructionson:/source/downloading.html.TocompileAndroid,followtheinstructionson/source/building.html

YoucanalsocompileyourownemulatorfromtheAndroidsourcecodeinsteadofrelyingontheonefromtheSDK.OnceAndroidiscompiled,youshouldhaveallthetoolsyouneedtocreatethetracefileTraceviewneeds.

IntheAVD’stracesdirectory,youcannowsimplyruntracedmdumpmytrace,whichwillcreateatracefileyoucanopenwithTraceview,asshowninFigure6–5.Makesureyourpathissetsothatallthecommandsexecutedbytracedmdumpcansucceed.Iftracedmdumpfailswitha“commandnotfound”errormessage,itislikelyyourpathisnotsetproperly.Forexample,tracedmdumpwillcallpost_trace,whichislocatedintheout/host/linux-x86/bindirectory.

Figure6–5.NativetracingwithTraceviewWhiletheuserinterfacestaysthesame,whatyouactuallyseeinFigure6–5isthelistofnativefunctionsbeingcalled,suchasvsnprintf()andsys_open(),respectively#10and#13.

Twofilesrepresentingthesamedataareactuallycreatedbytracedmdump:dmtrace

dmtrace.html

ThefirstfileistobeusedwithTraceviewwhilethesecondcanbeopenedwithanywebbrowser,includingLynx.

NOTE:Manyusersreportproblemswhenusingtracedmdump,anderrormessagesarenotalwaysveryclear.Ifyouencounteranerror,searchforasolutionontheInternetasitisverylikelysomeonehadthesameproblemandpublishedasolution.Sometimessimplyhavingareal-time,human-readabledescriptionofwhatishappeninginyourapplicationcanhelpyoutremendously.Loggingmessageshavebeenusedforaverylongtimebeforesophisticateddebuggingtoolswereinvented,andmanydeveloperswillheavilyrelyonlogstodebugorprofileapplications日志调试或者剖析应用.6.3Logging日志

Aswehaveseeninmanylistingsalready,youcanusetheLogclasstoprintoutmessagestoLogCat.InadditiontotheJavatraditionalloggingmechanismsuchasSystem.out.println(),Androiddefinessixloglevels,eachhavingitsownmethods:verbose(Log.v)debug(Log.d)info(Log.i)warning(Log.w)error(Log.e)assert(Log.wtf)Forexample,acalltoLog.v(TAG,“mymessage”)isequivalenttoacalltoLog.println(Log.VERBOSE,TAG,“mymessage”).

NOTE:TheLog.wtf()methodswereintroducedinAPIlevel8,butLog.ASSERTexistssinceAPIlevel1.IfyouwanttousetheASSERTloglevelbutwanttoguaranteecompatibilitywitholderAndroiddevices,useLog.println(Log.ASSERT,…)insteadofLog.wtf(…).YoucanthenuseLogCatinEclipse(Window

ShowView

LogCat)and/orinaterminal(adblogcat,orsimplylogcatfromanadbshell)andseethemessagesgeneratedwhileyourapplicationruns.Sincemanymessagesmaybedisplayed,manyofthemnotcomingfromyourapplication,youmaywanttocreatefilterssoyoucanfocusontheoutputthatisrelevanttoyou.Youcanfiltermessagesbasedontheirtags,prioritylevels,andPIDs.InEclipse,youcanusetheCreateFilterfeature,asshowninFigure6–6.Figure6–6.CreatingLogCatfilterwithEclipseEclipsecurrentlydoesnotsupportcreatingafilteronmultipletags,soyouwillhavetouseadblogcatinsteadifyouwanttodo