The Trace Processor is a C++ library (/src/trace_processor) that is able to ingest traces of various format and expose them in a massaged, higher level format, queryable through SQL queries. The trace processor is used:
trace_processor_shell
target (ninja -C out/xxx trace_processor_shell
).Supported input formats:
/sys/kernel/debug/tracing/trace
.Traces are raw because they are optimized for fast & low overhead writing. Despite being protos, their output is not ideal for being consumed by third parties as-is. Some data massaging is required.
Examples:
The sched table holds data about scheduling slices in the trace.
ts
Timestamp of the scheduling event, in nanoseconds. This comes from the CLOCK_BOOTTIME, when available.
dur
Duration of the scheduling event, in nanoseconds.
utid
ID of the thread. This is NOT the UNIX pid/tid (see below). This can be joined with the thread table.
cpu
CPU number where the scheduling event happened.
The counters table contains the data about counter events (both kernel and userspace) in the trace. This includes sources like memory, battery, cpufreq events etc.
id
A unique identifier for the counter row.
ts
The timestamp of the counter event.
name
The name of the counter event.
value
The value of the counter event.
ref
The identifier of the ref
erence metadata associated with the counter event. See ref_type for what data this can contain.
ref_type
The type of reference metadata associated to the counter event. Will be one of the following values utid
(the ref is an identifier for the thread table), upid
(same for process table), cpu
(the cpu the event occurred on), irq
and softirq
.
arg_set_id
The identifier into the args table. (see below)
The instants table contains the data about instant events (both kernel and userspace) in the trace. This includes sources like the lmk, sched_wakeup events etc.
id
A unique identifier for the instant row.
ts
The timestamp of the instant event.
name
The name of the instant event.
‘value’
The value of the instant event.
ref
The identifier of the ref
erence metadata associated with the instant event. See ref_type for what data this can contain.
ref_type
The type of reference metadata associated to the instant event. Will be one of the following values utid
(the ref is an identifier for the thread table), upid
(same for process table), cpu
(the cpu the event occurred on), irq
and softirq
.
arg_set_id
The identifier into the args table. (see below)
The slices table holds data about the userspace slices (from Chrome or Android) seen in the trace. These slices can be nested within each other forming ‘stacks’ of slices.
ts
The timestamp of the userspace slice in nanoseconds.
dur
Duration of the userspace slice, in nanoseconds.
utid
ID of the thread. This is NOT the UNIX pid/tid (see below). This can be joined with the thread table.
cat
The category of the slice. Only non-null and meaningful for Chrome traces.
name
The name of the slice.
depth
The nesting depth of the slice within the stack. Starts at 0 for root slices and counts upward for child slices.
stack_id
A unique identifier for the whole stack of slices to the current point. This identifier is useful when deriving metrics on unique stacks of slices.
parent_stack_id
The ‘stack_id’ for the parent stack of slices. This is 0 for all root slices and a reference to a ‘stack_id’ otherwise.
The process table holds data about the processes seen in the trace.
upid
Unique process ID. This is NOT the UNIX pid. This is a sequence number generated by the trace processor to uniquely identify a process in the trace. This is to deal with the fact that UNIX pids can be recycled and two distinct processes which lifetimes don't overlap can be assigned the same pid.
name
Process name, as per /proc/pid/cmdline.
pid
The UNIX pid (also known as Thread Group ID in Linux). This also matches the tid of the process' main thread.
Example:
upid | name | pid |
---|---|---|
1 | /system/bin/logd | 601 |
2 | rcu_preempt | 7 |
3 | rcuop/4 | 44 |
4 | rcuop/6 | 60 |
The thread table holds data about the threads seen in the trace.
utid
Unique thread ID. This is NOT the Linux pid or tid. Like the above, this is a sequence number generated by the trace processor to uniquely identify a thread in the trace.
upid
ID of the parent process in the process
table. This can be used to JOIN a thread with its process.
name
Thread name, as per /proc/pid/task/tid/comm.
tid
The Linux thread id (confusingly named “pid” in the Linux-world). For the process' main thread tid
== tgid
== pid
.
Example:
utid | upid | name | tid |
---|---|---|---|
1 | 1 | logd.klogd | 632 |
2 | 2 | rcu_preempt | 7 |
3 | 4 | rcuop/6 | 60 |
4 | 6 | rcuop/3 | 36 |
5 | 8 | sugov:0 | 588 |
6 | 9 | kworker/u16:6 | 9283 |
7 | 12 | sensors@1.0-ser | 1021 |
8 | 12 | HwBinder:797_1 | 1626 |
The stats table holds the statistics from the trace collection tool as well as counters from the trace processor collected during parsing and ingesting the trace
name
The name of the stat.
idx
The index of the stat in the array. This value is only non-null for stats which are indexed (e.g. ftrace overrun events are indexed per CPU).
severity
The severity of the value indicated by the stat. Can be one of ‘info’ and ‘error’.
source
The source of the stat i.e. whether is is coming from the trace collection time or parsing/ingestion time. One of ‘trace’ (i.e. trace collection time) or ‘analysis’ (parsing/ingestion time).
value
The value of the statistic.
The args table is a generic store of key value pairs deduplicated across the entire trace. A ‘set’ of arguments is given a unique identifier and can be referenced from other tables.
arg_set_id
The identifier for the set of arguments this arg belongs to.
flat_key
The key of the arg excluding any indexing for args which are arrays.
key
The long form key of the arg (including any indexes for array args.)
int_value
, real_value
, string_value
The value of the arg. One of these columns will be non-null depending on the type of the arg with the other two being null.
sched
(sched_switch events) tableselect ((select max(ts) from sched) - (select min(ts) from sched)) / 1e9 as duration_sec
select cpu, sum(dur)/1e9 as cpu_time_sec from sched group by cpu order by cpu
select process.name, pid from process limit 100
select process.name as proc_name, pid, thread.name as thread_name, tid from thread left join process using(upid) limit 100
select thread.name as thread_name, tid, cpu_sec from (select utid, sum(dur)/1e9 as cpu_sec from sched group by utid order by dur desc limit 100) inner join thread using(utid)
With matching process names
select thread.name as thread_name, process.name as proc_name, tid, pid, cpu_sec from (select utid, sum(dur)/1e9 as cpu_sec from sched group by utid order by dur desc limit 100) left outer join thread using(utid) left outer join process using(upid)
select process.name, tot_proc/1e9 as cpu_sec from (select upid, sum(tot_thd) as tot_proc from (select utid, sum(dur) as tot_thd from sched group by utid) join thread using(utid) group by upid) join process using(upid) order by cpu_sec desc limit 100;
select proc_name, cpu, cpu_sec from (select process.name as proc_name, upid, cpu, cpu_sec from (select cpu, utid, sum(dur)/1e9 as cpu_sec from sched group by utid) left join thread using(utid) left join process using(upid)) group by upid, cpu order by cpu_sec desc limit 100