Android Systrace Trace File Format
Android systrace tool, calls atrace tool via ADB. However, I don't understand very well the format of the traces file. Apparently it is very similar to linux ftrace tool with some differences. The main difference is that is doesn't uses a System.Map file but it includes all that information into the trace file. Also, there are new B|E entries that are android specific.
There is some information about this format in Android Source Code at: http://androidxref.com/4.1.1/xref/external/chromium-trace/src/tracing/linux_perf_importer.js
However, in that documentation we can read that the format belongs to Linux Perf Tool. I don't think so, linux perf gives as an output a very different format... (unless some special configuration is active...)
My question is: Does anybody know where can I found an official documentation about android trace files generated with atrace tool from adb?
Is this format familiar to you ?
# tracer: nop
#
# entries-in-buffer/entries-written: 66427/66427 #P:2
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
atrace-1724 [000] d..3 14186.680000: sched_switch: prev_comm=atrace prev_pid=1724 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
<idle>-0 [000] d.h7 14186.690000: sched_wakeup: comm=tfm_b6bcf800 pid=1714 prio=35 success=1 target_cpu=000
<idle>-0 [000] d..3 14186.690000: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=tfm_b6bcf800 next_pid=1714 next_prio=35
tfm_b6bcf800-1714 [000] d..3 14186.690000: sched_switch: prev_comm=tfm_b6bcf800 prev_pid=1714 prev_prio=35 prev_state=D|W ==> next_comm=swapper/0 next_pid=0 next_prio=120
<idle>-0 [001] d.h3 14186.690000: sched_wakeup: comm=Player Aud Mixe pid=146 prio=35 success=1 target_cpu=001
<idle>-0 [001] d..3 14186.690000: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=Player Aud Mixe next_pid=146 next_prio=35
Player Aud Mixe-146 [001] d..3 14186.690000: sched_switch: prev_comm=Player Aud Mixe prev_pid=146 prev_prio=35 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120
<idle>-0 [001] d.h3 14186.690000: sched_wakeup: comm=Player Aud Mixe pid=146 prio=35 success=1 target_cpu=001
<idle>-0 [001] d..3 14186.690000: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=Player Aud Mixe next_pid=146 next_prio=35
Player Aud Mixe-146 [001] d..3 14186.690000: sched_switch: prev_comm=Player Aud Mixe prev_pid=146 prev_prio=35 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
<idle>-0 [001] d.h3 14186.700000: sched_wakeup: comm=Player Aud Mixe pid=146 prio=35 success=1 target_cpu=001
<idle>-0 [001] d..3 14186.700000: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=Player Aud Mixe next_pid=146 next_prio=35
EventThread-110 [001] d..5 14190.100000: sched_wakeup: comm=SurfaceFlinger pid=103 prio=112 success=1 target_cpu=001
EventThread-110 [001] d..3 14190.100000: sched_switch: prev_comm=EventThread prev_pid=110 prev_prio=111 prev_state=S ==> next_comm=SurfaceFlinger next_pid=103 next_prio=112
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|onMessageReceived
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|handleTransaction
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|doTransaction
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: E
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: E
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|handleMessageInvalidate
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: E
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: E
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|onMessageReceived
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|handleMessageRefresh
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|rebuildLayerStacks
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|computeVisibleRegions
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: E
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: E
SurfaceFlinger-103 [001] ...1 14190.100000: tracing_mark_write: B|96|doComposition
SurfaceFlinger-103 [001] d.h4 14190.100000: sched_wakeup: comm=surfaceflinger pid=96 prio=120 success=1 target_cpu=001
SurfaceFlinger-103 [001] d..3 14190.100000: sched_switch: prev_comm=SurfaceFlinger prev_pid=103 prev_prio=112 prev_state=R ==> next_comm=surfaceflinger next_pid=96 next_prio=120
Thanks in advance !
Answer
Well, now it is sure: the format belongs to ftrace tool. Android atrace is an extension of ftrace build to facilitate configuration.
The official documentation from ftrace, shows that this output format can directly be produced by it in the following way:
root@adroid:# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
root@adroid:# echo 1 > /sys/kernel/debug/tracing/tracing_on
root@adroid:# cat /sys/kernel/debug/tracing/trace > mytracefile.txt
root@adroid:# echo 0 > /sys/kernel/debug/tracing/tracing_on
root@adroid:# echo 0 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
Official Documentation at: http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/trace/ftrace.txt
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 77/77 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2243 next_prio=120
snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=2229 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
[...]
Regards,