startop: Add script to analyze block I/O from an ftrace file

Adds a simple python parser to convert .ftrace file into
sqlite3 database.

The rest of the analysis logic is done through a series of SQL
commands that build tables/views/select queries.

Bug: 134705245
Test: trace_analyzer some_ftrace_file.trace tmp_file.db
Change-Id: I25274e25a0ab1f091ae4e6161e6726e006e346a5

startop/scripts/trace_analyzer/queries_all.sql

@@ -0,0 +1,57 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+-- filter for atrace writes
+CREATE VIEW IF NOT EXISTS tracing_mark_writes AS
+    SELECT *
+      FROM raw_ftrace_entries
+     WHERE function = 'tracing_mark_write';
+
+-- split the tracing_mark_write function args by ||s
+DROP TABLE IF exists tracing_mark_write_split_array;
+
+CREATE TABLE tracing_mark_write_split_array (
+    predictorset_id INT REFERENCES raw_ftrace_entries (id),
+    predictor_name,
+    rest,
+    gen,
+    
+    UNIQUE(predictorset_id, gen) -- drops redundant inserts into table
+);
+
+CREATE INDEX "tracing_mark_write_split_array_id" ON tracing_mark_write_split_array (
+    predictorset_id COLLATE BINARY COLLATE BINARY
+);
+
+INSERT INTO tracing_mark_write_split_array
+  WITH 
+    split(predictorset_id, predictor_name, rest, gen) AS (
+      -- split by |
+      SELECT id, '', function_args || '|', 0 FROM tracing_mark_writes WHERE id
+       UNION ALL
+      SELECT predictorset_id, 
+             substr(rest, 0, instr(rest, '|')),
+             substr(rest, instr(rest, '|')+1),
+             gen + 1
+        FROM split
+       WHERE rest <> ''),
+     split_results AS (
+       SELECT * FROM split WHERE predictor_name <> ''
+     )
+  SELECT * from split_results
+;
+
+

startop/scripts/trace_analyzer/queries_app_launch_spans_with_name.sql

@@ -0,0 +1,44 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+-- use the 'launching: $process_name' async slice to figure out launch duration.
+DROP VIEW IF EXISTS launch_durations_named;
+
+CREATE VIEW launch_durations_named AS
+WITH
+    launch_traces_raw AS (
+        SELECT *
+        FROM tracing_mark_write_split AS tmw,
+             raw_ftrace_entries AS rfe
+        WHERE atrace_message LIKE 'launching: %' AND rfe.id = tmw.raw_ftrace_entry_id
+    ),
+    launch_traces_joined AS (
+        SELECT started.timestamp AS started_timestamp,
+               finished.timestamp AS finished_timestamp,
+               started.id AS started_id,
+               finished.id AS finished_id,
+               SUBSTR(started.atrace_message, 12) AS proc_name   -- crop out "launching: " from the string.
+        FROM launch_traces_raw AS started,
+             launch_traces_raw AS finished
+        -- async slices ('S' -> 'F') have matching counters given the same PID.
+        WHERE started.atrace_type == 'S'
+              AND finished.atrace_type == 'F'
+              AND started.atrace_count == finished.atrace_count
+              AND started.atrace_pid == finished.atrace_pid
+    )
+SELECT * from launch_traces_joined;
+
+SELECT * FROM launch_durations_named;

startop/scripts/trace_analyzer/queries_block_launch.sql

@@ -0,0 +1,52 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+DROP VIEW IF EXISTS blocked_iowait_for_app_launches;
+
+CREATE VIEW blocked_iowait_for_app_launches AS
+WITH
+    block_launch_join AS (
+        SELECT *
+        FROM blocking_durations AS bd,
+             launch_durations_named AS ld
+        WHERE bd.block_timestamp >= ld.started_timestamp
+              AND bd.unblock_timestamp <= ld.finished_timestamp
+    ),
+    blocked_ui_threads AS (
+        SELECT *
+        FROM start_process_ui_threads AS sp,
+             block_launch_join AS blj
+        WHERE sp.atm_ui_thread_tid == unblock_pid
+              AND sp.process_name = blj.proc_name
+    ),
+    summed_raw AS (
+        SELECT SUM(unblock_timestamp-block_timestamp)*1000 AS sum_block_duration_ms,
+               *
+        FROM blocked_ui_threads
+        GROUP BY unblock_pid
+    ),
+    summed_neat AS (
+        SELECT sum_block_duration_ms AS blocked_iowait_duration_ms,
+               process_name,
+               (finished_timestamp - started_timestamp) * 1000 AS launching_duration_ms,
+               started_timestamp * 1000 AS launching_started_timestamp_ms,
+               finished_timestamp * 1000 AS launching_finished_timestamp_ms
+                -- filter out the rest because its just selecting 1 arbitrary row (due to the SUM aggregate).,
+        FROM summed_raw
+    )
+SELECT * FROM summed_neat;
+
+SELECT * FROM blocked_iowait_for_app_launches;

startop/scripts/trace_analyzer/queries_find_sched_switch_unblocked.sql

@@ -0,0 +1,101 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+DROP VIEW IF EXISTS sched_switch_iowaits_pre;
+
+-- scan for the closest pair such that:
+--                  sched_block_reason pid=$PID iowait=1 ...
+--                  ...
+--                  sched_switch next_pid=$PID
+CREATE VIEW sched_switch_iowaits_pre AS
+    SELECT MAX(sbr.id) AS blocked_id,
+           ss.id AS sched_switch_id,
+           pid,         -- iow.pid
+           iowait,      -- iowait=0 or iowait=1
+           caller,
+           sbr_f.timestamp AS blocked_timestamp,
+           ss_f.timestamp AS sched_switch_timestamp,
+           next_comm,   -- name of next_pid
+           next_pid     -- same as iow.pid
+    FROM sched_blocked_reasons AS sbr,
+         raw_ftrace_entries AS sbr_f,
+         sched_switches AS ss,
+         raw_ftrace_entries AS ss_f
+    WHERE sbr_f.id == sbr.id
+          AND ss_f.id == ss.id
+          AND sbr.pid == ss.next_pid
+          AND sbr.iowait = 1
+          AND sbr_f.timestamp < ss_f.timestamp     -- ensures the 'closest' sched_blocked_reason is selected.
+    GROUP BY ss.id
+;
+
+DROP VIEW IF EXISTS sched_switch_iowaits;
+
+CREATE VIEW sched_switch_iowaits AS
+    SELECT *, MIN(sched_switch_timestamp) AS ss_timestamp      -- drop all of the 'too large' sched_switch entries except the closest one.
+    FROM sched_switch_iowaits_pre
+    GROUP BY blocked_id;
+
+SELECT * FROM sched_switch_iowaits;
+
+-- use a real table here instead of a view, otherwise SQLiteStudio segfaults for some reason.
+DROP TABLE IF EXISTS blocking_durations;
+
+CREATE TABLE blocking_durations AS
+WITH
+    blocking_durations_raw AS (
+        SELECT MAX(ss.id) AS block_id,
+               ssf.timestamp AS block_timestamp,
+               iow.sched_switch_timestamp AS unblock_timestamp,
+               ss.prev_comm as block_prev_comm,
+               iow.next_comm AS unblock_next_comm,
+               ss.prev_state AS block_prev_state,
+               iow.sched_switch_id AS unblock_id,
+               iow.pid AS unblock_pid,
+               iow.caller AS unblock_caller
+        FROM sched_switches AS ss,          -- this is the sched_switch that caused a block (in the future when it unblocks, the reason is iowait=1).
+             sched_switch_iowaits AS iow,    -- this is the sched_switch that removes the block (it is now running again).
+             raw_ftrace_entries AS ssf
+        WHERE ssf.id = ss.id AND ss.prev_pid == iow.next_pid AND ssf.timestamp < iow.sched_switch_timestamp
+        GROUP BY unblock_timestamp 
+    ),
+    blocking_durations_tmp AS (
+        SELECT block_id,
+               unblock_timestamp,
+               block_timestamp,
+               block_prev_comm as comm,
+               block_prev_state as block_state,
+               unblock_id,
+               unblock_pid,
+               unblock_caller
+        FROM blocking_durations_raw
+    )
+    SELECT * FROM blocking_durations_tmp;-- ORDER BY block_id ASC;
+    --SELECT SUM(block_duration_ms) AS sum, * FROM blocking_durations GROUP BY unblock_pid ORDER BY sum DESC;
+
+DROP INDEX IF EXISTS "blocking_durations_block_timestamp";
+
+CREATE INDEX "blocking_durations_block_timestamp" ON blocking_durations (
+    block_timestamp COLLATE BINARY COLLATE BINARY
+);
+
+DROP INDEX IF EXISTS "blocking_durations_unblock_timestamp";
+
+CREATE INDEX "blocking_durations_unblock_timestamp" ON blocking_durations (
+    unblock_timestamp COLLATE BINARY COLLATE BINARY
+);
+
+SELECT * FROM blocking_durations;

startop/scripts/trace_analyzer/queries_get_comm_and_pids.sql

@@ -0,0 +1,42 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+DROP VIEW IF EXISTS sched_switch_next_comm_pids;
+
+CREATE VIEW IF NOT EXISTS sched_switch_next_comm_pids AS
+
+-- TODO: switch to using sched_switches table.
+
+WITH
+    sched_switchs AS (
+        SELECT * FROM raw_ftrace_entries WHERE function = 'sched_switch' AND function_args LIKE '% next_pid=%' AND function_args NOT LIKE '% next_comm=main %'
+    ),
+    comm_and_pids_raws AS (
+        SELECT id,
+               SUBSTR(function_args, instr(function_args, "next_comm="), instr(function_args, "next_pid=") - instr(function_args, "next_comm=")) AS next_comm_raw,
+               SUBSTR(function_args, instr(function_args, "next_pid="), instr(function_args, "next_prio=") - instr(function_args, "next_pid=")) AS next_pid_raw
+        FROM sched_switchs
+    ),
+    comm_and_pids AS (
+        SELECT id,
+               id AS raw_ftrace_entry_id,
+               TRIM(SUBSTR(next_pid_raw, 10)) AS next_pid, -- len("next_pid=") is 10
+               TRIM(SUBSTR(next_comm_raw, 11)) AS next_comm -- len("next_comm=") is 11
+        FROM comm_and_pids_raws
+    )
+SELECT * from comm_and_pids;
+
+SELECT * from sched_switch_next_comm_pids;

startop/scripts/trace_analyzer/queries_get_procs.sql

@@ -0,0 +1,30 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+DROP VIEW IF EXISTS start_procs;
+
+CREATE VIEW IF NOT EXISTS start_procs AS
+WITH
+  start_procs_raw AS (
+      SELECT * from tracing_mark_write_split WHERE atrace_message LIKE 'Start proc: %'
+  ),
+  start_procs_substr AS (
+      -- note: "12" is len("Start proc: ")+1. sqlite indices start at 1.
+      SELECT raw_ftrace_entry_id, atrace_pid, SUBSTR(atrace_message, 13) AS process_name FROM start_procs_raw
+  )
+SELECT * from start_procs_substr;
+
+SELECT * from start_procs;

startop/scripts/trace_analyzer/queries_get_ui_threads.sql

@@ -0,0 +1,88 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+-- note: These queries do comparisons based on raw_ftrace_entries.id by treating it as if it was equivalent to the temporal timestamp.
+-- in practice, the ID of raw_ftrace_entries is based on its order in the ftrace buffer [and on the same cpu its equivalent].
+-- we can always resort raw_ftrace_entries to ensure id order matches timestamp order. We should rarely need to compare by timestamp directly.
+-- accessing 'floats' is inferior as they are harder to index, and will result in slower queries.
+--
+-- Naming convention note: '_fid' corresponds to 'raw_ftrace_entry.id'.
+DROP VIEW IF EXISTS start_process_ui_threads;
+
+-- Map of started process names to their UI thread's TID (as returned by gettid).
+CREATE VIEW IF NOT EXISTS start_process_ui_threads AS
+WITH
+  start_proc_tids AS (
+    SELECT sp.raw_ftrace_entry_id AS start_proc_fid,
+           sp.atrace_pid AS atrace_pid,
+           sp.process_name AS process_name,
+           --MIN(nc.raw_ftrace_entry_id) as next_comm_fid,
+           nc.raw_ftrace_entry_id AS next_comm_fid,
+           nc.next_pid as next_pid,
+           nc.next_comm as next_comm,
+           SUBSTR(sp.process_name, -15) AS cut      -- why -15? See TASK_MAX in kernel, the sched_switch name is truncated to 16 bytes.
+    FROM start_procs AS sp,
+         sched_switch_next_comm_pids AS nc
+    WHERE sp.process_name LIKE '%' || nc.next_comm  -- kernel truncates the sched_switch::next_comm event, so we must match the prefix of the full name.
+    --WHERE SUBSTR(sp.process_name, -16) == nc.next_comm
+    --WHERE cut == nc.next_comm
+  ),
+  start_proc_tids_filtered AS (
+      SELECT *
+      FROM start_proc_tids
+      WHERE next_comm_fid > start_proc_fid        -- safeguard that avoids choosing "earlier" sched_switch before process was even started.
+      --ORDER BY start_proc_fid, next_comm_fid
+  ),
+  start_proc_all_threads AS (
+    SELECT DISTINCT
+        start_proc_fid, -- this is the ftrace entry of the system server 'Start proc: $process_name'. only need this to join for timestamp.
+        process_name,               -- this is the '$process_name' from the system server entry.
+        -- next up we have all the possible thread IDs as parsed from sched_switch that corresponds most closest to the start proc.
+        next_pid AS ui_thread_tpid, -- sched_switch.next_pid. This can be any of the threads in that process, it's not necessarily the main UI thread yet.
+        next_comm,
+        MIN(next_comm_fid) AS next_comm_fid   -- don't pick the 'later' next_comm_fid because it could correspond to another app start.
+    FROM start_proc_tids_filtered
+    GROUP BY start_proc_fid, ui_thread_tpid
+  ),
+  activity_thread_mains AS (
+    SELECT * FROM tracing_mark_write_split WHERE atrace_message = 'ActivityThreadMain'
+  ),
+  start_proc_ui_threads AS (
+    SELECT start_proc_fid,
+           process_name,
+           ui_thread_tpid,
+           next_comm,
+           next_comm_fid,
+           atm.raw_ftrace_entry_id as atm_fid,
+           atm.atrace_pid as atm_ui_thread_tid
+    FROM start_proc_all_threads AS spt, 
+         activity_thread_mains AS atm
+    WHERE atm.atrace_pid == spt.ui_thread_tpid AND atm.raw_ftrace_entry_id > spt.start_proc_fid -- Ensure we ignore earlier ActivityThreadMains prior to their Start proc.
+  ),
+  start_proc_ui_threads_filtered AS (
+    SELECT start_proc_fid,
+           process_name,                -- e.g. 'com.android.settings'
+           --ui_thread_tpid,
+           --next_comm,
+           --next_comm_fid,
+           MIN(atm_fid) AS atm_fid,
+           atm_ui_thread_tid            -- equivalent to gettid() for the process's UI thread.
+    FROM start_proc_ui_threads
+    GROUP BY start_proc_fid, atm_ui_thread_tid    -- find the temporally closest ActivityTaskMain to a "Start proc: $process_name"
+  )
+SELECT * FROM start_proc_ui_threads_filtered;
+
+SELECT * FROM start_process_ui_threads;

startop/scripts/trace_analyzer/queries_mark_write_join.sql

@@ -0,0 +1,53 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+DROP TABLE IF EXISTS tracing_mark_write_split;
+
+CREATE TABLE tracing_mark_write_split (
+    raw_ftrace_entry_id INT REFERENCES raw_ftrace_entries (id),
+    atrace_type CHAR(1), -- only null for the first 2 sync timers. usually 'B', 'C', E', ...
+    atrace_pid INT,      -- only null for first 2 sync timers
+    atrace_message,      -- usually null for type='E' etc.
+    atrace_count,        -- usually non-null only for 'C'
+
+    UNIQUE(raw_ftrace_entry_id) -- drops redundant inserts into table
+);
+
+INSERT INTO tracing_mark_write_split
+WITH
+    pivoted AS (
+        SELECT tx.predictorset_id,
+               --ty.predictorset_id,
+               --tz.predictorset_id,
+               --tzz.predictorset_id,
+               tx.predictor_name AS atrace_type,
+               CAST(ty.predictor_name  AS integer) AS atrace_pid,
+               tz.predictor_name AS atrace_message,
+               CAST(tzz.predictor_name AS integer) AS atrace_count
+        FROM (SELECT * from tracing_mark_write_split_array WHERE gen = 1) AS tx
+        LEFT JOIN
+             (SELECT * FROM tracing_mark_write_split_array WHERE gen = 2) AS ty
+        ON tx.predictorset_id = ty.predictorset_id
+        LEFT JOIN
+             (SELECT * FROM tracing_mark_write_split_array WHERE gen = 3) AS tz
+        ON tx.predictorset_id = tz.predictorset_id
+        LEFT JOIN
+             (SELECT * FROM tracing_mark_write_split_array WHERE gen = 4) AS tzz
+        ON tx.predictorset_id = tzz.predictorset_id
+    )
+SELECT * from pivoted ORDER BY predictorset_id;-- LIMIT 100;
+
+SELECT * FROM tracing_mark_write_split;

startop/scripts/trace_analyzer/queries_pretty_print_block_launch.sql

@@ -0,0 +1,28 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+.headers on
+.mode quote
+
+SELECT * FROM blocked_iowait_for_app_launches;
+
+/*
+Output as CSV example:
+
+'blocked_iowait_duration_ms','process_name','launching_duration_ms','launching_started_timestamp_ms','launching_finished_timestamp_ms'
+125.33199995596078224,'com.android.settings',1022.4840000009862706,17149896.822000000626,17150919.305999998003
+
+*/

startop/scripts/trace_analyzer/run-sql-queries

@@ -0,0 +1,79 @@
+#!/bin/bash
+# Copyright (C) 2019 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+DIR="$( cd "$(dirname "$0")" ; pwd -P )"
+
+if [[ $# -lt 1 ]]; then
+  echo "Usage: $0 <db-file>"
+fi
+
+DB_TARGET=$1
+
+if ! [[ -f $DB_TARGET ]]; then
+  echo "ERROR: File '$DB_TARGET' does not exist." >&2
+  exit 1
+fi
+
+exec_sql_file() {
+  local filename="$1"
+  if ! [[ -f $filename ]]; then
+    echo "ERROR: Can't exec SQL file, '$filename' does not exist." >&2
+    return 1
+  fi
+
+  sqlite3 "$DB_TARGET" < "$DIR"/"$filename"
+}
+
+exec_sql_file_quiet() {
+  exec_sql_file "$@" > /dev/null
+}
+
+# Some views/tables need other views already created, so order does matter.
+# x -> y , means x depends on y.
+
+# View: tracing_mark_writes
+# Table: tracing_mark_write_split_array -> tracing_mark_writes
+exec_sql_file_quiet "queries_all.sql"
+
+# Table: tracing_mark_write_split -> tracing_mark_write_split_array
+exec_sql_file_quiet "queries_mark_write_join.sql"
+
+# View: start_procs -> tracing_mark_write_split
+exec_sql_file_quiet "queries_get_procs.sql"
+
+# View: sched_switch_next_comm_pids
+exec_sql_file_quiet "queries_get_comm_and_pids.sql"
+
+# View: start_process_ui_threads -> start_procs, sched_switch_next_comm_pids
+exec_sql_file_quiet "queries_get_ui_threads.sql"
+
+# View: launch_durations_named -> tracing_mark_write_split
+exec_sql_file_quiet "queries_app_launch_spans_with_name.sql"
+
+# View: sched_switch_iowaits_pre
+# View: sched_switch_iowaits -> sched_switch_iowaits_pre
+# Table: blocking_durations -> sched_switch_iowaits
+exec_sql_file_quiet "queries_find_sched_switch_unblocked.sql"
+
+# View: blocked_iowait_for_app_launches -> launch_durations_named, blocking_durations
+exec_sql_file_quiet "queries_block_launch.sql"
+
+#####
+#####
+#####
+
+# Final queries
+
+exec_sql_file "queries_pretty_print_block_launch.sql"

startop/scripts/trace_analyzer/trace_analyzer

@@ -0,0 +1,42 @@
+#!/bin/bash
+# Copyright (C) 2019 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+DIR="$( cd "$(dirname "$0")" ; pwd -P )"
+
+if [[ "$#" -lt 2 ]]; then
+  echo "Usage: $0 <filename.trace> <sqlite-filename.db>" >&2
+  exit 1
+fi
+
+TRACE_FILENAME="$1"
+SQLITE_FILENAME="$2"
+
+#echo "Trace filename: $TRACE_FILENAME"
+#echo "SQLite filename: $SQLITE_FILENAME"
+
+if ! [[ -f "$TRACE_FILENAME" ]]; then
+  echo "Error: Trace '$TRACE_FILENAME' does not exist." >&2
+  exit 1
+fi
+
+if ! "$DIR/trace_analyzer.py" "$SQLITE_FILENAME" "$TRACE_FILENAME" > /dev/null; then
+  echo "Fatal: trace_analyzer.py failed, aborting." >&2
+  exit 1
+fi
+
+if ! "$DIR/run-sql-queries" "$SQLITE_FILENAME"; then
+  echo "Fatal: Failed to run sql queries, aborting." >&2
+  exit 1
+fi

startop/scripts/trace_analyzer/trace_analyzer.py

@@ -0,0 +1,350 @@
+#!/usr/bin/python3
+# Copyright (C) 2019 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import re
+import sys
+
+from sqlalchemy import create_engine
+from sqlalchemy import Column, Date, Integer, Float, String, ForeignKey
+from sqlalchemy.ext.declarative import declarative_base
+
+from sqlalchemy.orm import sessionmaker
+
+import sqlalchemy
+
+_DEBUG = False
+#_LIMIT = 100000
+_LIMIT = None
+_FLUSH_LIMIT = 10000
+
+Base = declarative_base()
+
+class RawFtraceEntry(Base):
+  __tablename__ = 'raw_ftrace_entries'
+
+  id = Column(Integer, primary_key=True)
+  task_name = Column(String, nullable=True) # <...> -> None.
+  task_pid = Column(String, nullable=False)
+  tgid = Column(Integer, nullable=True)     # ----- -> None.
+  cpu = Column(Integer, nullable=False)
+  timestamp = Column(Float, nullable=False)
+  function = Column(String, nullable=False)
+  function_args = Column(String, nullable=False)
+
+#  __mapper_args__ = {
+#      'polymorphic_identity':'raw_ftrace_entry',
+#      'polymorphic_on':function
+#  }
+
+  @staticmethod
+  def parse(line):
+    # '           <...>-5521  (-----) [003] ...1 17148.446877: tracing_mark_write: trace_event_clock_sync: parent_ts=17148.447266'
+    m = re.match('\s*(.*)-(\d+)\s+\(([^\)]+)\)\s+\[(\d+)\]\s+([\w.]{4})\s+(\d+[.]\d+):\s+(\w+):\s+(.*)', line)
+    if not m:
+      return None
+
+    groups = m.groups()
+    # groups example:
+    # ('<...>',
+    #  '5521',
+    #  '-----',
+    #  '003',
+    #  '...1',
+    #  '17148.446877',
+    #  'tracing_mark_write',
+    #  'trace_event_clock_sync: parent_ts=17148.447266')
+    task_name = groups[0]
+    if task_name == '<...>':
+      task_name = None
+
+    task_pid = int(groups[1])
+    tgid = groups[2]
+    if tgid == '-----':
+      tgid = None
+
+    cpu = int(groups[3])
+    # irq_flags = groups[4]
+    timestamp = float(groups[5])
+    function = groups[6]
+    function_args = groups[7]
+
+    return RawFtraceEntry(task_name=task_name, task_pid=task_pid, tgid=tgid, cpu=cpu,
+                          timestamp=timestamp, function=function, function_args=function_args)
+
+  @staticmethod
+  def parse_dict(line):
+    # '           <...>-5521  (-----) [003] ...1 17148.446877: tracing_mark_write: trace_event_clock_sync: parent_ts=17148.447266'
+    m = re.match('\s*(.*)-(\d+)\s+\(([^\)]+)\)\s+\[(\d+)\]\s+([\w.]{4})\s+(\d+[.]\d+):\s+(\w+):\s+(.*)', line)
+    if not m:
+      return None
+
+    groups = m.groups()
+    # groups example:
+    # ('<...>',
+    #  '5521',
+    #  '-----',
+    #  '003',
+    #  '...1',
+    #  '17148.446877',
+    #  'tracing_mark_write',
+    #  'trace_event_clock_sync: parent_ts=17148.447266')
+    task_name = groups[0]
+    if task_name == '<...>':
+      task_name = None
+
+    task_pid = int(groups[1])
+    tgid = groups[2]
+    if tgid == '-----':
+      tgid = None
+
+    cpu = int(groups[3])
+    # irq_flags = groups[4]
+    timestamp = float(groups[5])
+    function = groups[6]
+    function_args = groups[7]
+
+    return {'task_name': task_name, 'task_pid': task_pid, 'tgid': tgid, 'cpu': cpu, 'timestamp': timestamp, 'function': function, 'function_args': function_args}
+
+#class TracingMarkWriteFtraceEntry(RawFtraceEntry):
+#  __tablename__ = 'tracing_mark_write_ftrace_entries'
+#
+#  id = Column(Integer, ForeignKey('raw_ftrace_entries.id'), primary_key=True)
+#  mark_type = Column(String(1), nullable=False)
+#  mark_id = Column(Integer, nullable=False)
+#  message = Column(String)
+#
+##  __mapper_args__ = {
+##      'polymorphic_identity':'tracing_mark_write',
+##  }
+#
+#  @staticmethod
+#  def decode(raw_ftrace_entry):
+#    if raw_ftrace_entry.function != 'tracing_mark_write':
+#      raise ValueError("raw_ftrace_entry must be function 'tracing_mark_write':" + raw_ftrace_entry)
+#
+#    #"B|2446|(Paused)ClearCards|Foo"
+#    match = re.match("([^|]*)\|([^|]*)\|(.*)", raw_ftrace_entry.function_args)
+#
+#    if not match:
+#      return None
+#
+#    # ('B', '2446', '(Paused)ClearCards|Foo')
+#    groups = match.groups()
+#
+#    mark_type = groups[0]
+#    mark_id = int(groups[1])
+#    message = groups[2]
+#
+#    return TracingMarkWriteFtraceEntry(id = raw_ftrace_entry.id,
+#        mark_type = mark_type,
+#        mark_id = mark_id,
+#        message = message)
+
+class SchedSwitch(Base):
+  __tablename__ = 'sched_switches'
+
+  id = Column(Integer, ForeignKey('raw_ftrace_entries.id'), primary_key=True)
+
+  prev_comm = Column(String, nullable=False)
+  prev_pid = Column(Integer, nullable=False)
+  prev_prio = Column(Integer, nullable=False)
+  prev_state = Column(String, nullable=False)
+
+  next_comm = Column(String, nullable=False)
+  next_pid = Column(Integer, nullable=False)
+  next_prio = Column(Integer, nullable=False)
+
+#  __mapper_args__ = {
+#      'polymorphic_identity':'raw_ftrace_entry',
+#      'polymorphic_on':function
+#  }
+
+  @staticmethod
+  def parse_dict(function_args, id = None):
+    # 'prev_comm=kworker/u16:5 prev_pid=13971 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120'
+    m = re.match("prev_comm=(.*) prev_pid=(\d+) prev_prio=(\d+) prev_state=(.*) ==> next_comm=(.*) next_pid=(\d+) next_prio=(\d+) ?", function_args)
+    if not m:
+      return None
+
+    groups = m.groups()
+    # ('kworker/u16:5', '13971', '120', 'S', 'swapper/4', '0', '120')
+    d = {}
+    if id is not None:
+      d['id'] = id
+    d['prev_comm'] = groups[0]
+    d['prev_pid'] = int(groups[1])
+    d['prev_prio'] = int(groups[2])
+    d['prev_state'] = groups[3]
+    d['next_comm'] = groups[4]
+    d['next_pid'] = int(groups[5])
+    d['next_prio'] = int(groups[6])
+
+    return d
+
+class SchedBlockedReason(Base):
+  __tablename__ = 'sched_blocked_reasons'
+
+  id = Column(Integer, ForeignKey('raw_ftrace_entries.id'), primary_key=True)
+
+  pid = Column(Integer, nullable=False)
+  iowait = Column(Integer, nullable=False)
+  caller = Column(String, nullable=False)
+
+  @staticmethod
+  def parse_dict(function_args, id = None):
+    # 'pid=2289 iowait=1 caller=wait_on_page_bit_common+0x2a8/0x5f'
+    m = re.match("pid=(\d+) iowait=(\d+) caller=(.*) ?", function_args)
+    if not m:
+      return None
+
+    groups = m.groups()
+    # ('2289', '1', 'wait_on_page_bit_common+0x2a8/0x5f8')
+    d = {}
+    if id is not None:
+      d['id'] = id
+    d['pid'] = int(groups[0])
+    d['iowait'] = int(groups[1])
+    d['caller'] = groups[2]
+
+    return d
+
+def init_sqlalchemy(db_filename):
+  global _DEBUG
+  engine = create_engine('sqlite:///' + db_filename, echo=_DEBUG)
+
+  # DROP TABLES
+#  Base.metadata.drop_all(engine)
+  # CREATE ... (tables)
+  Base.metadata.create_all(engine)
+
+  Session = sessionmaker(bind=engine)
+  session = Session()
+  return (session, engine)
+
+def insert_pending_entries(engine, kls, lst):
+  if len(lst) > 0:
+    # for some reason, it tries to generate an empty INSERT statement with len=0,
+    # which of course violates the first non-null constraint.
+    try:
+      # Performance-sensitive parsing according to:
+      # https://docs.sqlalchemy.org/en/13/faq/performance.html#i-m-inserting-400-000-rows-with-the-orm-and-it-s-really-slow
+      engine.execute(kls.__table__.insert(), lst)
+      lst.clear()
+    except sqlalchemy.exc.IntegrityError as err:
+      # possibly violating some SQL constraint, print data here.
+      print(err)
+      print(lst)
+      raise
+
+def parse_file(filename, session, engine):
+  global _LIMIT
+  global _FLUSH_LIMIT
+  count = 0
+
+  pending_entries = []
+  pending_sched_switch = []
+  pending_sched_blocked_reasons = []
+
+  def insert_all_pending_entries():
+    insert_pending_entries(engine, RawFtraceEntry, pending_entries)
+    insert_pending_entries(engine, SchedSwitch, pending_sched_switch)
+    insert_pending_entries(engine, SchedBlockedReason, pending_sched_blocked_reasons)
+
+  # use explicit encoding to avoid UnicodeDecodeError.
+  with open(filename, encoding="ISO-8859-1") as f:
+    for l in f:
+
+      if len(l) > 1 and l[0] == '#':
+        continue
+
+      count = count + 1
+
+      if _LIMIT and count >= _LIMIT:
+        break
+
+      raw_ftrace_entry = RawFtraceEntry.parse_dict(l)
+      if not raw_ftrace_entry:
+        print("WARNING: Failed to parse raw ftrace entry: " + l)
+        continue
+
+      pending_entries.append(raw_ftrace_entry)
+
+      if raw_ftrace_entry['function'] == 'sched_switch':
+        sched_switch = SchedSwitch.parse_dict(raw_ftrace_entry['function_args'], count)
+
+        if not sched_switch:
+          print("WARNING: Failed to parse sched_switch: " + l)
+        else:
+          pending_sched_switch.append(sched_switch)
+
+      elif raw_ftrace_entry['function'] == 'sched_blocked_reason':
+        sbr = SchedBlockedReason.parse_dict(raw_ftrace_entry['function_args'], count)
+
+        if not sbr:
+          print("WARNING: Failed to parse sched_blocked_reason: " + l)
+        else:
+          pending_sched_blocked_reasons.append(sbr)
+
+      # Objects are cached in python memory, not yet sent to SQL database.
+      #session.add(raw_ftrace_entry)
+
+      # Send INSERT/UPDATE/etc statements to the underlying SQL database.
+      if count % _FLUSH_LIMIT == 0:
+        # session.flush()
+        #session.bulk_save_objects(pending_entries)
+        #session.bulk_insert_mappings(RawFtraceEntry, pending_entries)
+        insert_all_pending_entries()
+
+  insert_all_pending_entries()
+
+  # Ensure underlying database commits changes from memory to disk.
+  session.commit()
+
+  return count
+
+#def decode_raw_traces(session, engine):
+#  count = 0
+#  global _FLUSH_LIMIT
+#
+#  for tmw in session.query(RawFtraceEntry).filter_by(function = 'tracing_mark_write'):
+#    print(tmw)
+#    decoded = TracingMarkWriteFtraceEntry.decode(tmw)
+#    session.add(decoded)
+#
+#    if count % _FLUSH_LIMIT == 0:
+#      session.flush()
+#
+#  session.commit()
+#
+#  return count
+
+def main(argv):
+  db_filename = sys.argv[1]
+  trace_filename = sys.argv[2]
+
+  session, engine = init_sqlalchemy(db_filename)
+  print("SQL Alchemy db initialized")
+
+  # parse 'raw_ftrace_entries' table
+  count = parse_file(trace_filename, session, engine)
+  print("Count was ", count)
+
+  # create other tables
+#  count = decode_raw_traces(session, engine)
+
+  return 0
+
+if __name__ == '__main__':
+  main(sys.argv)

startop/scripts/trace_analyzer/trace_analyzer_recursive

@@ -0,0 +1,78 @@
+#!/bin/bash
+# Copyright (C) 2019 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+DIR="$( cd "$(dirname "$0")" ; pwd -P )"
+
+if [[ "$#" -lt 3 ]]; then
+  echo "Usage: $0 <trace-dir> <db-dir> <output.csv>" >&2
+  exit 1
+fi
+
+simulate="n"
+
+TRACE_DIRNAME="$1"
+SQLITE_DIRNAME="$2"
+OUTPUT_FILENAME="$3"
+
+echo "Trace filename: $TRACE_DIRNAME"
+echo "SQLite filename: $SQLITE_DIRNAME"
+
+if ! [[ -d "$TRACE_DIRNAME" ]]; then
+  echo "Error: Trace '$TRACE_DIRNAME' does not exist." >&2
+  exit 1
+fi
+
+process_trace_file() {
+  local trace_filename="$1"
+  local db_dirname="$2"
+  local output_file="$3"
+
+  local db_filename="$db_dirname/$(basename "$trace_filename").db"
+
+  if [[ $simulate == y ]]; then
+    echo "$DIR/trace_analyzer.py" "$db_filename" "$trace_filename" "> /dev/null"
+  else
+    if ! "$DIR/trace_analyzer.py" "$db_filename" "$trace_filename" > /dev/null; then
+      echo "Fatal: trace_analyzer.py failed, aborting." >&2
+      return 1
+    fi
+  fi
+
+  if [[ $simulate == y ]]; then
+    echo "$DIR/run-sql-queries" "$db_filename" ">> '$output_file'"
+  else
+    # append name of trace to CSV, so we can see where data came from
+    echo "; $trace_filename" >> "$output_file"
+    if ! "$DIR/run-sql-queries" "$db_filename" >> "$output_file"; then
+      echo "Fatal: Failed to run sql queries, aborting." >&2
+      return 1
+    fi
+  fi
+
+  return 0
+}
+
+find "$TRACE_DIRNAME" -type f -name '*.trace' -print0 |
+while IFS= read -r -d '' file; do
+  if [[ $file == *#*.trace && $file != *#1.trace ]]; then
+    echo "Skip $file"
+    continue
+  fi
+
+  printf '%s\n' "$file"
+  process_trace_file "$file" "$SQLITE_DIRNAME" "$OUTPUT_FILENAME"
+done
+
+echo "Done"