Add a query that will compute the CPU time per chrome thread slice.
This is limited to slices on chrome thread tracks where CPU time is
reported.
Bug: 162583133
Change-Id: Ib1e4715576b677498ce375b52580270077872947
diff --git a/Android.bp b/Android.bp
index ae97dd5..6004bc9 100644
--- a/Android.bp
+++ b/Android.bp
@@ -6931,6 +6931,7 @@
"src/trace_processor/metrics/android/span_view_stats.sql",
"src/trace_processor/metrics/android/unsymbolized_frames.sql",
"src/trace_processor/metrics/chrome/chrome_processes.sql",
+ "src/trace_processor/metrics/chrome/chrome_thread_slice_with_cpu_time.sql",
"src/trace_processor/metrics/chrome/scroll_flow_event.sql",
"src/trace_processor/metrics/chrome/scroll_flow_event_queuing_delay.sql",
"src/trace_processor/metrics/chrome/scroll_jank.sql",
diff --git a/BUILD b/BUILD
index 1df26df..760197f 100644
--- a/BUILD
+++ b/BUILD
@@ -807,6 +807,7 @@
"src/trace_processor/metrics/android/span_view_stats.sql",
"src/trace_processor/metrics/android/unsymbolized_frames.sql",
"src/trace_processor/metrics/chrome/chrome_processes.sql",
+ "src/trace_processor/metrics/chrome/chrome_thread_slice_with_cpu_time.sql",
"src/trace_processor/metrics/chrome/scroll_flow_event.sql",
"src/trace_processor/metrics/chrome/scroll_flow_event_queuing_delay.sql",
"src/trace_processor/metrics/chrome/scroll_jank.sql",
diff --git a/src/trace_processor/metrics/BUILD.gn b/src/trace_processor/metrics/BUILD.gn
index 5e3caa5..8fa723d 100644
--- a/src/trace_processor/metrics/BUILD.gn
+++ b/src/trace_processor/metrics/BUILD.gn
@@ -55,6 +55,7 @@
"android/global_counter_span_view.sql",
"android/unsymbolized_frames.sql",
"chrome/chrome_processes.sql",
+ "chrome/chrome_thread_slice_with_cpu_time.sql",
"chrome/scroll_jank.sql",
"chrome/scroll_jank_cause.sql",
"chrome/scroll_jank_cause_blocking_task.sql",
diff --git a/src/trace_processor/metrics/chrome/chrome_thread_slice_with_cpu_time.sql b/src/trace_processor/metrics/chrome/chrome_thread_slice_with_cpu_time.sql
new file mode 100644
index 0000000..02b0b83
--- /dev/null
+++ b/src/trace_processor/metrics/chrome/chrome_thread_slice_with_cpu_time.sql
@@ -0,0 +1,96 @@
+--
+-- 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
+ (
+ SELECT
+ MIN(value)
+ FROM counter
+ WHERE
+ counter.ts = s.ts AND
+ counter.track_id = s.counter_track_id
+ ) AS start_cpu_time,
+ (
+ SELECT
+ MAX(value)
+ FROM counter
+ WHERE
+ counter.ts =
+ CASE WHEN s.dur >= 0 THEN s.ts + s.dur ELSE s.ts END AND
+ counter.track_id = s.counter_track_id
+ ) AS end_cpu_time,
+ *
+ FROM
+ chrome_slice_and_counter_track s
+ );
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
new file mode 100644
index 0000000..92b2a6d
--- /dev/null
+++ b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.out
@@ -0,0 +1,7 @@
+
+"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.sql b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.sql
new file mode 100644
index 0000000..10857de
--- /dev/null
+++ b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time.sql
@@ -0,0 +1,29 @@
+--
+-- 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_thread_slice_with_cpu_time.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
+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_with_cpu_time_repeated.out b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.out
new file mode 100644
index 0000000..02820f0
--- /dev/null
+++ b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.out
@@ -0,0 +1,7 @@
+
+"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
+"event1_on_t3",4000,100,10000.000000,15000.000000,5000.000000
diff --git a/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.sql b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.sql
new file mode 100644
index 0000000..4702b55
--- /dev/null
+++ b/test/trace_processor/chrome/chrome_thread_slice_with_cpu_time_repeated.sql
@@ -0,0 +1,27 @@
+--
+-- 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_thread_slice_with_cpu_time.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
diff --git a/test/trace_processor/chrome/index b/test/trace_processor/chrome/index
index 5f84e43..a1d9c54 100644
--- a/test/trace_processor/chrome/index
+++ b/test/trace_processor/chrome/index
@@ -10,3 +10,5 @@
../../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
diff --git a/test/trace_processor/track_event/track_event_counters.textproto b/test/trace_processor/track_event/track_event_counters.textproto
index decdd68..1049fc9 100644
--- a/test/trace_processor/track_event/track_event_counters.textproto
+++ b/test/trace_processor/track_event/track_event_counters.textproto
@@ -28,7 +28,7 @@
uuid: 3
process {
pid: 5
- process_name: "p1"
+ process_name: "Browser"
}
}
}
@@ -116,7 +116,7 @@
uuid: 3
process {
pid: 5
- process_name: "p1"
+ process_name: "Browser"
}
}
}
@@ -130,7 +130,7 @@
parent_uuid: 1
counter {
type: 1 # COUNTER_THREAD_TIME_NS.
- unit_multiplier: 1000 # provided in ys.
+ unit_multiplier: 1000 # provided in us.
is_incremental: true # use delta encoding.
}
}
@@ -149,6 +149,20 @@
}
}
+# Nested value that happens to be emitted at the same timestamp but different
+# thread time value.
+packet {
+ trusted_packet_sequence_id: 1
+ sequence_flags: 2 # SEQ_NEEDS_INCREMENTAL_STATE
+ timestamp: 2000
+ track_event {
+ categories: "cat"
+ name: "event3_on_t1"
+ type: 1 # TYPE_SLICE_BEGIN.
+ extra_counter_values: 10 # Absolute: 2010
+ }
+}
+
# End for event above.
packet {
trusted_packet_sequence_id: 1
@@ -156,7 +170,18 @@
timestamp: 2200
track_event {
type: 2 # TYPE_SLICE_END.
- extra_counter_values: 10 # Absolute: 2010.
+ extra_counter_values: 10 # Absolute: 2020.
+ }
+}
+
+# End for event for "event2_on_t1".
+packet {
+ trusted_packet_sequence_id: 1
+ sequence_flags: 2 # SEQ_NEEDS_INCREMENTAL_STATE
+ timestamp: 2200
+ track_event {
+ type: 2 # TYPE_SLICE_END.
+ extra_counter_values: 10 # Absolute: 2030.
}
}
@@ -189,12 +214,12 @@
timestamp: 4000
track_event {
categories: "cat"
- name: "event3_on_t1"
+ name: "event4_on_t1"
type: 3 # TYPE_INSTANT.
extra_counter_track_uuids: 10 # "c1".
extra_counter_track_uuids: 11 # "MySizeCounter".
- extra_counter_values: 10 # Absolute: 2020.
- extra_counter_values: 1024 # Absolute: 2020.
+ extra_counter_values: 10 # Absolute: 2040.
+ extra_counter_values: 1024 # Absolute: 2040.
}
}
diff --git a/test/trace_processor/track_event/track_event_counters_counters.out b/test/trace_processor/track_event/track_event_counters_counters.out
index d5cc7b2..25b8dd0 100644
--- a/test/trace_processor/track_event/track_event_counters_counters.out
+++ b/test/trace_processor/track_event/track_event_counters_counters.out
@@ -1,13 +1,15 @@
"counter_name","process","thread","thread_process","unit","track_args","ts","value"
-"thread_time","[NULL]","t1","p1","ns",1,1000,1000000.000000
-"thread_time","[NULL]","t1","p1","ns",1,1100,1010000.000000
-"thread_time","[NULL]","t1","p1","ns",1,2000,2000000.000000
-"thread_time","[NULL]","t1","p1","ns",1,2200,2010000.000000
+"thread_time","[NULL]","t1","Browser","ns",1,1000,1000000.000000
+"thread_time","[NULL]","t1","Browser","ns",1,1100,1010000.000000
+"thread_time","[NULL]","t1","Browser","ns",1,2000,2000000.000000
+"thread_time","[NULL]","t1","Browser","ns",1,2000,2010000.000000
+"thread_time","[NULL]","t1","Browser","ns",1,2200,2020000.000000
+"thread_time","[NULL]","t1","Browser","ns",1,2200,2030000.000000
"MySizeCounter","[NULL]","[NULL]","[NULL]","bytes",2,3000,1024.000000
"MySizeCounter","[NULL]","[NULL]","[NULL]","bytes",2,3100,2048.000000
-"thread_time","[NULL]","t1","p1","ns",1,4000,2020000.000000
+"thread_time","[NULL]","t1","Browser","ns",1,4000,2040000.000000
"MySizeCounter","[NULL]","[NULL]","[NULL]","bytes",2,4000,1024.000000
-"thread_time","[NULL]","t4","p1","[NULL]","[NULL]",4000,10000.000000
-"thread_instruction_count","[NULL]","t4","p1","[NULL]","[NULL]",4000,20.000000
-"thread_time","[NULL]","t4","p1","[NULL]","[NULL]",4100,15000.000000
-"thread_instruction_count","[NULL]","t4","p1","[NULL]","[NULL]",4100,25.000000
+"thread_time","[NULL]","t4","Browser","[NULL]","[NULL]",4000,10000.000000
+"thread_instruction_count","[NULL]","t4","Browser","[NULL]","[NULL]",4000,20.000000
+"thread_time","[NULL]","t4","Browser","[NULL]","[NULL]",4100,15000.000000
+"thread_instruction_count","[NULL]","t4","Browser","[NULL]","[NULL]",4100,25.000000
diff --git a/test/trace_processor/track_event/track_event_counters_slices.out b/test/trace_processor/track_event/track_event_counters_slices.out
index f17c0b4..f07b511 100644
--- a/test/trace_processor/track_event/track_event_counters_slices.out
+++ b/test/trace_processor/track_event/track_event_counters_slices.out
@@ -1,5 +1,6 @@
"track","process","thread","thread_process","ts","dur","category","name","arg_set_id"
-"[NULL]","[NULL]","t1","p1",1000,100,"cat","event1_on_t1",0
-"[NULL]","[NULL]","t1","p1",2000,200,"cat","event2_on_t1",0
-"[NULL]","[NULL]","t1","p1",4000,0,"cat","event3_on_t1",0
-"[NULL]","[NULL]","t4","p1",4000,100,"cat","event1_on_t3",0
+"[NULL]","[NULL]","t1","Browser",1000,100,"cat","event1_on_t1",0
+"[NULL]","[NULL]","t1","Browser",2000,200,"cat","event2_on_t1",0
+"[NULL]","[NULL]","t1","Browser",2000,200,"cat","event3_on_t1",0
+"[NULL]","[NULL]","t1","Browser",4000,0,"cat","event4_on_t1",0
+"[NULL]","[NULL]","t4","Browser",4000,100,"cat","event1_on_t3",0