The metrics subsystem is a part of the trace processor which uses traces to compute reproducible metrics. It can be used in a wide range of situations; examples include benchmarks, lab tests and on large corpuses of traces.
The quickstart provides a quick overview on how to compute trace-based metrics traces using trace processor.
Performance metrics are useful to monitor for the health of a system and ensure that a system does not regress over time as new features are added.
However, metrics retrieved directly from the system have a downside: if there is a regression, it is difficult to root-cause the issue. Often, the problem may not be reproducible or may rely on a particular setup.
Trace-based metrics are one possible solution to this problem. Instead of collecting metrics directly on the system, a trace is collected and metrics are computed from the trace. If a regression in the metric is spotted, the developer can look directly at the trace to understand why the regression has occurred instead of having to reproduce the issue.
The metric subsystem is a part of the trace processor which executes SQL queries against traces and produces a metric which summarizes some performance attribute (e.g. CPU, memory, startup latency etc.).
For example, generating the Android CPU metrics on a trace is as simple as:
> ./trace_processor --run-metrics android_cpu <trace> android_cpu { process_info { name: "/system/bin/init" threads { name: "init" core { id: 1 metrics { mcycles: 1 runtime_ns: 570365 min_freq_khz: 1900800 max_freq_khz: 1900800 avg_freq_khz: 1902017 } } ... } ... } ... }
NOTE: Googlers: for internal usage of metrics in Google3 (i.e. metrics which are confidential), please see this internal page.
Authors are strongly encouraged to add all metrics derived on Perfetto traces to the Perfetto repo unless there is a clear usecase (e.g. confidentiality) why these metrics should not be publicly available.
In return for upstreaming metrics, authors will have first class support for running metrics locally and the confidence that their metrics will remain stable as trace processor is developed.
As well as scaling upwards while developing from running on a single trace locally to running on a large set of traces, the reverse is also very useful. When an anomaly is observed in the metrics of a lab benchmark, a representative trace can be downloaded and the same metric can be run locally in trace processor.
Since the same code is running locally and remotely, developers can be confident in reproducing the issue and use the trace processor and/or the Perfetto UI to identify the problem.
TIP: To see how to add a new metric to trace processor, see the checklist here
This walkthrough will outline how to prototype a metric locally without needing to compile trace processor. This metric will compute the CPU time for every process in the trace and list the names of the top 5 processes (by CPU time) and the number of threads created by the process.
NOTE: See this GitHub gist to see how the code should look at the end of the walkthrough. The prerequisites and Step 4 below give instructions on how to get trace processor and run the metrics code.
As a setup step, create a folder to act as a scratch workspace; this folder will be referred to using the env variable $WORKSPACE
in Step 4.
The other requirement is trace processor. This can downloaded from here or can be built from source using the instructions here. Whichever method is chosen, $TRACE_PROCESSOR env variable will be used to refer to the location of the binary in Step 4.
As all metrics in the metrics platform are defined using protos, the metric needs to be structured as a proto. For this metric, there needs to be some notion of a process name along with its CPU time and number of threads.
Starting off, in a file named top_five_processes.proto
in our workspace, create a basic proto message called ProcessInfo with those three fields:
message ProcessInfo { optional string process_name = 1; optional uint64 cpu_time_ms = 2; optional uint32 num_threads = 3; }
Next , create a wrapping message which will hold the repeated field containing the top 5 processes.
message TopProcesses { repeated ProcessInfo process_info = 1; }
Finally, define an extension to the root proto for all metrics (the TraceMetrics proto).
extend TraceMetrics { optional TopProcesses top_five_processes = 450; }
Adding this extension field allows trace processor to link the newly defined metric to the TraceMetrics
proto.
Notes:
Putting everything together, along with some boilerplate preamble gives:
syntax = "proto2"; package perfetto.protos; import "protos/perfetto/metrics/metrics.proto"; message ProcessInfo { optional string process_name = 1; optional int64 cpu_time_ms = 2; optional uint32 num_threads = 3; } message TopProcesses { repeated ProcessInfo process_info = 1; } extend TraceMetrics { optional TopProcesses top_five_processes = 450; }
Next, write the SQL to generate the table of the top 5 processes ordered by the sum of the CPU time they ran for and the number of threads which were associated with the process.
The following SQL should be added to a file called top_five_processes.sql
in the workspace:
CREATE VIEW top_five_processes_by_cpu AS SELECT process.name as process_name, CAST(SUM(sched.dur) / 1e6 as INT64) as cpu_time_ms, COUNT(DISTINCT utid) as num_threads FROM sched INNER JOIN thread USING(utid) INNER JOIN process USING(upid) GROUP BY process.name ORDER BY cpu_time_ms DESC LIMIT 5;
Let's break this query down:
sched
table. This contains all the scheduling data available in the trace. Each scheduling “slice” is associated with a thread which is uniquely identified in Perfetto traces using its utid
. The two pieces of information needed from the sched table are the dur
- short for duration, this is the amount of time the slice lasted - and the utid
which will be used to join with the thread table.upid
. Similar to utid
, upid
is the unique identifier for a process in a Perfetto trace. In this case, upid
will refer to the process which hosts the thread given by utid
.Now that the result of the metric has been expressed as an SQL table, it needs to be converted to a proto. The metrics platform has built-in support for emitting protos using SQL functions; something which is used extensively in this step.
Let's look at how it works for our table above.
CREATE VIEW top_five_processes_output AS SELECT TopProcesses( 'process_info', ( SELECT RepeatedField( ProcessInfo( 'process_name', process_name, 'cpu_time_ms', cpu_time_ms, 'num_threads', num_threads ) ) FROM top_five_processes_by_cpu ) );
Breaking this down again:
Starting from the inner-most SELECT statement, there is what looks like a function call to the ProcessInfo function; in fact this is no coincidence. For each proto that the metrics platform knows about, an SQL function is generated with the same name as the proto. This function takes key value pairs with the key as the name of the proto field to fill and the value being the data to store in the field. The output is the proto created by writing the fields described in the function. (*)
In this case, this function is called once for each row in the top_five_processes_by_cpu
table. The output will be the fully filled ProcessInfo proto.
The call to the RepeatedField
function is the most interesting part and also the most important. In technical terms, RepeatedField
is an aggregate function. Practically, this means that it takes a full table of values and generates a single array which contains all the values passed to it.
Therefore, the output of this whole SELECT statement is an array of 5 ProcessInfo protos.
Next is creation of the TopProcesses
proto. By now, the syntax should already feel somewhat familiar; the proto builder function is called to fill in the process_info
field with the array of protos from the inner function.
The output of this SELECT is a single TopProcesses
proto containing the ProcessInfos as a repeated field.
Finally, the view is created. This view is specially named to allow the metrics platform to query it to obtain the root proto for each metric (in this case TopProcesses
). See the note below as to the pattern behind this view's name.
(*) This is not strictly true. To type-check the protos, some metadata is returned about the type of the proto but this is unimportant for metric authors.
NOTE: It is important that the views be named {name of TraceMetrics extension field}_output. This is the pattern used and expected by the metrics platform for all metrics.
The final file should look like so:
CREATE VIEW top_five_processes_by_cpu AS SELECT process.name as process_name, CAST(SUM(sched.dur) / 1e6 as INT64) as cpu_time_ms, COUNT(DISTINCT utid) as num_threads FROM sched INNER JOIN thread USING(utid) INNER JOIN process USING(upid) GROUP BY process.name ORDER BY cpu_time_ms DESC LIMIT 5; CREATE top_five_processes_output AS SELECT TopProcesses( 'process_info', ( SELECT RepeatedField( ProcessInfo( 'process_name', process_name, 'cpu_time_ms', cpu_time_ms, 'num_threads', num_threads ) ) FROM top_five_processes_by_cpu ) );
NOTE: The name of the SQL file should be the same as the name of TraceMetrics extension field. This is to allow the metrics platform to associated the proto extension field with the SQL which needs to be run to generate it.
For this step, invoke trace processor shell to run the metrics (see the Quickstart for downloading instructions):
$TRACE_PROCESSOR --run-metrics $WORKSPACE/top_five_processes.sql $TRACE 2> /dev/null
(For an example trace to test this on, see the Notes section below.)
By passing the SQL file for the metric to be computed, trace processor uses the name of this file to find the proto and to figure out the name of the output table for the proto and the name of the extension field for TraceMetrics
; this is the reason it was important to choose the names of these other objects carefully.
Notes:
If everything went successfully, the following output should be visible (specifically this is the output for the Android example trace linked above):
[perfetto.protos.top_five_processes] { process_info { process_name: "com.google.android.GoogleCamera" cpu_time_ms: 15154 num_threads: 125 } process_info { process_name: "sugov:4" cpu_time_ms: 6846 num_threads: 1 } process_info { process_name: "system_server" cpu_time_ms: 6809 num_threads: 66 } process_info { process_name: "cds_ol_rx_threa" cpu_time_ms: 6684 num_threads: 1 } process_info { process_name: "com.android.chrome" cpu_time_ms: 5125 num_threads: 49 } }