android trace字段分析

示例log:

suspend all histogram:  Sum: 10.106s 99% C.I. 41.374us-14883.596us Avg: 738.922us Max: 452703us
DALVIK THREADS (138):
"Signal Catcher" daemon prio=5 tid=2 Runnable
  | group="system" sCount=0 dsCount=0 obj=0x12c010d0 self=0x7fab654a00
  | sysTid=1994 nice=0 cgrp=default sched=0/0 handle=0x7fb300b450
  | state=R schedstat=( 60023536568 9178338589 34437 ) utm=4300 stm=1702 core=3 HZ=100
  | stack=0x7fb2f11000-0x7fb2f13000 stackSize=1005KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 0000000000477cec  /system/lib64/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiP12BacktraceMapPKcPNS_9ArtMethodEPv+220)
  native: #01 pc 0000000000477ce8  /system/lib64/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiP12BacktraceMapPKcPNS_9ArtMethodEPv+216)
  native: #02 pc 000000000044bd94  /system/lib64/libart.so (_ZNK3art6Thread9DumpStackERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEbP12BacktraceMap+472)
  native: #03 pc 0000000000463c2c  /system/lib64/libart.so (_ZN3art14DumpCheckpoint3RunEPNS_6ThreadE+904)
  native: #04 pc 000000000045b9b8  /system/lib64/libart.so (_ZN3art10ThreadList13RunCheckpointEPNS_7ClosureEb+808)
  native: #05 pc 000000000045b418  /system/lib64/libart.so (_ZN3art10ThreadList4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEb+308)
  native: #06 pc 000000000045b2a0  /system/lib64/libart.so (_ZN3art10ThreadList14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+804)
  native: #07 pc 00000000004373d8  /system/lib64/libart.so (_ZN3art7Runtime14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+332)
  native: #08 pc 000000000043da90  /system/lib64/libart.so (_ZN3art13SignalCatcher13HandleSigQuitEv+2240)
  native: #09 pc 000000000043c5b8  /system/lib64/libart.so (_ZN3art13SignalCatcher3RunEPv+476)
  native: #10 pc 0000000000068164  /system/lib64/libc.so (_ZL15__pthread_startPv+196)
  native: #11 pc 000000000001db40  /system/lib64/libc.so (__start_thread+16)
  (no managed stack frames)

解释:
打印位置 http://androidxref.com/8.0.0_r4/xref/art/runtime/thread.cc#1517
"Signal Catcher" daemon prio=5 tid=2 Runnable
| group="system" sCount=0 dsCount=0 obj=0x12c010d0 self=0x7fab654a00
| sysTid=1994 nice=0 cgrp=default sched=0/0 handle=0x7fb300b450
| state=R schedstat=( 60023536568 9178338589 34437 ) utm=4300 stm=1702 core=3 HZ=100
| stack=0x7fb2f11000-0x7fb2f13000 stackSize=1005KB
| held mutexes= "mutator lock"(shared held)

  • name "Signal Catcher"
  • daemon: java daemon进程java_lang_Thread_daemon
  • prio: 优先级 http://androidxref.com/8.0.0_r4/xref/art/runtime/thread_android.cc#36
  • tid: thread id.
  • Runnable: 进程状态 R,S, D, etc..
  • group="system", java_lang_ThreadGroup_name
  • sCount: thread->tls32_.suspend_count
  • dsCount: thread->tls32_.debug_suspend_count
  • flags=" << thread->tls32_.state_and_flags.as_struct.flags
  • obj=" << reinterpret_cast<void*>(thread->tlsPtr_.opeer)
  • self=" << reinterpret_cast(thread) << "\n";
  • sysTid=1994
  • nice=0 getpriority系统调用
  • cgrp=default /proc/self/task/pid/cgroup cpu:行,没有就是default
  • sched : sched_getscheduler()/sched_getparam() 系统调用
  • handle=0x7fb300b450 reinterpret_cast<void*>(thread->tlsPtr_.pthread_self);
  • state=R 进程状态 下述信息中的S
    (3) state %c
    One of the following characters, indicating process
    state:

                    R  Running
    
                    S  Sleeping in an interruptible wait
    
                    D  Waiting in uninterruptible disk sleep
    
                    Z  Zombie
    
                    T  Stopped (on a signal) or (before Linux 2.6.33)
                       trace stopped
    
                    t  Tracing stop (Linux 2.6.33 onward)
    
                    W  Paging (only before Linux 2.6.0)
    
                    X  Dead (from Linux 2.6.0 onward)
    
                    x  Dead (Linux 2.6.33 to 3.13 only)
    
                    K  Wakekill (Linux 2.6.33 to 3.13 only)
    
                    W  Waking (Linux 2.6.33 to 3.13 only)
    
                    P  Parked (Linux 3.9 to 3.13 only)
    
cat /proc/5788/task/5788/stat
5788 (system_server) S 5459 5459 0 0 -1 1077936448 181146 0 78 0 2444 533 0 0 -2 -20 203 0 67425 2766426112 90450 18446744073709551615 366503874560 366503889516 548938123040 548938113152 548161414464 0 4612 1 36088 18446743798833821120 0 0 17 1 1 1 0 0 0 366503897704 366503899144 366714880000 548938124082 548938124181 548938124181 548938125278 0
  • schedstat=( 60023536568 9178338589 34437 )
/proc/self/task/%d/schedstat
/proc/<pid>/schedstat
----------------
schedstats also adds a new /proc/<pid>/schedstat file to include some of
the same information on a per-process level.  There are three fields in
this file correlating for that process to:
     1) time spent on the cpu
     2) time spent waiting on a runqueue
     3) # of timeslices run on this cpu
  • utm=4300
    (14) utime %lu
    Amount of time that this process has been scheduled
    in user mode, measured in clock ticks (divide by
    sysconf(_SC_CLK_TCK)). This includes guest time,
    guest_time (time spent running a virtual CPU, see
    below), so that applications that are not aware of
    the guest time field do not lose that time from
    their calculations.
  • stm=1702
    (15) stime %lu
    Amount of time that this process has been scheduled
    in kernel mode, measured in clock ticks (divide by
    sysconf(_SC_CLK_TCK)).
  • core=3
    (39) processor %d (since Linux 2.2.8)
    CPU number last executed on.
  • HZ=100 sysconf(_SC_CLK_TCK)
  • stack=0x7fb2f11000-0x7fb2f13000 stackSize=1005KB
  • held mutexes= "mutator lock"(shared held)
    锁类型
    if 读写锁:
    (exclusive held) exclusive_owner_ = self
    (shared held) exclusive_owner_ = self, maybe not locked

关于major 以及minor
有时候,系统中内存压力比较大,会出现如下log。
这个log中打印的有32% 1582/system_server: 18% user + 13% kernel / faults: 7549 minor 35 major
那么这里的minor是什么意思呢?
http://androidxref.com/8.0.0_r4/xref/frameworks/base/core/java/com/android/internal/os/ProcessCpuTracker.java#239 中的st.rel_minfaults

通过ProcessCpuTracker,android会计算上次统计到本次统计之间的fault的差值,所以下面的4431ms to -1209ms faults: 7549 minor 35 major代表system_server在5640ms内一共发生了7549 minor 35 major fault

03-10 11:42:57.440 565 565 E lowmemorykiller: Error writing /proc/4357/oom_score_adj; errno=22
03-10 11:42:57.442 9819 9819 D AndroidRuntime: Shutting down VM
03-10 11:42:57.453 1582 1597 E ActivityManager: ANR in com.tencent.mm:appbrand0
03-10 11:42:57.453 1582 1597 E ActivityManager: PID: 9165
03-10 11:42:57.453 1582 1597 E ActivityManager: Reason: Broadcast of Intent { flg=0x10 cmp=com.tencent.mm/.plugin.appbrand.task.AppBrandTaskPreloadReceiver }
03-10 11:42:57.453 1582 1597 E ActivityManager: Load: 0.0 / 0.0 / 0.0
03-10 11:42:57.453 1582 1597 E ActivityManager: CPU usage from 4431ms to -1209ms ago (2018-03-10 11:42:51.783 to 2018-03-10 11:42:57.423):
03-10 11:42:57.453 1582 1597 E ActivityManager: 95% 9165/com.tencent.mm:appbrand0: 39% user + 55% kernel / faults: 61 minor 2 major
03-10 11:42:57.453 1582 1597 E ActivityManager: 32% 1582/system_server: 18% user + 13% kernel / faults: 7549 minor 35 major
03-10 11:42:57.453 1582 1597 E ActivityManager: 19% 442/logd: 8.6% user + 10% kernel / faults: 166 minor 2 major
03-10 11:42:57.453 1582 1597 E ActivityManager: 0.9% 2544/mcd: 0.1% user + 0.7% kernel / faults: 21 minor 1 major
03-10 11:42:57.453 1582 1597 E ActivityManager: 6.9% 2758/com.miui.daemon: 6% user + 0.8% kernel / faults: 6797 minor 795 major
03-10 11:42:57.453 1582 1597 E ActivityManager: 4.9% 2483/com.android.phone: 4.2% user + 0.7% kernel / faults: 1202 minor 2 major
03-10 11:42:57.453 1582 1597 E ActivityManager: 0.1% 2988/com.miui.home: 0.1% user + 0% kernel / faults: 475 minor 14 major
03-10 11:42:57.453 1582 1597 E ActivityManager: 0.1% 774/keystore: 0% user + 0.1% kernel / faults: 28 minor

发表评论

电子邮件地址不会被公开。 必填项已用*标注