Correlate Android Logcat Messages with VTune Amplifier Timeline

Intel® Developer Zone offers tools and how-to information for cross-platform app development, platform and technology information, code samples, and peer expertise to help developers innovate and succeed. Join our communities for Android, Internet of Things, Intel® RealSense™ Technology and Windows to download tools, access dev kits, share ideas with like-minded developers, and participate in hackathon’s, contests, roadshows, and local events.

Introduction

Android logcat is a very powerful tool for debugging. With Android logcat, we can see lots of useful information from the system or the applications over the time. Android provides the standardized API for the logs. In our development, we can easily add the logs and use logcat to see the logs from our program. VTune™ Amplifier for systems is a profiling tool for system or application performance tuning. VTune Amplifier provides a powerful timeline pane to help the developer to see the performance matrix over the time.

How to correlate the logcat message with VTune Amplifier timeline pane? It’s reasonable for developers to view the logs from logcat together with the other performance matrix from VTune Amplifier timeline pane. By doing this, we can know what happens in a particular time, and the correlated performance data around that time.

Intel® VTune™ Amplifier can process and integrate performance statistics collected externally with a custom collector or with your target application in parallel with the native VTune Amplifier analysis. To achieve this, provide the collected custom data as a csv file with a predefined structure and load this file to the VTune Amplifier result.

The details on how to create a CSV file with external data are described in the VTune Amplifier user’s guide. Open the VTune Amplifier Help documentation, go to Intel VTune™ Amplifier > User’s Guide > External Data Import, we can find how to create the CSV file with external data and the examples of the CSV file format. In order to view the logcat message in the VTune timeline pane, follow the guide to change the logcat message into the CSV file, load the message in VTune Amplifier.

An Example

Here is an example. I have a JAVA application "com.example.Thread1". In my application, I have a function which contains lots of computation. The pseudo code looks like below:

void myfunction ()
{
        Log.v("MYTEST", "start block 1");
        {
		...//my computation block 1
	}
        Log.v("MYTEST", "start block 2");
        {
		...//my computation block 2
	}
	Log.v("MYTEST", "my computation finished");
}

In the Vtune Amplifier timeline pane shown as below, we can see that this function is executed for 6 times. The main thread ID for my application is 12271. The brown column shows the performance data (the CPU time) we collected during the VTune Amplifier profiling.

For each execution of the function, if we collect the logcat message with "logcat -v threadtime", we could have something like below:

01-12 11:13:19.090  2174  2174 V MYTEST  : start block 1
01-12 11:13:19.260  2174  2174 V MYTEST  : start block 2
01-12 11:13:19.500  2174  2174 V MYTEST  : my computation finished

Now we can convert the message from logcat into the csv file with the format which can be loaded into VTune Amplifier. According to the documentation from VTune Amplifier, we could have the following csv file for example:

name,start_tsc.UTC,end_tsc,pid,tid
V/MYTEST : start block 1,2015-01-12 03:13:19.090,2015-01-12 03:13:19.090,2174,2174
V/MYTEST : start block 2,2015-01-12 03:13:19.260,2015-01-12 03:13:19.260,2174,2174
V/MYTEST:my computation finished,2015-01-12 03:13:19.500, 2015-01-12 03:13:19.500, 2174, 2174

Here we use log tag and message string as the "name". We use the time of the message as both the start_tsc.UTC and end_tsc, use the process ID and thread ID from logcat as pid and tid. The fields are separated by comma.

From VTune Amplifier "Analysis Type" > "Import from CSV", select the csv file we created, VTune Amplifier will load the data and show the correlated logcat message with the performance data over the timeline. See below screenshot from the output, move the mouse over the message point (the small yellow triangle), we can see each message from logcat for our application.

There are several tips and tricks for creating the CSV file.

1. The time from logcat is the time from the Andriod OS which is related to a specific time zone. This time needs to be changed to UTC time in the CSV file which is accepted by VTune Amplifier.
2. The CSV file name should specify the hostname where your custom collector gathered the data. E.g. [user-defined]-hostname-<hostname-of-system>.csv. For Android target, you may get the host name by reading the file /proc/sys/kernel/hostname from the adb shell.
3. You can custom the string in the "name" column in the CSV file. In screenshot shown above, I simply use the whole logcat message line as the "name". Please note that you will need to remove the comma in the "name" string if it exists in the logcat message. The comma "," is the reserved separator which should not appear in the name string.
4. You may also convert the kernel messages (e.g. from "dmesg") into CSV file and see the kernel logs in the VTune Amplifier timeline pane. This is very useful for the system level developer, e.g. when you are developing your kernel module or device driver. The process ID and thread ID should be specified to 0 for the messages from kernel. Please note that the kernel message timestamp (e.g. from dmesg) is the offset of seconds from the time when system is booting up. You need to convert the timestamp into the UTC time when the message is generated. For example, using this way to get the message time: "time of message" = "now" - "system uptime" + "timestamp of the message". Here "now" is the current time of the system. You may get the "now" time with "date" command from adb shell. The "system uptime" is the passed seconds since the system is booting up. You can get this date from file /proc/uptime.

A Script

I have created an experimental bash script to make things easier. You can use the script "logcat2vtune.sh" to collect the logcat data and generate the needed CSV file automatically. The script can collect the logcat and/or kernel message, read the target system information, parse the logs and convert it to the CSV file automatically.

To use this script file, you need a bash environment which is available natively on a Linux host. If you are working on a Windows host, I would recommend to install the Cygwin* which provides a Linux style bash environment on Windows system. Here are the basic steps to get the CSV file during the VTune Amplifier profiling.

1. In the shell command, make sure you can access the "adb", start the logcat2vtune.sh script with proper option, e.g. > ./logcat2vtune.sh -c logcat -g MYTEST
2. Start the VTune Amplifier performance data collection. This can be done from VTune Amplifier GUI or from command line.
3. Stop the VTune Amplifier performance data collection.
4. Press any key in the logcat2vtune.sh shell windows to stop the log collections. The script will read the collected log data, parse the logs with bash regular expression and convert it into a CSV file. You will find a .csv file created in the current shell folder.
5. Load the CSV file into VTune Amplifier and examine the log messages from VTune timeline view.

Here are some typical usage modes for using the script file.

$logcat2vtune.sh -c logcat -g MYTEST

Collect the logcat data, filter the logcat message with string "MYTEST" and generate the CSV file. The logcat is collected using the following command internally in scripts.
$adb shell logcat -v threadtime
"MYTEST" is the string to filter the logcat messages. Using the filter is highly recommended since logcat may get very large logs while we only care the logs from our own process. The filter could be the string of my logcat tag name, the process ID, the thread ID or any other string. You can use comma "," to specify multiple strings. The logs which match any string from "-g" option will be parsed and generated in the CSV file.

$logcat2vtune.sh -c dmesg -g "MYDRIVER"

Collect the "dmesg" output, filter it with "MYDRIVER" string and generate the CSV file.

$logcat2vtune.sh -c logcatk -g MYTEST,MYDRIVER

Collect both logcat data and kernel message data, filter by string "MYTEST" or "MYDRIVER" and generate the CSV file. In this case, you will find both user level logs from logcat and kernel level logs from "dmesg" in the VTune Amplifier timeline pane. The logs are collected internally from script using following command:
>adb shell logcat -v threadtime -f /dev/kmsg | adb shell cat /proc/kmsg
In this case, you can see the kernel logs from vmlinux with TID 0, and the user level logs for TID 1922from logcat.

Please use command "logcat2vtune.sh -h" to get more details on the script usage. You can customize the script for your own purpose. Please note that this script is an experimental script which is not fully validated. Please feel free to let me know if you get any issues when using this script.