Benchmarking And Profiling（性能评测和剖析）

蔚落 2022-01-15 10:51 315阅读 0赞

Being able to measure performance is required针对性能进行度量 in order to determine whether optimizations are needed是否需要优化, and whether the optimizations actually improved anything优化后是否有提升.  
Performance in most cases will be measured as a function of the time it takes to  
complete an operation. For example, the performance of a game will very often be  
measured in how many frames per second can be rendered每秒渲染多少帧来度量, which directly depends on how much time it takes to render frames: to achieve a constant frame rate恒定数率 of 60 frames per second, each frame should take less than 16.67 milliseconds to render and display. Also, as we discussed in Chapter 1, a response time of 100 milliseconds is often desired in order for results to appear instantaneous有瞬时的感觉.  
In this chapter you learn the various ways of measuring time in your application. You  
also learn how to use a profiling tool剖析工具, Traceview, to trace Java code and native code and easily identify bottlenecks瓶颈 in your application. Finally, you learn about the logging mechanism in Android and how to take advantage of the filtering capabilities日志过滤机制的方法.

6.1 Measuring Time 测量时间

How much time an operation操作 or sequence of operations操作序列 takes to complete is a critical piece of information when it is time to optimize code. Without knowing how much time is spent doing something, your optimizations are impossible to measure. Java and Android provide the following simple APIs your application can use to measure time and therefore performance:  
System.currentTimeMillis  
System.nanoTime  
Debug.threadCpuTimeNanos  
SystemClock.currentThreadTimeMillis  
SystemClock.elapsedRealtime  
SystemClock.uptimeMillis  
Typically, your application needs to make two calls to these methods as a single call is  
hardly meaningful. To measure time, your application needs a start time and an end  
time, and performance is measured as the difference between these two values. At the  
risk of sounding overly patronizing, now is a good time to state that there are  
1,000,000,000 nanoseconds in one second, or in other words, a nanosecond is one  
billionth of a second.  
NOTE: Even though some methods return a time expressed in nanoseconds, it does not imply nanosecond accuracy纳秒级的. The actual accuracy depends on the platform and may differ between devices. Similarly, System.currentTimeMillis() returns a number of milliseconds but does not guarantee millisecond accuracy.  
A typical usage is shown in Listing 6–1.  
Listing 6–1. Measuring Time  
long startTime = System.nanoTime();  
// perform operation you want to measure here  
long duration = System.nanoTime() - startTime;  
System.out.println(“Duration: ” + duration);  
An important detail is the fact that Listing 6–1 does not use anything Android-specific.  
As a matter of fact, this measurement code is only using the java.lang.System,  
java.lang.String and java.io.PrintStream packages. Consequently, you could use similar  
code in another Java application that is not meant to run on an Android device. The  
Debug and SystemClock classes are, on the other hand, Android-specific.  
While System.currentTimeMillis() was listed as a method to measure time, it is  
actually not recommended to use this method, for two reasons:  
Its precision and accuracy精度准确度 may not be good enough.  
Changing the system time can affect the results.  
Instead, your application should use System.nanoTime() as it offers better precision and  
accuracy.  
6.1.1 System.nanoTime()  
Because the reference time is not defined, you should only use System.nanoTime() to  
measure time intervals, as shown in Listing 6–1. To get the time (as a clock), use  
System.currentTimeMillis() as it defines the return value as the number of milliseconds  
since January 1, 1970 00:00:00 UTC.  
Listing 6–2 shows you how to measure, roughly, the time it takes for System.nanoTime()  
to complete.  
Listing 6–2. Measuring System.nanoTime()  
private void measureNanoTime() \{  
final int ITERATIONS = 100000;  
long total = 0;  
long min = Long.MAX\_VALUE;  
long max = Long.MIN\_VALUE;  
for (int i = 0; i < ITERATIONS; i++) \{  
long startTime = System.nanoTime();  
long time = System.nanoTime() - startTime;  
total += time;  
if (time < min) \{  
min = time;  
\}  
if (time > max) \{  
max = time;  
\}  
\}  
Log.i(TAG, "Average time: " + ((float)total / ITERATIONS) + " nanoseconds");  
Log.i(TAG, " Minimum: " + min);  
Log.i(TAG, " Maximum: " + max);  
\}  
On a Samsung Galaxy Tab 10.1, the average time is about 750 nanoseconds.  
NOTE: How much time a call to System.nanoTime() takes depends on the implementation and the device.  
Because the scheduler调度器 is ultimately responsible for scheduling threads to run on the processing units, the operation you want to measure may sometimes be interrupted,  
possibly several times, to make room for another thread. Therefore, your measurement  
may include time spent on executing some other code, which can make your  
measurement incorrect, and therefore misleading.  
To have a better idea of how much time your own code needs to complete, you can use  
the Android-specific Debug.threadCpuTimeNanos() method.

6.1.2 Debug.threadCpuTimeNanos()

Because it measures only the time spent in the current thread,  
Debug.threadCpuTimeNanos() should give you a better idea of how much time your own  
code takes to complete. However, if what you are measuring is executed in multiple  
threads, a single call to Debug.threadCpuTimeNanos() won’t give you an accurate  
estimate, and you would have to call this method from all the threads of interest and  
sum the results.

Listing 6–3 shows a simple example of how Debug.threadCpuTimeNanos() can be used.  
The usage is no different from System.nanoTime()’s, and it should only be used to  
measure a time interval.  
Listing 6–3. Using Debug.threadCpuTimeNanos()  
long startTime = Debug.threadCpuTimeNanos();  
// warning: this may return -1 if the system does not support this operation  
// simply sleep for one second (other threads will be scheduled to run during that  
time)  
try \{  
TimeUnit.SECONDS.sleep(1);  
// same as Thread.sleep(1000);  
\} catch (InterruptedException e) \{  
e.printStackTrace();  
\}  
long duration = Debug.threadCpuTimeNanos() - startTime;  
Log.i(TAG, "Duration: " + duration + " nanoseconds");  
While the code will take about one second to complete because of the call to  
TimeUnit.SECONDS.sleep(), the actual time spent executing code is much less. In fact,  
running that code on a Galaxy Tab 10.1 shows that the duration is only about 74  
microseconds. This is expected as nothing much is done in between the two calls to  
Debug.threadCpuTimeNanos() other than putting the thread to sleep for one second.  
NOTE: Refer to the TimeUnit class documentation. TimeUnit offers convenient methods for converting time between different units and also performing thread-related operations such as  
Thread.join() and Object.wait().  
Of course, you can also measure time in your application’s C code using “standard” C  
time functions, as shown in Listing 6–4.  
Listing 6–4. Using C Time Function  
\#include <time.h>  
void foo() \{  
double duration;  
time\_t time = time(NULL);  
// do something here you want to measure  
duration = difftime(time(NULL), time); // duration in seconds  
\}

6.2 Tracing 方法调用跟踪

Once you identify what is taking too much time, you probably want to be able to know in  
more detail which methods are the culprits×××. You can do this by creating trace files with the help of a tracing-specific method, and then analyze them with the Traceview tool.

6.2.1 Debug.startMethodTracing()

Android provides the Debug.startMethodTracing() method to create trace files that can  
then be used with the Traceview tool to debug and profile your application. There are  
actually four variants of the Debug.startMethodTracing() method:  
startMethodTracing()  
startMethodTracing(String traceName)  
startMethodTracing(String traceName, int bufferSize)  
startMethodTracing(String traceName, int bufferSize, int flags)  
The traceName parameter specifies the name of the file to write the trace information  
into写入跟踪信息的文件名. (If the file already exists it will be truncated.) You need to make sure your  
application has write access to this file. (By default, the file will be created in the sdcard  
directory unless an absolute path is given.) The bufferSize parameter specifies the  
maximum size of the trace file. Trace information can use a fair amount of space and  
your storage capacity may be limited so try to use a sensible value (default is 8MB).  
Android currently defines only one flag, Debug.TRACE\_COUNT\_ALLOCS, so the flags  
parameter should be set to either 0 or Debug.TRACE\_COUNT\_ALLOCS (to add the results  
from Debug.startAllocCounting() to the trace, that is, the number and aggregate size of  
memory allocations). Android also provides the Debug.stopMethodTracing() method,  
which, you would have guessed, stops the method tracing. The usage is very similar to  
time measurements seen earlier, as shown in Listing 6–5.

Debug.startMethodTracing(“/sdcard/awesometrace.trace”);  
// perform operation you want to trace here  
BigInteger fN = Fibonacci.computeRecursivelyWithCache(100000);  
Debug.stopMethodTracing();  
// now there should be a file named awesometrace.trace in /mnt/sdcard, get it in  
Eclipse DDMS  
The trace file will be saved onto your Android device (or the emulator), so you will need  
to copy the file from the device to your host machine, for example in Eclipse (using  
DDMS) or with the “adb pull” command.

6.2.2 Using the Traceview Tool

The Android SDK comes with a tool named Traceview, which can use these trace files  
and give you a graphical representation of the trace, as shown in Figure 6–1. You can  
find the Traceview tool in the SDK’s tools directory and simply type traceview  
awesometrace.trace on a command line to start Traceview.  
Figure 6–1. Traceview window  
The trace basically contains the list of all the function calls together with how much time  
these calls took and how many were made. Seven columns are displayed:  
Name: the name of the method  
Incl %: the percentage of time spent in that method (including children methods)此方法中占的时间百分比  
Inclusive: the time in milliseconds spent in that method (including children methods)  
Excl %: the percentage of time spent in that method (excluding  
children methods)  
Exclusive 独家新闻: the time in milliseconds spent in that method (excluding  
children methods) Calls+RecurCalls/Total: the number of calls and recursive calls  
Time/Call: the average time per call in milliseconds  
For example, a total of 14 calls to BigInteger.multiply() were made for a total of  
10.431 milliseconds, or 745 microseconds per call. Because the VM will run more slowly  
when tracing is enabled, you should not consider the time values as definitive numbers.  
Instead, use these time values simply to determine which method or run is faster.  
If you click on a method name, Traceview will show you more detailed information for  
that specific method, as shown in Figure 6–2. This includes:  
Parents (the methods calling this method)  
Children (the methods called by this method)  
Parents while recursive (if method is recursive)  
Children while recursive (if method is recursive)  
As you can see in Figure 6–2, most of the time is spent on four methods:  
BigInteger.multiply()  
BigInteger.pow()  
BigInteger.add()  
BigInteger.shiftLeft()  
Even though we established where the bottlenecks were in Chapter 1 already, Traceview  
allows you to very quickly determine where they can be without having to perform any  
expansive research进一步花精力研究. In this particular case, you can quickly see that  
BigInteger.multiply() is where most of the time is spent, followed by  
BigInteger.pow(). This is not surprising as multiplications are intuitively直观的 more  
complicated than additions and shifts done by BigInteger.add() and  
BigInteger.shiftLeft().  
Figure 6–2. A method’s detailed information  
At the top of the window, you can see the timeline for the main thread. You can zoom急速上升 in  
by selecting a certain region in this timeline, and zoom out by double-clicking on the  
time scale. Familiarize yourself with the Traceview tool and learn how to navigate from  
one method to another.

Hint: it’s easy. Just click on a method’s name!  
Because the Just-In-Time compiler is disabled when tracing is enabled, the results you  
get can be somewhat misleading. In fact, you may think a method takes a certain time  
when in reality it can be much faster since it can be compiled into native code by the  
Dalvik Just-In-Time compiler. Also, the trace won’t show you how much time is spent in  
native functions. For example, Figure 6–1 shows calls to NativeBN.BN\_mul() and  
NativeBN.BN\_exp(), but if you click on these methods, you won’t see what other  
methods they may call.

6.2.3 Traceview in DDMS

Another way to trace calls and use Traceview is to generate a trace file directly from the  
Eclipse DDMS perspective观点（视图）. After you select a specific process, you can click on the  
Start Method Profiling icon, and then click again to stop profiling. Once you stop profiling, the trace will be visible in the Debug perspective in Eclipse and it will be like using Traceview. Figure 6–3 shows how to start method profiling from the DDMS perspective, and Figure 6–4 shows you the method profiling view in the Debug perspective.  
Figure 6–3. Starting method profiling from the DDMS perspective  
Figure 6–4. Method profiling in the Debug perspective  
As you can see in Figure 6–4, timelines for multiple threads can be shown.  
Traceview is not perfect, however it can give you great insight into what code is actually executed and where the bottlenecks may be. When it is time to achieve better performance, this should be one of your preferred tools to detect where you should focus your attention.

TIP: Remember to delete the trace files when you are done with your debugging and profiling.  
You can use the Eclipse DDMS perspective to delete files from your device.

6.2.4 Native Tracing 本地方法追踪

In addition to profiling Java methods with the startMethodTracing() APIs, Android also  
supports native tracing (including kernel code). Native tracing is also referred to as QEMU tracing. In this section you learn how to generate the QEMU trace files and how to convert them into a file Traceview can interpret.. To generate QEMU traces, you have to do two things:  
Start the emulator using the –trace option (for example, “emulator –  
trace mytrace –avd myavd”).  
Start and then stop native tracing, either by calling Debug.startNativeTracing() and Debug.stopNativeTracing(), or by pressing the F9 key (the first time will start tracing, the second time  
will stop tracing). In the AVD’s traces directory on your host machine, you will then find a mytrace  
directory containing several QEMU emulator trace files:  
qtrace.bb  
qtrace.exc  
qtrace.insn  
qtrace.method  
qtrace.pid  
qtrace.static  
NOTE: QEMU is an open-source emulator. Refer to

[http://wiki.qemu.org][http_wiki.qemu.org] for more information. Generating Trace File For Traceview  
To use the traces in Traceview like we did for Java methods, you need to generate a  
trace file that Traceview can understand. To do this, you will use the tracedmdump  
command (not to be confused with the dmtracedump SDK tool, which is a tool used to  
create the call stack as a tree diagram). The tracedmdump command is defined in the  
Android source code, in build/envsetup.sh. For access to this command, you have to  
download the Android source code and compile Android.  
To download the full Android code, follow the instructions on:  
[http://source.android.com/source/downloading.html][http_source.android.com_source_downloading.html].  
To compile Android, follow the instructions on  
[http://source.android.com/source/building.html][http_source.android.com_source_building.html]  
 You can also compile your own emulator from the Android source code instead of  
relying on the one from the SDK. Once Android is compiled, you should have all the  
tools you need to create the trace file Traceview needs.  
In the AVD’s traces directory, you can now simply run tracedmdump mytrace, which will  
create a trace file you can open with Traceview, as shown in Figure 6–5. Make sure your  
path is set so that all the commands executed by tracedmdump can succeed. If  
tracedmdump fails with a “command not found” error message, it is likely your path is not  
set properly. For example, tracedmdump will call post\_trace, which is located in the  
out/host/linux-x86/bin directory.  
Figure 6–5. Native tracing with Traceview  
While the user interface stays the same, what you actually see in Figure 6–5 is the list of  
native functions being called, such as vsnprintf() and sys\_open(), respectively \#10 and  
\#13.  
Two files representing the same data are actually created by tracedmdump:  
dmtrace  
dmtrace.html  
The first file is to be used with Traceview while the second can be opened with any web  
browser, including Lynx.  
NOTE: Many users report problems when using tracedmdump, and error messages are not always very clear. If you encounter an error, search for a solution on the Internet as it is very likely someone had the same problem and published a solution.  
Sometimes simply having a real-time, human-readable description of what is happening  
in your application can help you tremendously. Logging messages have been used for a  
very long time before sophisticated debugging tools were invented, and many  
developers will heavily rely on logs to debug or profile applications日志调试或者剖析应用.

6.3 Logging日志

As we have seen in many listings already, you can use the Log class to print out messages to LogCat. In addition to the Java traditional logging mechanism such as System.out.println(), Android defines six log levels, each having its own methods:  
verbose (Log.v)  
debug (Log.d)  
info (Log.i)  
warning (Log.w)  
error (Log.e)  
assert (Log.wtf)  
For example, a call to Log.v(TAG, “my message”) is equivalent to a call to Log.println(Log.VERBOSE, TAG, “my message”).  
NOTE: The Log.wtf() methods were introduced in API level 8, but Log.ASSERT exists since  
API level 1. If you want to use the ASSERT log level but want to guarantee compatibility with  
older Android devices, use Log.println(Log.ASSERT, …) instead of Log.wtf(…).  
You can then use LogCat in Eclipse (Window Show View LogCat) and/or in a terminal  
(adb logcat, or simply logcat from an adb shell) and see the messages generated while  
your application runs. Since many messages may be displayed, many of them not coming from your  
application, you may want to create filters so you can focus on the output that is relevant to you. You can filter messages based on their tags, priority levels, and PIDs. In  
Eclipse, you can use the Create Filter feature, as shown in Figure 6–6.  
Figure 6–6. Creating LogCat filter with Eclipse  
Eclipse currently does not support creating a filter on multiple tags, so you will have to use adb logcat instead if you want to do that. For example, to show only log messages with the tag “MyTag” at priority “Debug” or above (that is, Debug, Info, Warning, Error, and Assert), and log messages with the tag “MyOtherTag” at priority “Warning” or  
above, you can type:  
adb logcat MyTag:D MyOtherTag:W \*:S  
Make sure you don’t forget the \*:S part since it means all other log messages will be filtered out. (S is for Silent.)  
Logging functions are also available in the NDK, so you can use LogCat as well to log  
messages from your C/C++ code. Functions are defined in the NDK’s android/log.h:  
\_\_android\_log\_write  
\_\_android\_log\_print  
\_\_android\_log\_vprint  
\_\_android\_log\_assert  
For example, the equivalent of Log.i(“MyTag”, “Hello”) would be \_\_android\_log\_write(ANDROID\_LOG\_INFO, “MyTag”, “Hello”).  
Because these are Android-specific routines内置工具函数 and because their use makes your code a  
little too wordy啰嗦, it is recommended you create a wrapper around these functions. As a  
matter of fact, this is exactly what the Android source code does in the cutils/log.h file  
by creating macros such as LOGI and LOGE, the equivalent of Log.i and Log.e,  
respectively. You should design your wrapper认真设计包装函数 so you can easily use it in non-Android  
code as well.

6.4 Summary

Being able to measure performance is a simple yet critical feature in optimizations, and  
Android provides simple yet powerful tools to assist you. Traceview, whether it is used  
for Java or native tracing, is one of the most useful tools you will use, but remember that  
only actual measurements on a real device give you a definitive answer as Traceview  
disables the Dalvik Just-In-Time compiler. While considered quite trivial琐碎, these topics are  
important, and you should become comfortable with the various tools Android offers.  
You should also always check for new tools in new versions of the SDK that could  
improve your profiling, benchmarking, and debugging capabilities. Remember to first  
find where bottlenecks are before you start optimizing code as you want to focus your  
effort on the things that actually need to be optimized.

转载于:https://blog.51cto.com/1137907860/1700261

[http_wiki.qemu.org]: http://wiki.qemu.org
[http_source.android.com_source_downloading.html]: http://source.android.com/source/downloading.html
[http_source.android.com_source_building.html]: http://source.android.com/source/building.html