systrace 로그 읽기

내가 전에 물었던 것을 알고 있지만 "systrace는 ftrace를 확장하는 atrace를 사용하므로 ftrace 형식을 확인하십시오."라는 메시지가 나에게 충분하지 않습니다. 몇 가지 systrace 특정 태그/형식에 대한 자세한 내용을 알고 있습니다. 나는 약간의 확신을 가지고있는 추측을 가지고 있으며, 따라서 나는 그들에게 정말로 확신/불확실성을 알리는 누군가가 필요하다.systrace 로그 읽기

다음은 trace.html에서 찾은 몇 가지 결과입니다. Q1은

# 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\

:에 "실"을하지 왜 때때로 다른 PID와 함께 제공하고 동시에 다른 CPU에, 예를 실행하도록 예약하세요 스레드 117? 여기서 "스레드"가 실제로 의미하는 것은 무엇입니까?

 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 : "sched_switch"의 "prev_state를"무엇을 의미합니까? "S, D, R, R +"는이 변수에서 각각 무엇을 의미합니까?

Q3 : "tracing_mark_write"는 시작에 B, 변경 C 및 끝 E를 사용합니다. 그러나 E 태그에는 추적 이름이 없습니다. 해당 B 태그를 확인하는 방법은 무엇입니까? 호출 스택 스타일 LIFO에서 작동합니까? 그렇다면 "스레드"가 2 개의 CPU에서 일관되게 실행되도록 분할 될 수없는 실제 스레드 인 경우에만 보장 될 수 있습니다. Q1으로 돌아갑니다.

도움을 주시면 감사하겠습니다.

출처

2014-04-04 logicor

A1 : 프로세스에서 설정 한 ps -t에서 볼 수있는 스레드 이름이 표시됩니다. 명명되지 않은 Dalvik 스레드는 "Thread-N"으로 명명됩니다. 여기서 N은 스레드 클래스가 추적하는 일련 번호입니다 (바인더 스레드 풀에서 생성 된 것과 동일한 방법으로 "Binder_1"). 따라서 "Thread-117"의 "117"은 시스템 pid 또는 tid와 관계가 없습니다. 스레드가 호출되는 것입니다. 고유 한 것으로 보장되지 않습니다. 하나의 프로세스에 여러 인스턴스가 있거나 별도의 프로세스에있을 수 있습니다.

대답 : 상태는 ps 출력에서 보는 것과 같습니다. 리눅스 맨 페이지의 "공정 상태 코드"절을 참조하십시오 :

D uninterruptible sleep (usually IO) 
    R running or runnable (on run queue) 
    S interruptible sleep (waiting for an event to complete) 
    ...

A3 : 예, LIFO, 단일 스레드 용. 이는 공개 android.os.Trace API와 일치합니다. (가 당신이 시작과 끝을 위해 동일한 태그와 "쿠키"를 제공 "asynchronous" traces에 대한 다른 (비공개) API이지만, 널리 사용 아닙니다.)

출처

2014-04-06 16:33:56 fadden

감사합니다, 매우 상세하고 명확한 대답은. – logicor

systrace 로그 읽기

답변

관련 문제