Add a new "restricted" metric name to reduce noise.
Currently our breakdown metric grabs trace event names and concatenates
them to form detailed names, but often trace events aren't informative
or they are optional and will break up our aggregation into different
rows.
This new restricted_metric_name is more opiniated about which trace
events to include. It always includes the top level slice name, and if
its a PostTask where it was posted from. After that it includes only one
additional trace event using a priority list of categories from the
descendant slices.
1) mojom
2) toplevel
3) java
If there is multiple for a given category the first is used.
If there is no matching categories for the descendants (if they have
any) we will append "UnknownEvent" to ensure un classified events don't
become super common.
The test has some UnknownEvents because its missing the toplevel
category which would normally make most events not be tagged as
UnknownEvents.
Bug: 209448519
Change-Id: I23210fc53337f0bd3a5650c95e9936a1143226be
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 d3762ef..23a9908 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
@@ -129,9 +129,15 @@
EXTRACT_ARG(descendant.arg_set_id,
"chrome_mojo_event_info.watcher_notify_interface_tag"),
NULL) || ")",
+ descendant.name || "(" ||
+ IIF(descendant.arg_set_id IS NOT NULL,
+ EXTRACT_ARG(descendant.arg_set_id,
+ "chrome_mojo_event_info.mojo_interface_tag"),
+ NULL) || ")",
descendant.name) AS descendant_name,
descendant.parent_id As descendant_parent_id,
descendant.depth AS descendant_depth,
+ descendant.category AS descendant_category,
base.*
FROM
blocking_tasks_queuing_delay base LEFT JOIN
@@ -225,6 +231,7 @@
track_id,
trace_id,
name,
+ category,
scroll_slice_id AS scroll_id,
scroll_ts,
scroll_dur,
@@ -277,12 +284,73 @@
ELSE
NULL
END
- , "-") AS descendant_cpu_time
+ , "-") AS descendant_cpu_time,
+ GROUP_CONCAT(
+ CASE WHEN descendant_category = "mojom" THEN
+ descendant_name
+ ELSE
+ NULL
+ END
+ , "-") AS mojom_name,
+ GROUP_CONCAT(
+ CASE WHEN
+ descendant_category = "toplevel" AND
+ descendant_name NOT GLOB "*ThreadController*" THEN
+ descendant_name
+ ELSE
+ NULL
+ END
+ , "-") AS toplevel_name,
+ GROUP_CONCAT(
+ CASE WHEN descendant_category = "Java" THEN
+ descendant_name
+ ELSE
+ NULL
+ END
+ , "-") AS java_name
FROM
blocking_tasks_queuing_delay_with_invalid_depth
- GROUP BY 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17
+ GROUP BY 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19
ORDER BY descendant_cpu_percentage DESC;
+
+SELECT CREATE_FUNCTION(
+ -- Function prototype: takes a '-' separated list of slice names (formed by
+ -- the GROUP_CONCAT above) and returns the first slice if any or NULL
+ -- otherwise.
+ 'GetFirstSliceNameOrNull(name STRING)',
+ -- Returns the first slice name or NULL
+ 'STRING',
+ -- Preforms the actual string modification, takes the either the whole string
+ -- if there is no '-' or up to the first '-'. SUBSTR returns NULL if $name is
+ -- NULL.
+ 'SELECT SUBSTR($name, 0,
+ CASE WHEN INSTR($name, "-") = 0 THEN
+ LENGTH($name)+1 ELSE
+ INSTR($name, "-")
+ END)'
+);
+
+SELECT CREATE_FUNCTION(
+ -- Function prototype: takes slice name, category and descendant_name and
+ -- determines if this event should be classified as unknown or not.
+ 'UnknownEventOrEmptyString(name STRING, cat STRING, has_descendant STRING)',
+ -- Returns either "-UnknownEvent" or "".
+ 'STRING',
+ -- If our current event has a posted from we consider it already categorized
+ -- even if we don't have events underneath it. If its java often we won't have
+ -- sub events, and finally if its a single event we just use its name there
+ -- isn't anything under to use so just leave it at that.
+ 'SELECT
+ CASE WHEN
+ $name = "ThreadControllerImpl::RunTask" OR
+ $cat = "Java" OR
+ $has_descendant IS NULL THEN
+ "" ELSE
+ "-UnknownEvent"
+ END'
+);
+
-- Create a common name for each "cause" based on the slice stack we found.
DROP VIEW IF EXISTS scroll_jank_cause_queuing_delay_temp;
CREATE VIEW scroll_jank_cause_queuing_delay_temp AS
@@ -292,7 +360,16 @@
ELSE
name
END || COALESCE("-" || descendant_name, "") AS location,
-
+ CASE WHEN name = "ThreadControllerImpl::RunTask" THEN
+ 'posted-from-' || function || '()-in-' || file
+ ELSE
+ name
+ END || COALESCE(
+ "-" || GetFirstSliceNameOrNull(mojom_name),
+ "-" || GetFirstSliceNameOrNull(toplevel_name),
+ "-" || GetFirstSliceNameOrNull(java_name),
+ UnknownEventOrEmptyString(name, category, descendant_name)
+ ) AS restricted_location,
base.*
FROM descendant_blocking_tasks_queuing_delay base;
@@ -307,10 +384,22 @@
WHERE NOT jank
GROUP BY 1;
+-- Again figure out the average time, but based on a more restricted set of
+-- trace events.
+DROP VIEW IF EXISTS scroll_jank_cause_queuing_delay_average_no_jank_time_restricted;
+CREATE VIEW scroll_jank_cause_queuing_delay_average_no_jank_time_restricted AS
+ SELECT
+ restricted_location,
+ AVG(dur_overlapping_ns) as avg_dur_overlapping_ns_restricted
+ FROM scroll_jank_cause_queuing_delay_temp
+ WHERE NOT jank
+ GROUP BY 1;
+
+
-- Join every row (jank and non-jank with the average non-jank time for the
-- given metric_name).
-DROP VIEW IF EXISTS scroll_jank_cause_queuing_delay;
-CREATE VIEW scroll_jank_cause_queuing_delay AS
+DROP VIEW IF EXISTS scroll_jank_cause_queuing_delay_unannotated;
+CREATE VIEW scroll_jank_cause_queuing_delay_unannotated AS
SELECT
base.*,
'InputLatency.LatencyInfo.Flow.QueuingDelay.' ||
@@ -321,4 +410,19 @@
FROM
scroll_jank_cause_queuing_delay_temp base LEFT JOIN
scroll_jank_cause_queuing_delay_average_no_jank_time avg_no_jank ON
- base.location = avg_no_jank.location;
\ No newline at end of file
+ base.location = avg_no_jank.location;
+
+-- Join in the restricted set of trace events average as well to form the final output.
+DROP VIEW IF EXISTS scroll_jank_cause_queuing_delay;
+CREATE VIEW scroll_jank_cause_queuing_delay AS
+ SELECT
+ base.*,
+ 'QueuingDelay.' ||
+ CASE WHEN jank THEN 'Jank' ELSE 'NoJank' END || '.BlockingTasksUs.' ||
+ base.restricted_location AS restricted_metric_name,
+ COALESCE(avg_no_jank.avg_dur_overlapping_ns_restricted, 0)
+ AS avg_no_jank_dur_overlapping_ns_restricted
+ FROM
+ scroll_jank_cause_queuing_delay_unannotated base LEFT JOIN
+ scroll_jank_cause_queuing_delay_average_no_jank_time_restricted avg_no_jank ON
+ base.restricted_location = avg_no_jank.restricted_location;
diff --git a/test/trace_processor/chrome/index b/test/trace_processor/chrome/index
index 5b9cc73..019067a 100644
--- a/test/trace_processor/chrome/index
+++ b/test/trace_processor/chrome/index
@@ -11,6 +11,7 @@
../../data/chrome_scroll_without_vsync.pftrace scroll_flow_event_queuing_delay.sql scroll_flow_event_queuing_delay.out
../../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_restricted.sql scroll_jank_cause_queuing_delay_restricted.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.sql chrome_thread_slice.out
../track_event/track_event_counters.textproto chrome_thread_slice_repeated.sql chrome_thread_slice_repeated.out
diff --git a/test/trace_processor/chrome/scroll_jank_cause_queuing_delay_restricted.out b/test/trace_processor/chrome/scroll_jank_cause_queuing_delay_restricted.out
new file mode 100644
index 0000000..4049795
--- /dev/null
+++ b/test/trace_processor/chrome/scroll_jank_cause_queuing_delay_restricted.out
@@ -0,0 +1,25 @@
+
+"process_name","thread_name","trace_id","jank","dur_overlapping_ns","restricted_metric_name"
+"Browser","CrProcessMain",2918,0,55000,"QueuingDelay.NoJank.BlockingTasksUs.GestureProvider::OnTouchEvent"
+"Browser","CrProcessMain",2918,0,433000,"QueuingDelay.NoJank.BlockingTasksUs.RenderWidgetHostImpl::ForwardTouchEvent-UnknownEvent"
+"Renderer","Compositor",2918,0,66000,"QueuingDelay.NoJank.BlockingTasksUs.WidgetInputHandlerImpl::DispatchNonBlockingEvent-UnknownEvent"
+"Renderer","Compositor",2918,0,116000,"QueuingDelay.NoJank.BlockingTasksUs.WidgetInputHandlerImpl::DispatchEvent-UnknownEvent"
+"Renderer","Compositor",2918,0,29000,"QueuingDelay.NoJank.BlockingTasksUs.WidgetInputHandlerImpl::DispatchNonBlockingEvent-UnknownEvent"
+"Renderer","Compositor",2918,0,7000,"QueuingDelay.NoJank.BlockingTasksUs.ScrollPredictor::ResampleScrollEvents"
+"Renderer","Compositor",2918,0,25000,"QueuingDelay.NoJank.BlockingTasksUs.InputHandlerProxy::HandleGestureScrollUpdate-UnknownEvent"
+"Renderer","Compositor",2918,0,6000,"QueuingDelay.NoJank.BlockingTasksUs.LatencyInfo.Flow"
+"Gpu","VizCompositorThread",2918,0,10000,"QueuingDelay.NoJank.BlockingTasksUs.LatencyInfo.Flow"
+"Browser","CrProcessMain",2926,1,52000,"QueuingDelay.Jank.BlockingTasksUs.InputRouterImpl::GestureEventHandled-UnknownEvent"
+"Browser","CrProcessMain",2926,1,17000,"QueuingDelay.Jank.BlockingTasksUs.GestureProvider::OnTouchEvent"
+"Renderer","Compositor",2926,1,1208,"QueuingDelay.Jank.BlockingTasksUs.WidgetInputHandlerImpl::DispatchNonBlockingEvent-UnknownEvent"
+"Renderer","Compositor",2926,1,38000,"QueuingDelay.Jank.BlockingTasksUs.WidgetInputHandlerImpl::DispatchNonBlockingEvent-UnknownEvent"
+"Renderer","Compositor",2926,1,21000,"QueuingDelay.Jank.BlockingTasksUs.WidgetInputHandlerImpl::DispatchEvent-UnknownEvent"
+"Renderer","Compositor",2926,1,6000,"QueuingDelay.Jank.BlockingTasksUs.ScrollPredictor::ResampleScrollEvents"
+"Renderer","Compositor",2926,1,30000,"QueuingDelay.Jank.BlockingTasksUs.InputHandlerProxy::HandleGestureScrollUpdate-UnknownEvent"
+"Renderer","Compositor",2926,1,14000,"QueuingDelay.Jank.BlockingTasksUs.WidgetInputHandlerManager::DidHandleInputEventSentToCompositor-UnknownEvent"
+"Gpu","VizCompositorThread",2926,1,2000,"QueuingDelay.Jank.BlockingTasksUs.LatencyInfo.Flow"
+"Gpu","VizCompositorThread",2926,1,5000,"QueuingDelay.Jank.BlockingTasksUs.LatencyInfo.Flow"
+"Gpu","VizCompositorThread",2926,1,8000,"QueuingDelay.Jank.BlockingTasksUs.LatencyInfo.Flow"
+"Gpu","VizCompositorThread",2926,1,2000,"QueuingDelay.Jank.BlockingTasksUs.LatencyInfo.Flow"
+"Gpu","VizCompositorThread",2926,1,8000,"QueuingDelay.Jank.BlockingTasksUs.LatencyInfo.Flow"
+"Gpu","VizCompositorThread",2926,1,2000,"QueuingDelay.Jank.BlockingTasksUs.LatencyInfo.Flow"
diff --git a/test/trace_processor/chrome/scroll_jank_cause_queuing_delay_restricted.sql b/test/trace_processor/chrome/scroll_jank_cause_queuing_delay_restricted.sql
new file mode 100644
index 0000000..7c8b59a
--- /dev/null
+++ b/test/trace_processor/chrome/scroll_jank_cause_queuing_delay_restricted.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/scroll_jank_cause_queuing_delay.sql')
+ AS suppress_query_output;
+
+SELECT
+ process_name,
+ thread_name,
+ trace_id,
+ jank,
+ dur_overlapping_ns,
+ restricted_metric_name
+FROM scroll_jank_cause_queuing_delay
+WHERE trace_id = 2918 OR trace_id = 2926
+ORDER BY trace_id ASC, ts ASC
