New issue
Advanced search Search tips

Issue 811035 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Mar 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug

Blocking:
issue 651354



Sign in to add a comment

[TaskScheduler] Improve tracing visualization of tasks and worker activity

Project Member Reported by gab@chromium.org, Feb 10 2018

Issue description

A few tracing improvements in mind:

1) Highlight when worker threads are active (currently topmost event is "RunTask") to help identify whether TaskScheduler or kernel is at fault when a thread appears ready and isn't picking up a task.

2) Fix toplevel.flow for TaskScheduler tasks, it's currently completely borked.

3) Should probably move task scheduler task flows to task_scheduler.flow (way too much stuff on toplevel.flow and it makes massive traces which are slow to render and navigate, e.g. bundled with net,ipc,mojo,etc.).

4) Bonus: Beyond scope of TaskScheduler but would be nice if tracing had a way to highlight dead threads. Currently on long traces in can look like there are way too many TaskScheduler workers when in fact it's just because some threads were reclaimed per idleness and later recreated with new IDs per a surge of new work (tracing has one line per thread ID ever to be alive and doesn't highlight dead threads).
 

Comment 1 by gab@chromium.org, Feb 12 2018

Here's a screenshot where it's unclear why a worker isn't running, adding a trace event when the scheduler is doing anything at all but intentionally sleeping will be useful to determine who's at fault.
parallel_scavenge_tasks_poor_latency.png
132 KB View Download

Comment 2 by gab@chromium.org, Feb 12 2018

Blocking: 651354

Comment 3 by gab@chromium.org, Feb 12 2018

Summary: [TaskScheduler] Improve tracing visualization of tasks and worker activity (was: [TaskScheduler] Add tracing visualization of inactive (idle/reclaimed) workers)
Broadening the scope of this issue.

Comment 4 by dskiba@chromium.org, Feb 12 2018

Cc: dskiba@chromium.org

Comment 5 by gab@chromium.org, Feb 12 2018

Status: Started (was: Assigned)

Comment 6 by gab@chromium.org, Feb 12 2018

Description: Show this description

Comment 7 by gab@chromium.org, Feb 12 2018

Here's what fixed toplevel.flow for TaskScheduler tasks looks like :)
TaskScheduler_flow_events.png
238 KB View Download

Comment 8 by fdoray@chromium.org, Feb 12 2018

> 4) Bonus: Beyond scope of TaskScheduler but would be nice if tracing had a way to highlight dead threads.
> Currently on long traces in can look like there are way too many TaskScheduler workers when in fact it's
> just because some threads were reclaimed per idleness and later recreated with new IDs per a surge of
> new work (tracing has one line per thread ID ever to be alive and doesn't highlight dead threads).

A efficient way to use available space would be to allow a new TaskScheduler thread to reuse the row of a dead TaskScheduler thread in the same pool. Example:

TaskSchedulerForegroundWorker  ============ [Dead] 
TaskSchedulerForegroundWorker                      [Born] ==========

Becomes:

TaskSchedulerForegroundWorker  ============ [Dead] [Born] ==========
Project Member

Comment 9 by bugdroid1@chromium.org, Feb 12 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/d641a6adecc1dddf67823f2b424b6ebac79bce02

commit d641a6adecc1dddf67823f2b424b6ebac79bce02
Author: Gabriel Charette <gab@chromium.org>
Date: Mon Feb 12 20:42:01 2018

Add a trace event when a task scheduler worker is active.

Example trace with this enabled: https://drive.google.com/file/d/11si1qvQUhRi1jMPNTzgJpqp3D-yFKOf7/view?usp=sharing

Also fix a racy setup order in MemoryDumpManagerTest exercised by this change.

R=fdoray@chromium.org

Bug:  811035 
Change-Id: I328dca43f7b5bfd42bcf1a69b1e191fe41523ade
Reviewed-on: https://chromium-review.googlesource.com/913251
Reviewed-by: François Doray <fdoray@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#536177}
[modify] https://crrev.com/d641a6adecc1dddf67823f2b424b6ebac79bce02/base/task_scheduler/scheduler_worker.cc
[modify] https://crrev.com/d641a6adecc1dddf67823f2b424b6ebac79bce02/base/trace_event/memory_dump_manager_unittest.cc

Project Member

Comment 10 by bugdroid1@chromium.org, Feb 13 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/afeefc5f0138cda1aa5f1f87e67876dbebcdf7f2

commit afeefc5f0138cda1aa5f1f87e67876dbebcdf7f2
Author: Hajime Hoshi <hajimehoshi@chromium.org>
Date: Tue Feb 13 04:10:31 2018

Revert "Add a trace event when a task scheduler worker is active."

This reverts commit d641a6adecc1dddf67823f2b424b6ebac79bce02.

Reason for revert: This CL causes TSan failures:  crbug.com/811482 

Original change's description:
> Add a trace event when a task scheduler worker is active.
> 
> Example trace with this enabled: https://drive.google.com/file/d/11si1qvQUhRi1jMPNTzgJpqp3D-yFKOf7/view?usp=sharing
> 
> Also fix a racy setup order in MemoryDumpManagerTest exercised by this change.
> 
> R=​fdoray@chromium.org
> 
> Bug:  811035 
> Change-Id: I328dca43f7b5bfd42bcf1a69b1e191fe41523ade
> Reviewed-on: https://chromium-review.googlesource.com/913251
> Reviewed-by: François Doray <fdoray@chromium.org>
> Commit-Queue: Gabriel Charette <gab@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#536177}

TBR=gab@chromium.org,primiano@chromium.org,fdoray@chromium.org

Change-Id: I6372620c5cff7b04d44be9909f3123436ee6019c
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug:  811035 
Reviewed-on: https://chromium-review.googlesource.com/915581
Reviewed-by: Hajime Hoshi <hajimehoshi@chromium.org>
Commit-Queue: Hajime Hoshi <hajimehoshi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#536256}
[modify] https://crrev.com/afeefc5f0138cda1aa5f1f87e67876dbebcdf7f2/base/task_scheduler/scheduler_worker.cc
[modify] https://crrev.com/afeefc5f0138cda1aa5f1f87e67876dbebcdf7f2/base/trace_event/memory_dump_manager_unittest.cc

Project Member

Comment 11 by bugdroid1@chromium.org, Feb 13 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/153eb02201c6bf2eca3eaa26d69de52eba60bc19

commit 153eb02201c6bf2eca3eaa26d69de52eba60bc19
Author: Gabriel Charette <gab@chromium.org>
Date: Tue Feb 13 09:01:04 2018

Fix toplevel.flow for TaskScheduler tasks.

First TaskTracker wasn't even using a fixed TaskAnnotator instance.

Second, it turns out that TaskAnnotator depends on a unique
|sequence_num| but TaskScheduler doesn't use nor set
PendingTask::sequence_num. While this is unfortunate and a bit of an
overreaching assumption, TaskScheduler is the only task system where
this isn't true. Thus, it's not worthwhile to refactor how this is
done at this time. This CL makes this assumption true for TaskScheduler
tasks when tracing is active.

Third, it appears there's a bug in TaskAnnotator/TRACE_ID_MANGLE
where the IDs aren't cross-process unique as they intend to be. This
occasionally still results in weird flow artifacts despite fixing the
above issues. Will address this independently.
Discussion @ https://groups.google.com/a/chromium.org/d/topic/benchmarking-dev/y_cK75SrevE/discussion

Example trace with this CL @  crbug.com/811035#c7 

R=fdoray@chromium.org

Bug:  811035 
Change-Id: I77f3ace2eca2b07f1e74f7f79cb35f6d8077931c
Reviewed-on: https://chromium-review.googlesource.com/913950
Commit-Queue: Gabriel Charette <gab@chromium.org>
Reviewed-by: François Doray <fdoray@chromium.org>
Cr-Commit-Position: refs/heads/master@{#536300}
[modify] https://crrev.com/153eb02201c6bf2eca3eaa26d69de52eba60bc19/base/task_scheduler/task.cc
[modify] https://crrev.com/153eb02201c6bf2eca3eaa26d69de52eba60bc19/base/task_scheduler/task_tracker.cc
[modify] https://crrev.com/153eb02201c6bf2eca3eaa26d69de52eba60bc19/base/task_scheduler/task_tracker.h

Project Member

Comment 12 by bugdroid1@chromium.org, Feb 13 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/8c1fb16b6c55d7fbce3f2c90b56b70e6966b2290

commit 8c1fb16b6c55d7fbce3f2c90b56b70e6966b2290
Author: Gabriel Charette <gab@chromium.org>
Date: Tue Feb 13 10:24:06 2018

Reland "Add a trace event when a task scheduler worker is active."

This is a reland of d641a6adecc1dddf67823f2b424b6ebac79bce02.

It was reverted per causing data races in MemoryDumpManagerTests
as they re-initialized the MemoryDumpManager instance after scheduler
workers had been brought up (and the workers using tracing prior to
receiving a task -- which previously acted as a sync point -- is
now highlighting this initialization race).

Original change's description:
> Add a trace event when a task scheduler worker is active.
>
> Example trace with this enabled: https://drive.google.com/file/d/11si1qvQUhRi1jMPNTzgJpqp3D-yFKOf7/view?usp=sharing
>
> Also fix a racy setup order in MemoryDumpManagerTest exercised by this change.
>
> R=fdoray@chromium.org
>
> Bug:  811035 
> Change-Id: I328dca43f7b5bfd42bcf1a69b1e191fe41523ade
> Reviewed-on: https://chromium-review.googlesource.com/913251
> Reviewed-by: François Doray <fdoray@chromium.org>
> Commit-Queue: Gabriel Charette <gab@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#536177}

Bug:  811035 ,  811482 
Change-Id: If3a7b1dbfa8d50cec97b7b98e88c68f26f9813ec

TBR=fdoray@chromium.org

Change-Id: If3a7b1dbfa8d50cec97b7b98e88c68f26f9813ec
Reviewed-on: https://chromium-review.googlesource.com/915941
Reviewed-by: Primiano Tucci <primiano@chromium.org>
Commit-Queue: Primiano Tucci <primiano@chromium.org>
Cr-Commit-Position: refs/heads/master@{#536322}
[modify] https://crrev.com/8c1fb16b6c55d7fbce3f2c90b56b70e6966b2290/base/task_scheduler/scheduler_worker.cc
[modify] https://crrev.com/8c1fb16b6c55d7fbce3f2c90b56b70e6966b2290/base/trace_event/memory_dump_manager_unittest.cc

Project Member

Comment 13 by bugdroid1@chromium.org, Mar 1 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/77a419e11de9f4b92a9123cc12a07bc4692e4544

commit 77a419e11de9f4b92a9123cc12a07bc4692e4544
Author: Gabriel Charette <gab@chromium.org>
Date: Thu Mar 01 12:47:58 2018

Introduce task_scheduler.flow category.

This extracts task_scheduler.flow from toplevel.flow. toplevel.flow has
way too many events at the moment and is essentially unusable (results
in massive traces which are slow to visualize).

Unfortunately the tracing macros result in a static variable
that assumes the category never changes (INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO).
As such the code in task_annotator.cc cannot be reused to log events
to a provided category. Instead TaskAnnotator now supports nullptr to
disable trace events and TaskScheduler adds its own trace flow events.

Bonus: restricted the scope of the TRACE_EVENT_FLAG_FLOW_IN events
such that the event "receiving the task" precedes TaskAnnotator::RunTask
instead of overlapping with it. This will make flow arrows line up
nicer.

R=fdoray@chromium.org, primiano@chromium.org

Bug:  811035 
Change-Id: I1b4042c225486df0caf6c242f1f111291b2a1101
Reviewed-on: https://chromium-review.googlesource.com/939177
Reviewed-by: François Doray <fdoray@chromium.org>
Reviewed-by: Robert Liao <robliao@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#540135}
[modify] https://crrev.com/77a419e11de9f4b92a9123cc12a07bc4692e4544/base/debug/task_annotator.cc
[modify] https://crrev.com/77a419e11de9f4b92a9123cc12a07bc4692e4544/base/debug/task_annotator.h
[modify] https://crrev.com/77a419e11de9f4b92a9123cc12a07bc4692e4544/base/task_scheduler/task_tracker.cc

Comment 14 by gab@chromium.org, Mar 21 2018

Status: Fixed (was: Started)
1+2+3 fixed.

Sign in to add a comment