summaryrefslogtreecommitdiff
path: root/startop/scripts/trace_analyzer
diff options
context:
space:
mode:
authorIgor Murashkin <iam@google.com>2019-06-06 16:10:16 -0700
committerIgor Murashkin <iam@google.com>2019-06-10 22:17:13 +0000
commit0c65d1c5faac197630f919085fc690a716783303 (patch)
tree5a0a83ff437cdc95e9729a70984e1c59eab81b73 /startop/scripts/trace_analyzer
parent2cd5a231f9775c07e13312607260b338549e37b1 (diff)
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
Diffstat (limited to 'startop/scripts/trace_analyzer')
-rw-r--r--startop/scripts/trace_analyzer/queries_all.sql57
-rw-r--r--startop/scripts/trace_analyzer/queries_app_launch_spans_with_name.sql44
-rw-r--r--startop/scripts/trace_analyzer/queries_block_launch.sql52
-rw-r--r--startop/scripts/trace_analyzer/queries_find_sched_switch_unblocked.sql101
-rw-r--r--startop/scripts/trace_analyzer/queries_get_comm_and_pids.sql42
-rw-r--r--startop/scripts/trace_analyzer/queries_get_procs.sql30
-rw-r--r--startop/scripts/trace_analyzer/queries_get_ui_threads.sql88
-rw-r--r--startop/scripts/trace_analyzer/queries_mark_write_join.sql53
-rw-r--r--startop/scripts/trace_analyzer/queries_pretty_print_block_launch.sql28
-rwxr-xr-xstartop/scripts/trace_analyzer/run-sql-queries79
-rwxr-xr-xstartop/scripts/trace_analyzer/trace_analyzer42
-rwxr-xr-xstartop/scripts/trace_analyzer/trace_analyzer.py350
-rwxr-xr-xstartop/scripts/trace_analyzer/trace_analyzer_recursive78
13 files changed, 1044 insertions, 0 deletions
diff --git a/startop/scripts/trace_analyzer/queries_all.sql b/startop/scripts/trace_analyzer/queries_all.sql
new file mode 100644
index 000000000000..41d1c0804a7f
--- /dev/null
+++ b/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
+;
+
+
diff --git a/startop/scripts/trace_analyzer/queries_app_launch_spans_with_name.sql b/startop/scripts/trace_analyzer/queries_app_launch_spans_with_name.sql
new file mode 100644
index 000000000000..c28475eec73d
--- /dev/null
+++ b/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;
diff --git a/startop/scripts/trace_analyzer/queries_block_launch.sql b/startop/scripts/trace_analyzer/queries_block_launch.sql
new file mode 100644
index 000000000000..34e5f03d0c48
--- /dev/null
+++ b/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;
diff --git a/startop/scripts/trace_analyzer/queries_find_sched_switch_unblocked.sql b/startop/scripts/trace_analyzer/queries_find_sched_switch_unblocked.sql
new file mode 100644
index 000000000000..788d0dae47d3
--- /dev/null
+++ b/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;
diff --git a/startop/scripts/trace_analyzer/queries_get_comm_and_pids.sql b/startop/scripts/trace_analyzer/queries_get_comm_and_pids.sql
new file mode 100644
index 000000000000..0c166b09784c
--- /dev/null
+++ b/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;
diff --git a/startop/scripts/trace_analyzer/queries_get_procs.sql b/startop/scripts/trace_analyzer/queries_get_procs.sql
new file mode 100644
index 000000000000..06871c6e16b6
--- /dev/null
+++ b/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;
diff --git a/startop/scripts/trace_analyzer/queries_get_ui_threads.sql b/startop/scripts/trace_analyzer/queries_get_ui_threads.sql
new file mode 100644
index 000000000000..876e50e9880a
--- /dev/null
+++ b/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;
diff --git a/startop/scripts/trace_analyzer/queries_mark_write_join.sql b/startop/scripts/trace_analyzer/queries_mark_write_join.sql
new file mode 100644
index 000000000000..100f07403423
--- /dev/null
+++ b/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;
diff --git a/startop/scripts/trace_analyzer/queries_pretty_print_block_launch.sql b/startop/scripts/trace_analyzer/queries_pretty_print_block_launch.sql
new file mode 100644
index 000000000000..bf5e3ccb4ac7
--- /dev/null
+++ b/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
+
+*/
diff --git a/startop/scripts/trace_analyzer/run-sql-queries b/startop/scripts/trace_analyzer/run-sql-queries
new file mode 100755
index 000000000000..61a0ad42a339
--- /dev/null
+++ b/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"
diff --git a/startop/scripts/trace_analyzer/trace_analyzer b/startop/scripts/trace_analyzer/trace_analyzer
new file mode 100755
index 000000000000..8c0396430c40
--- /dev/null
+++ b/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
diff --git a/startop/scripts/trace_analyzer/trace_analyzer.py b/startop/scripts/trace_analyzer/trace_analyzer.py
new file mode 100755
index 000000000000..45429339bea6
--- /dev/null
+++ b/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)
diff --git a/startop/scripts/trace_analyzer/trace_analyzer_recursive b/startop/scripts/trace_analyzer/trace_analyzer_recursive
new file mode 100755
index 000000000000..4d9ee0eec9b0
--- /dev/null
+++ b/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"