diff options
author | Igor Murashkin <iam@google.com> | 2019-06-06 16:10:16 -0700 |
---|---|---|
committer | Igor Murashkin <iam@google.com> | 2019-06-10 22:17:13 +0000 |
commit | 0c65d1c5faac197630f919085fc690a716783303 (patch) | |
tree | 5a0a83ff437cdc95e9729a70984e1c59eab81b73 /startop/scripts/trace_analyzer | |
parent | 2cd5a231f9775c07e13312607260b338549e37b1 (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')
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" |