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

    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 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.
To compile Android, follow the instructions on
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.