Cookbook: Analysing Android Traces

This page will take you through some real world examples on how you can analyse issues with SQL and more advanced features of the Perfetto UI.

Finding slices

Demonstrates:

Querying slices.
GLOB and similar operators.
Common aggregators: COUNT, SUM, PERCENTILE.
JOIN tables.

Slices seen in Perfetto’s timeline UI can also be queried with PerfettoSQL. Press “Query (SQL)” in the sidebar and enter this query:

SELECT *
FROM slice
WHERE name GLOB '*interesting_slice*'
LIMIT 10;

Navigating back to the timeline (press “Show timeline”) will show the results table in the bottom bar. You can click slice IDs to jump to the slice in the timeline.

PerfettoSQL supports multiple pattern matching operators like GLOB, LIKE, and REGEXP. You can also use different aggregators to generate statistics on your selection.

SELECT
  name,
  COUNT(dur) AS count_slice,
  -- Convert nanoseconds to milliseconds
  AVG(dur) / 1000000 AS avg_dur_ms,
  CAST(MAX(dur) AS DOUBLE) / 1000000 AS max_dur_ms,
  CAST(MIN(dur) AS DOUBLE) / 1000000 AS min_dur_ms,
  PERCENTILE(dur,50) / 1000000 AS P50_dur_ms,
  PERCENTILE(dur,90) / 1000000 AS P90_dur_ms,
  PERCENTILE(dur,99) / 1000000 AS P99_dur_ms
FROM slice
WHERE name REGEXP '.*interesting_slice.*'
GROUP BY name
ORDER BY count_slice DESC
LIMIT 10;

You can join information across multiple tables to surface more information in query results or to narrow down your search.

SELECT
  s.id AS id,
  s.ts AS ts,
  s.track_id AS track_id,
  s.slice_id AS slice_id,
  s.dur AS dur,
  s.name AS slice,
  p.name AS process,
  t.name AS thread
FROM slice s
JOIN thread_track tt ON s.track_id = tt.id
JOIN thread t on tt.utid = t.utid
JOIN process p on t.upid = p.upid
WHERE s.name LIKE '%interesting_slice%'
-- Only look for slices in your app's process
AND p.name = 'com.example.myapp'
-- Only look for slices on your app's main thread
AND t.is_main_thread
ORDER BY dur DESC;

After running the query in the SQL view, click “Show timeline” in the sidebar and the query results will appear in the bottom bar. Queries that include the slice columns id, ts, dur, track_id, and slice_id can link to slices in the Timeline view for easy navigation. Click the value under id and the timeline will jump straight to that slice.

Find top causes for uninterruptible sleep

Demonstrates:

Joining tables on PerfettoSQL unique IDs.
SQL aggregation.

Thread tracks show a thread’s state, such as if it’s running, is runnable but not running, sleeping, etc. A common source of performance problems is when application threads enter “uninterruptible sleep”, i.e. call a kernel function that blocks on an uninterruptible condition.

To troubleshoot uninterruptible sleep you will need the following snippet in your Perfetto configuration when recording traces:

data_sources: {
    config {
        name: "linux.ftrace"
        target_buffer: 0
        ftrace_config {
            ftrace_events: "sched/sched_blocked_reason"
        }
    }
}

With this configured, when clicking on a thread state slice in uninterruptible sleep you will see in the bottom bar a field named “blocked_function”. Instead of clicking on individual slices, you can run a query to summarize the data:

SELECT blocked_function, COUNT(thread_state.id), SUM(dur)
FROM thread_state
JOIN thread USING (utid)
JOIN process USING (upid)
WHERE process.name = "com.google.android.youtube"
GROUP BY blocked_function
ORDER BY SUM(dur) DESC;

Find app startups blocked on monitor contention

Demonstrates:

PARTITION to subdivide a table of slices by the value of a column.
SPAN_JOIN to create spans from the intersection of data from two tables.

In Android Java and Kotlin, “monitor contention” is when a thread attempts to enter a synchronized section or call a synchronized method but another thread has already acquired the lock (aka monitor) used for synchronization. The example below demonstrates finding monitor contention slices that happened while an app was starting that blocked the app’s main thread, thus delaying the app’s startup.

INCLUDE PERFETTO MODULE android.monitor_contention;
INCLUDE PERFETTO MODULE android.startup.startups;

-- Join package and process information for startups
DROP VIEW IF EXISTS startups;
CREATE VIEW startups AS
SELECT startup_id, ts, dur, upid
FROM android_startups
JOIN android_startup_processes USING(startup_id);

-- Intersect monitor contention with startups in the same process.
-- This ensures that we only look at monitor contention in apps
-- that were starting up, and only during their startup phase.
DROP TABLE IF EXISTS monitor_contention_during_startup;
CREATE VIRTUAL TABLE monitor_contention_during_startup
USING SPAN_JOIN(android_monitor_contention PARTITIONED upid, startups PARTITIONED upid);

SELECT
  process_name,
  -- Convert duration from nanoseconds to milliseconds
  SUM(dur) / 1000000 AS sum_dur_ms,
  COUNT(*) AS count_contention
FROM monitor_contention_during_startup
WHERE is_blocked_thread_main
GROUP BY process_name
ORDER BY SUM(dur) DESC;

Process scheduling groups as debug tracks

Demonstrates:

Projecting a string column into one or more columns using substring substitution.
Creating a custom Debug Tracks in the Perfetto Timeline view.
Views.
PARTITION to subdivide slices by another column value.
LEAD to find the next event in a partition by timestamp order.

Android’s system_server will classify different app processes as belonging to different scheduling groups. This is used to direct more system resources towards more user-facing or otherwise latency-sensitive apps (such as “top” or “foreground” apps) and away from other processes that are doing latency-insensitive tasks in the background.

system_server will emit slices in the format of:

setProcessGroup <process> to <group>

With PerfettoSQL you can turn these strings into structured data:

INCLUDE PERFETTO MODULE slices.with_context;
SELECT
  ts,
  dur,
  SUBSTR(name, INSTR(name, ' ') + 1, INSTR(name, ' to ') - INSTR(name, ' ') - 1) as process_name,
  SUBSTR(name, INSTR(name, ' to ') + 4) AS group_id
FROM thread_slice
WHERE process_name = 'system_server'
AND thread_name = 'OomAdjuster'
AND name LIKE 'setProcessGroup %';

Using debug tracks you can add this information to the timeline. Press “Show timeline”. In the bottom bar, press “Show debug track” and configure:

Track type: counter
ts: ts
value: group_id
pivot: process_name

Press “Show” and you’ll see debug tracks generated from the results:

The integer values for groups are enumerated in SchedPolicy in system/core/libprocessgroup/include/processgroup/sched_policy.h. You can project the numeric values into string names:

INCLUDE PERFETTO MODULE slices.with_context;
SELECT
  ts,
  dur,
  SUBSTR(name, INSTR(name, ' ') + 1, INSTR(name, ' to ') - INSTR(name, ' ') - 1) as process_name,
  -- Resolve SchedPolicy
  CASE SUBSTR(name, INSTR(name, ' to ') + 4)
    WHEN '-1' THEN 'SP_DEFAULT'
    WHEN '0' THEN 'SP_BACKGROUND'
    WHEN '1' THEN 'SP_FOREGROUND'
    WHEN '2' THEN 'SP_SYSTEM'
    WHEN '3' THEN 'SP_AUDIO_APP'
    WHEN '4' THEN 'SP_AUDIO_SYS'
    WHEN '5' THEN 'SP_TOP_APP'
    WHEN '6' THEN 'SP_RT_APP'
    WHEN '7' THEN 'SP_RESTRICTED'
    WHEN '8' THEN 'SP_FOREGROUND_WINDOW'
    ELSE SUBSTR(name, INSTR(name, ' to ') + 4)
  END AS group_name
FROM thread_slice
WHERE process_name = 'system_server'
AND thread_name = 'OomAdjuster'
AND name LIKE 'setProcessGroup %';

Configure a debug track:

You’ll see debug tracks with human-readable names:

You’ll notice a problem - the durations of these tracks are short. The durations indicate just the time it took system_server to change the process group for these processes. You might want to see the duration that the process was in that group, i.e. for the durations to extend until the next group update or until the end of the trace. You can do this with LEAD by finding the next slice, partitioned over process_name.

INCLUDE PERFETTO MODULE slices.with_context;

-- Create a view so we can refer to next_ts in the following query
DROP VIEW IF EXISTS setProcessGroup;
CREATE VIEW setProcessGroup AS
SELECT
  ts,
  dur,
  SUBSTR(name, INSTR(name, ' ') + 1, INSTR(name, ' to ') - INSTR(name, ' ') - 1) as process_name,
  LEAD(ts) OVER (PARTITION BY SUBSTR(name, INSTR(name, ' ') + 1, INSTR(name, ' to ') - INSTR(name, ' ') - 1) ORDER BY ts) AS next_ts,
  -- Resolve SchedPolicy
  CASE SUBSTR(name, INSTR(name, ' to ') + 4)
    WHEN '-1' THEN 'SP_DEFAULT'
    WHEN '0' THEN 'SP_BACKGROUND'
    WHEN '1' THEN 'SP_FOREGROUND'
    WHEN '2' THEN 'SP_SYSTEM'
    WHEN '3' THEN 'SP_AUDIO_APP'
    WHEN '4' THEN 'SP_AUDIO_SYS'
    WHEN '5' THEN 'SP_TOP_APP'
    WHEN '6' THEN 'SP_RT_APP'
    WHEN '7' THEN 'SP_RESTRICTED'
    WHEN '8' THEN 'SP_FOREGROUND_WINDOW'
    ELSE SUBSTR(name, INSTR(name, ' to ') + 4)
  END AS group_name
FROM thread_slice
WHERE process_name = 'system_server'
AND thread_name = 'OomAdjuster'
AND name LIKE 'setProcessGroup %';

SELECT
  ts,
  dur,
  process_name,
  group_name,
  next_ts,
  IIF(
    next_ts IS NOT NULL,
    -- Duration is from ts to next_ts
    next_ts - ts,
    -- Duration is from ts to the last timestamp seen in this trace
    (SELECT MAX(ts + dur) FROM slice) - ts
  ) AS dur_until_next
FROM setProcessGroup;

Configure your debug tracks again:

The debug tracks should now look like this:

Here is an example from a busier trace, where you can see the same process being assigned to different groups: