Improve CPU time accuracy by using thread_slice.
Previously we were performing multiple joins with the counter table, afterwards we get the data pre-joined by trace processor. This improves speed as well as accuracy since we know which slice generated which CPU timestamp.
Bug: 209995826
Change-Id: I4cd60421ccc351f1babe2d8a16164ba333312b0e
Testing: tools/diff_test_trace_processor.py out/android/trace_processor_shell
[==========] 287 tests ran. (535925 ms total)
[ PASSED ] 287 tests
diff --git a/Android.bp b/Android.bp
index 8edaabb..90df1e7 100644
--- a/Android.bp
+++ b/Android.bp
@@ -8204,7 +8204,7 @@
"src/trace_processor/metrics/sql/chrome/actual_power_by_rail_mode.sql",
"src/trace_processor/metrics/sql/chrome/chrome_event_metadata.sql",
"src/trace_processor/metrics/sql/chrome/chrome_processes.sql",
- "src/trace_processor/metrics/sql/chrome/chrome_thread_slice_with_cpu_time.sql",
+ "src/trace_processor/metrics/sql/chrome/chrome_thread_slice.sql",
"src/trace_processor/metrics/sql/chrome/cpu_time_by_category.sql",
"src/trace_processor/metrics/sql/chrome/cpu_time_by_rail_mode.sql",
"src/trace_processor/metrics/sql/chrome/estimated_power_by_category.sql",
diff --git a/BUILD b/BUILD
index 31ba472..bd2a35f 100644
--- a/BUILD
+++ b/BUILD
@@ -1097,7 +1097,7 @@
"src/trace_processor/metrics/sql/chrome/actual_power_by_rail_mode.sql",
"src/trace_processor/metrics/sql/chrome/chrome_event_metadata.sql",
"src/trace_processor/metrics/sql/chrome/chrome_processes.sql",
- "src/trace_processor/metrics/sql/chrome/chrome_thread_slice_with_cpu_time.sql",
+ "src/trace_processor/metrics/sql/chrome/chrome_thread_slice.sql",
"src/trace_processor/metrics/sql/chrome/cpu_time_by_category.sql",
"src/trace_processor/metrics/sql/chrome/cpu_time_by_rail_mode.sql",
"src/trace_processor/metrics/sql/chrome/estimated_power_by_category.sql",
diff --git a/src/trace_processor/metrics/sql/BUILD.gn b/src/trace_processor/metrics/sql/BUILD.gn
index c2b3592..3cb5831 100644
--- a/src/trace_processor/metrics/sql/BUILD.gn
+++ b/src/trace_processor/metrics/sql/BUILD.gn
@@ -80,7 +80,7 @@
"chrome/actual_power_by_rail_mode.sql",
"chrome/chrome_event_metadata.sql",
"chrome/chrome_processes.sql",
- "chrome/chrome_thread_slice_with_cpu_time.sql",
+ "chrome/chrome_thread_slice.sql",
"chrome/cpu_time_by_category.sql",
"chrome/cpu_time_by_rail_mode.sql",
"chrome/estimated_power_by_category.sql",
diff --git a/src/trace_processor/metrics/sql/chrome/chrome_thread_slice.sql b/src/trace_processor/metrics/sql/chrome/chrome_thread_slice.sql
new file mode 100644
index 0000000..273d3e7
--- /dev/null
+++ b/src/trace_processor/metrics/sql/chrome/chrome_thread_slice.sql
@@ -0,0 +1,38 @@
+--
+-- Copyright 2021 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
+--
+-- https://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.
+--
+
+SELECT RUN_METRIC('chrome/chrome_processes.sql');
+
+-- Grab all the thread tracks which are found in chrome threads.
+DROP VIEW IF EXISTS chrome_track;
+CREATE VIEW chrome_track AS
+ SELECT
+ *
+ FROM thread_track
+ WHERE utid IN (SELECT utid FROM chrome_thread);
+
+-- From all the chrome thread tracks select all the slice details for thread
+-- slices.
+DROP VIEW IF EXISTS chrome_thread_slice;
+CREATE VIEW chrome_thread_slice AS
+ SELECT
+ thread_slice.*
+ FROM
+ thread_slice JOIN
+ chrome_track ON
+ chrome_track.id = thread_slice.track_id
+ WHERE
+ track_id in (SELECT id FROM chrome_track);
\ No newline at end of file
diff --git a/src/trace_processor/metrics/sql/chrome/chrome_thread_slice_with_cpu_time.sql b/src/trace_processor/metrics/sql/chrome/chrome_thread_slice_with_cpu_time.sql
deleted file mode 100644
index 4af0d45..0000000
--- a/src/trace_processor/metrics/sql/chrome/chrome_thread_slice_with_cpu_time.sql
+++ /dev/null
@@ -1,98 +0,0 @@
---
--- Copyright 2020 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
---
--- https://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.
---
-
-SELECT RUN_METRIC('chrome/chrome_processes.sql');
-
--- Grab all the thread tracks which are found in chrome threads.
-DROP VIEW IF EXISTS chrome_track;
-CREATE VIEW chrome_track AS
- SELECT
- *
- FROM thread_track
- WHERE utid IN (SELECT utid FROM chrome_thread);
-
--- From all the chrome thread tracks select all the slice details as well as
--- the utid of the track so we can join with counter table later.
-DROP VIEW IF EXISTS chrome_slice;
-CREATE VIEW chrome_slice AS
- SELECT
- slice.*,
- chrome_track.utid
- FROM
- slice JOIN
- chrome_track ON
- chrome_track.id = slice.track_id
- WHERE
- track_id in (SELECT id FROM chrome_track);
-
--- Using utid join the thread_counter_track to chrome thread slices. This allows
--- the filtering of the counter table to only counters associated to these
--- threads.
-DROP VIEW IF EXISTS chrome_slice_and_counter_track;
-CREATE VIEW chrome_slice_and_counter_track AS
- SELECT
- s.*,
- thread_counter_track.id as counter_track_id,
- thread_counter_track.name as counter_name
- FROM
- chrome_slice s JOIN
- thread_counter_track ON
- thread_counter_track.utid = s.utid AND
- thread_counter_track.name = "thread_time";
-
--- Join each slice with the recorded value at the beginning and the end, as
--- well as computing the total CPU time each slice took.
---
--- We use MIN and MAX inside because sometimes nested slices will have the exact
--- same timestamp and we need to select one, there is nothing tying a particular
--- counter value to which slice generated it so we always choose the minimum for
--- the start on ties and the maximum for ties on the end of the slice. This
--- means this is always an overestimate, but events being emitted at exactly the
--- same timestamp is relatively rare so shouldn't cause to much inflation.
-DROP VIEW IF EXISTS chrome_thread_slice_with_cpu_time;
-CREATE VIEW chrome_thread_slice_with_cpu_time AS
- SELECT
- end_cpu_time - start_cpu_time AS slice_cpu_time,
- *
- FROM (
- SELECT
- s.*,
- min_counter.start_cpu_time
- FROM
- chrome_slice_and_counter_track s LEFT JOIN (
- SELECT
- ts,
- track_id,
- MIN(value) AS start_cpu_time
- FROM counter
- GROUP BY 1, 2
- ) min_counter ON
- min_counter.ts = s.ts AND min_counter.track_id = s.counter_track_id
- ) min_and_slice LEFT JOIN (
- SELECT
- ts,
- track_id,
- MAX(value) AS end_cpu_time
- FROM counter
- GROUP BY 1, 2
- ) max_counter ON
- max_counter.ts =
- CASE WHEN min_and_slice.dur >= 0 THEN
- min_and_slice.ts + min_and_slice.dur
- ELSE
- min_and_slice.ts
- END AND
- max_counter.track_id = min_and_slice.counter_track_id;
diff --git a/src/trace_processor/metrics/sql/chrome/scroll_jank_cause_queuing_delay.sql b/src/trace_processor/metrics/sql/chrome/scroll_jank_cause_queuing_delay.sql
index a45ac79..d5424bd 100644
--- a/src/trace_processor/metrics/sql/chrome/scroll_jank_cause_queuing_delay.sql
+++ b/src/trace_processor/metrics/sql/chrome/scroll_jank_cause_queuing_delay.sql
@@ -13,7 +13,7 @@
-- See the License for the specific language governing permissions and
-- limitations under the License.
-SELECT RUN_METRIC('chrome/chrome_thread_slice_with_cpu_time.sql');
+SELECT RUN_METRIC('chrome/chrome_thread_slice.sql');
SELECT RUN_METRIC('chrome/scroll_flow_event_queuing_delay.sql');
-- See b/184134310 why we remove ThreadController active.
@@ -24,7 +24,7 @@
ancestor.id AS task_ancestor_id,
ancestor.name AS task_ancestor_name
FROM
- chrome_thread_slice_with_cpu_time AS slice LEFT JOIN
+ chrome_thread_slice AS slice LEFT JOIN
ancestor_slice(slice.id) as ancestor ON ancestor.id = slice.parent_id
WHERE
slice.name != "ThreadController active" AND
@@ -114,10 +114,11 @@
DROP TABLE IF EXISTS all_descendant_blocking_tasks_queuing_delay_with_cpu_time;
CREATE TABLE all_descendant_blocking_tasks_queuing_delay_with_cpu_time AS
SELECT
- cpu.slice_cpu_time AS descendant_slice_cpu_time,
- cpu.slice_cpu_time / descendant.slice_cpu_time AS descendant_cpu_percentage,
- cpu.slice_cpu_time /
- (descendant.slice_cpu_time /
+ cpu.thread_dur AS descendant_thread_dur,
+ CAST(cpu.thread_dur AS REAL) / descendant.thread_dur
+ AS descendant_cpu_percentage,
+ CAST(cpu.thread_dur AS REAL) /
+ (descendant.thread_dur /
(1 << (descendant.descendant_depth - 1))) > 0.5
AS descendant_cpu_time_above_relative_threshold,
descendant_dur / descendant.dur AS descendant_dur_percentage,
@@ -128,8 +129,8 @@
FROM
all_descendant_blocking_tasks_queuing_delay descendant LEFT JOIN (
SELECT
- id, slice_cpu_time
- FROM chrome_thread_slice_with_cpu_time
+ id, thread_dur
+ FROM chrome_thread_slice
) AS cpu ON
cpu.id = descendant.descendant_id;
@@ -237,11 +238,11 @@
END, "-") AS descendant_name,
GROUP_CONCAT(
CASE WHEN descendant_depth < invalid_depth OR descendant_major_slice THEN
- descendant_slice_cpu_time
+ descendant_thread_dur
ELSE
NULL
END
- , "-") AS descendant_slice_cpu_time,
+ , "-") AS descendant_thread_dur,
GROUP_CONCAT(
CASE WHEN descendant_depth < invalid_depth OR descendant_major_slice THEN
descendant_cpu_percentage
diff --git a/test/trace_processor/chrome/chrome_thread_slice.out b/test/trace_processor/chrome/chrome_thread_slice.out
new file mode 100644
index 0000000..e3ed290
--- /dev/null
+++ b/test/trace_processor/chrome/chrome_thread_slice.out
@@ -0,0 +1,7 @@
+
+"trace_id","dur","thread_dur"
+2734,25000,25000
+2734,1000,2000
+2734,2000,2000
+2734,258000,171000
+2734,1000,1000
diff --git a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.sql b/test/trace_processor/chrome/chrome_thread_slice.sql
similarity index 83%
rename from test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.sql
rename to test/trace_processor/chrome/chrome_thread_slice.sql
index 10857de..654f424 100644
--- a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.sql
+++ b/test/trace_processor/chrome/chrome_thread_slice.sql
@@ -14,16 +14,14 @@
-- limitations under the License.
--
-SELECT RUN_METRIC('chrome/chrome_thread_slice_with_cpu_time.sql')
+SELECT RUN_METRIC('chrome/chrome_thread_slice.sql')
AS suppress_query_output;
SELECT
EXTRACT_ARG(arg_set_id, 'chrome_latency_info.trace_id') AS trace_id,
dur,
- start_cpu_time,
- end_cpu_time,
- slice_cpu_time
-FROM chrome_thread_slice_with_cpu_time
+ thread_dur
+FROM chrome_thread_slice
WHERE
name = 'LatencyInfo.Flow' AND
EXTRACT_ARG(arg_set_id, 'chrome_latency_info.trace_id') = 2734;
diff --git a/test/trace_processor/chrome/chrome_thread_slice_repeated.out b/test/trace_processor/chrome/chrome_thread_slice_repeated.out
new file mode 100644
index 0000000..1efb2b1
--- /dev/null
+++ b/test/trace_processor/chrome/chrome_thread_slice_repeated.out
@@ -0,0 +1,9 @@
+
+"name","ts","dur","thread_dur"
+"event1_on_t1",1000,100,10000
+"event2_on_t1",2000,200,30000
+"event3_on_t1",2000,200,10000
+"event4_on_t1",4000,0,0
+"float_counter_on_t1",4300,0,"[NULL]"
+"float_counter_on_t1",4500,0,"[NULL]"
+"event1_on_t3",4000,100,5000
diff --git a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.sql b/test/trace_processor/chrome/chrome_thread_slice_repeated.sql
similarity index 81%
rename from test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.sql
rename to test/trace_processor/chrome/chrome_thread_slice_repeated.sql
index 4702b55..124d306 100644
--- a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.sql
+++ b/test/trace_processor/chrome/chrome_thread_slice_repeated.sql
@@ -14,14 +14,12 @@
-- limitations under the License.
--
-SELECT RUN_METRIC('chrome/chrome_thread_slice_with_cpu_time.sql')
+SELECT RUN_METRIC('chrome/chrome_thread_slice.sql')
AS suppress_query_output;
SELECT
name,
ts,
dur,
- start_cpu_time,
- end_cpu_time,
- slice_cpu_time
-FROM chrome_thread_slice_with_cpu_time
+ thread_dur
+FROM chrome_thread_slice
diff --git a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.out b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.out
deleted file mode 100644
index 92b2a6d..0000000
--- a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.out
+++ /dev/null
@@ -1,7 +0,0 @@
-
-"trace_id","dur","start_cpu_time","end_cpu_time","slice_cpu_time"
-2734,2000,3192921000.000000,3192923000.000000,2000.000000
-2734,258000,3192951000.000000,3193122000.000000,171000.000000
-2734,1000,3193009000.000000,3193010000.000000,1000.000000
-2734,25000,1579266000.000000,1579291000.000000,25000.000000
-2734,1000,1579284000.000000,1579286000.000000,2000.000000
diff --git a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.out b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.out
deleted file mode 100644
index 0794b25..0000000
--- a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.out
+++ /dev/null
@@ -1,9 +0,0 @@
-
-"name","ts","dur","start_cpu_time","end_cpu_time","slice_cpu_time"
-"event1_on_t1",1000,100,1000000.000000,1010000.000000,10000.000000
-"event2_on_t1",2000,200,2000000.000000,2030000.000000,30000.000000
-"event3_on_t1",2000,200,2000000.000000,2030000.000000,30000.000000
-"event4_on_t1",4000,0,2040000.000000,2040000.000000,0.000000
-"float_counter_on_t1",4300,0,"[NULL]","[NULL]","[NULL]"
-"float_counter_on_t1",4500,0,"[NULL]","[NULL]","[NULL]"
-"event1_on_t3",4000,100,10000.000000,15000.000000,5000.000000
diff --git a/test/trace_processor/chrome/index b/test/trace_processor/chrome/index
index 27f59ec..5b9cc73 100644
--- a/test/trace_processor/chrome/index
+++ b/test/trace_processor/chrome/index
@@ -12,8 +12,8 @@
../../data/chrome_scroll_without_vsync.pftrace scroll_flow_event_queuing_delay_general_validation.sql scroll_flow_event_general_validation.out
../../data/chrome_scroll_without_vsync.pftrace scroll_jank_cause_queuing_delay.sql scroll_jank_cause_queuing_delay.out
../../data/chrome_scroll_without_vsync.pftrace scroll_jank_cause_queuing_delay_general_validation.sql scroll_jank_cause_queuing_delay_general_validation.out
-../../data/chrome_scroll_without_vsync.pftrace chrome_thread_slice_with_cpu_time.sql chrome_thread_slice_with_cpu_time.out
-../track_event/track_event_counters.textproto chrome_thread_slice_with_cpu_time_repeated.sql chrome_thread_slice_with_cpu_time_repeated.out
+../../data/chrome_scroll_without_vsync.pftrace chrome_thread_slice.sql chrome_thread_slice.out
+../track_event/track_event_counters.textproto chrome_thread_slice_repeated.sql chrome_thread_slice_repeated.out
../../data/chrome_rendering_desktop.pftrace frame_times frame_times_metric.out
../../data/chrome_rendering_desktop.pftrace chrome_dropped_frames chrome_dropped_frames_metric.out
scroll_jank_mojo_simple_watcher.py scroll_jank_mojo_simple_watcher.sql scroll_jank_mojo_simple_watcher.out
