Menu
I know this is asked before but I am afraid "systrace uses atrace which extends ftrace, so check ftrace format here" is not enough for me. I am after more details on some systrace specific tag/formats. I have some guesses which I have little confidence on, thus I need somebody who really KNOW them to confirm/disconfirm.
Here is some results I found in trace.html.
# tracer: nop\n\
#\n\
# entries-in-buffer/entries-written: 393636/393636 #P:1\n\
#\n\
# _-----=> irqs-off\n\
# / _----=> need-resched\n\
# | / _---=> hardirq/softirq\n\
# || / _--=> preempt-depth\n\
# ||| / delay\n\
# TASK-PID CPU# |||| TIMESTAMP FUNCTION\n\
# | | | |||| | |\n\
atrace-27768 [000] ...2 17184.509740: sched_switch: prev_comm=atrace prev_pid=27768 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
Thread-117-16753 [001] ...1 17184.510251: tracing_mark_write: B|4237|eglSwapBuffers\n\
<idle>-0 [000] d.h4 17184.510329: sched_wakeup: comm=AudioOut_2 pid=608 prio=101 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.510338: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=AudioOut_2 next_pid=608 next_prio=101\n\
AudioOut_2-608 [000] d..4 17184.510393: sched_wakeup: comm=AudioTrack pid=16778 prio=104 success=1 target_cpu=000\n\
AudioOut_2-608 [000] ...2 17184.510446: sched_switch: prev_comm=AudioOut_2 prev_pid=608 prev_prio=101 prev_state=S ==> next_comm=AudioTrack next_pid=16778 next_prio=104\n\
Thread-117-16753 [001] ...1 17184.510610: tracing_mark_write: B|4237|queueBuffer\n\
Thread-117-16753 [001] d..4 17184.510648: sched_wakeup: comm=Binder_2 pid=189 prio=120 success=1 target_cpu=001\n\
Thread-117-16753 [001] ...2 17184.510656: sched_switch: prev_comm=Thread-117 prev_pid=16753 prev_prio=120 prev_state=R+ ==> next_comm=Binder_2 next_pid=189 next_prio=120\n\
Binder_2-189 [001] ...2 17184.510664: sched_switch: prev_comm=Binder_2 prev_pid=189 prev_prio=120 prev_state=D ==> next_comm=Thread-117 next_pid=16753 next_prio=120\n\
Thread-117-16753 [001] d..4 17184.510670: sched_wakeup: comm=Binder_2 pid=189 prio=120 success=1 target_cpu=001\n\
Thread-117-16753 [001] ...2 17184.510673: sched_switch: prev_comm=Thread-117 prev_pid=16753 prev_prio=120 prev_state=R+ ==> next_comm=Binder_2 next_pid=189 next_prio=120\n\
Binder_2-189 [001] ...1 17184.510722: tracing_mark_write: B|147|queueBuffer\n\
Binder_2-189 [001] ...1 17184.510729: tracing_mark_write: B|147|SurfaceView: 0\n\
Binder_2-189 [001] ...1 17184.510734: tracing_mark_write: E\n\
Binder_2-189 [001] ...1 17184.510753: tracing_mark_write: C|147|SurfaceView|1\n\
Binder_2-189 [001] d..4 17184.510772: sched_wakeup: comm=EventThread pid=255 prio=111 success=1 target_cpu=001\n\
Binder_2-189 [001] ...1 17184.510781: tracing_mark_write: E\n\
Binder_2-189 [001] ...2 17184.510810: sched_switch: prev_comm=Binder_2 prev_pid=189 prev_prio=120 prev_state=S ==> next_comm=EventThread next_pid=255 next_prio=111\n\
EventThread-255 [001] d..4 17184.510828: sched_wakeup: comm=DispSync pid=186 prio=111 success=1 target_cpu=001\n\
EventThread-255 [001] ...1 17184.510840: tracing_mark_write: C|147|VsyncOn|1\n\
EventThread-255 [001] ...2 17184.510852: sched_switch: prev_comm=EventThread prev_pid=255 prev_prio=111 prev_state=S ==> next_comm=DispSync next_pid=186 next_prio=111\n\
DispSync-186 [001] ...2 17184.510867: sched_switch: prev_comm=DispSync prev_pid=186 prev_prio=111 prev_state=S ==> next_comm=Thread-117 next_pid=16753 next_prio=120\n\
Thread-117-16753 [001] ...1 17184.510885: tracing_mark_write: E\n\
Thread-117-16753 [001] ...1 17184.510893: tracing_mark_write: B|4237|query\n\
Thread-117-16753 [001] ...1 17184.510899: tracing_mark_write: E\n\
Thread-117-16753 [001] ...1 17184.510906: tracing_mark_write: B|4237|query\n\
Thread-117-16753 [001] ...1 17184.510911: tracing_mark_write: E\n\
Thread-117-16753 [001] ...1 17184.510924: tracing_mark_write: E\n\
AudioTrack-16778 [000] d.h7 17184.510984: sched_wakeup: comm=FastMixer pid=330 prio=96 success=1 target_cpu=000\n\
AudioTrack-16778 [000] ...2 17184.511000: sched_switch: prev_comm=AudioTrack prev_pid=16778 prev_prio=104 prev_state=R+ ==> next_comm=FastMixer next_pid=330 next_prio=96\n\
Thread-117-16753 [001] ...1 17184.511012: tracing_mark_write: B|4237|dequeueBuffer\n\
Thread-117-16753 [001] d..4 17184.511034: sched_wakeup: comm=Binder_1 pid=185 prio=120 success=1 target_cpu=001\n\
Thread-117-16753 [001] ...2 17184.511041: sched_switch: prev_comm=Thread-117 prev_pid=16753 prev_prio=120 prev_state=R+ ==> next_comm=Binder_1 next_pid=185 next_prio=120\n\
Binder_1-185 [001] ...2 17184.511053: sched_switch: prev_comm=Binder_1 prev_pid=185 prev_prio=120 prev_state=D ==> next_comm=Thread-117 next_pid=16753 next_prio=120\n\
Thread-117-16753 [001] d..4 17184.511059: sched_wakeup: comm=Binder_1 pid=185 prio=120 success=1 target_cpu=001\n\
Thread-117-16753 [001] ...2 17184.511062: sched_switch: prev_comm=Thread-117 prev_pid=16753 prev_prio=120 prev_state=R+ ==> next_comm=Binder_1 next_pid=185 next_prio=120\n\
FastMixer-330 [000] ...2 17184.511070: sched_switch: prev_comm=FastMixer prev_pid=330 prev_prio=96 prev_state=S ==> next_comm=AudioTrack next_pid=16778 next_prio=104\n\
AudioTrack-16778 [000] ...2 17184.511087: sched_switch: prev_comm=AudioTrack prev_pid=16778 prev_prio=104 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
Binder_1-185 [001] ...1 17184.511093: tracing_mark_write: B|147|dequeueBuffer\n\
Binder_1-185 [001] ...1 17184.511102: tracing_mark_write: B|147|SurfaceView: 1\n\
Binder_1-185 [001] ...1 17184.511105: tracing_mark_write: E\n\
Binder_1-185 [001] ...1 17184.511110: tracing_mark_write: E\n\
Binder_1-185 [001] ...2 17184.511131: sched_switch: prev_comm=Binder_1 prev_pid=185 prev_prio=120 prev_state=S ==> next_comm=Thread-117 next_pid=16753 next_prio=120\n\
Thread-117-16753 [001] ...1 17184.511143: tracing_mark_write: E\n\
<idle>-0 [000] d.h4 17184.512011: sched_wakeup: comm=Thread-117 pid=16780 prio=120 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.512021: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=Thread-117 next_pid=16780 next_prio=120\n\
Thread-117-16780 [000] ...2 17184.512047: sched_switch: prev_comm=Thread-117 prev_pid=16780 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
<idle>-0 [000] d.h4 17184.513414: sched_wakeup: comm=Thread-117 pid=17201 prio=120 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.513425: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=Thread-117 next_pid=17201 next_prio=120\n\
Thread-117-17201 [000] ...2 17184.513441: sched_switch: prev_comm=Thread-117 prev_pid=17201 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
Thread-117-16753 [001] ...2 17184.516369: sched_switch: prev_comm=Thread-117 prev_pid=16753 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120\n\
<idle>-0 [000] d.h6 17184.517936: sched_wakeup: comm=kworker/0:3 pid=27267 prio=120 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.517947: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=27267 next_prio=120\n\
kworker/0:3-27267 [000] ...2 17184.518045: sched_switch: prev_comm=kworker/0:3 prev_pid=27267 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
<idle>-0 [000] d.h7 17184.520977: sched_wakeup: comm=FastMixer pid=330 prio=96 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.520986: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=FastMixer next_pid=330 next_prio=96\n\
FastMixer-330 [000] ...2 17184.521041: sched_switch: prev_comm=FastMixer prev_pid=330 prev_prio=96 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
<idle>-0 [000] d.h6 17184.521117: sched_wakeup: comm=kworker/0:3 pid=27267 prio=120 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.521122: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:3 next_pid=27267 next_prio=120\n\
kworker/0:3-27267 [000] d..4 17184.521130: sched_wakeup: comm=hwc_eventmon pid=246 prio=100 success=1 target_cpu=000\n\
kworker/0:3-27267 [000] ...2 17184.521135: sched_switch: prev_comm=kworker/0:3 prev_pid=27267 prev_prio=120 prev_state=S ==> next_comm=hwc_eventmon next_pid=246 next_prio=100\n\
hwc_eventmon-246 [000] ...2 17184.521155: sched_switch: prev_comm=hwc_eventmon prev_pid=246 prev_prio=100 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
<idle>-0 [000] d.s5 17184.521414: sched_wakeup: comm=cfinteractive pid=88 prio=0 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.521420: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=cfinteractive next_pid=88 next_prio=0\n\
cfinteractive-88 [000] ...2 17184.521440: sched_switch: prev_comm=cfinteractive prev_pid=88 prev_prio=0 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
<idle>-0 [001] d.h4 17184.525814: sched_wakeup: comm=DispSync pid=186 prio=111 success=1 target_cpu=001\n\
<idle>-0 [001] ...2 17184.525821: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=DispSync next_pid=186 next_prio=111\n\
DispSync-186 [001] d..4 17184.525842: sched_wakeup: comm=EventThread pid=255 prio=111 success=1 target_cpu=001\n\
DispSync-186 [001] ...2 17184.525851: sched_switch: prev_comm=DispSync prev_pid=186 prev_prio=111 prev_state=S ==> next_comm=EventThread next_pid=255 next_prio=111\n\
<idle>-0 [000] d.h3 17184.525884: sched_wakeup: comm=surfaceflinger pid=147 prio=112 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.525890: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=surfaceflinger next_pid=147 next_prio=112\n\
EventThread-255 [001] ...2 17184.525892: sched_switch: prev_comm=EventThread prev_pid=255 prev_prio=111 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120\n\
Q1: Why does a "thread" come with different PID and sometimes get scheduled to run on different CPUs simultaneously, e.g. Thread-117? What does "thread" really mean here?
Binder_1-185 [001] ...2 17184.511131: sched_switch: prev_comm=Binder_1 prev_pid=185 prev_prio=120 prev_state=S ==> next_comm=Thread-117 next_pid=16753 next_prio=120\n\
Thread-117-16753 [001] ...1 17184.511143: tracing_mark_write: E\n\
<idle>-0 [000] d.h4 17184.512011: sched_wakeup: comm=Thread-117 pid=16780 prio=120 success=1 target_cpu=000\n\
<idle>-0 [000] ...2 17184.512021: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=Thread-117 next_pid=16780 next_prio=120\n\
Thread-117-16780 [000] ...2 17184.512047: sched_switch: prev_comm=Thread-117 prev_pid=16780 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120\n\
Q2: What does "prev_state" in "sched_switch" mean? What does "S,D,R,R+" refer to in this variable respectively?
Q3: "tracing_mark_write" uses B for begin, C for change and E for end. But E tag does not come with trace name. How to determine which B tag it corresponds to? Does it work in a call stack style LIFO? If so, that can only be guaranteed if a "thread" is a real thread that can not be split to run on two CPUs coherently. Which lead us back to Q1.
Any help is appreciated!
951
A1: It's showing you the thread name that you would see from ps -t on the device, which is set by the process. Unnamed Dalvik threads are named "Thread-N", where N is a serial number tracked by the Thread class (the same way the Binder thread pool created "Binder_1"). So the "117" in "Thread-117" has no relationship to the system pid or tid; it's just what the thread is called. It's not guaranteed to be unique -- you could have multiple instances in one process, or in separate processes.
A2: The states are the same as you'd see in ps output. See the Linux man page's "PROCESS STATE CODES" section:
D uninterruptible sleep (usually IO)
R running or runnable (on run queue)
S interruptible sleep (waiting for an event to complete)
...
A3: Yes, LIFO, for a single thread. This is matched by the public android.os.Trace API. (There is a different (non-public) API for "asynchronous" traces where you supply the same tag and "cookie" for start and end, but it's not used as widely.)
160
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With
