Long tasks: add a trace event for long tasks

Long tasks: add a trace event for long tasks

Add a trace event for long task entries, so this can be better surfaced in
devtools, traceviewer etc.

BUG=738752
Review-Url: https://codereview.chromium.org/2966073003
Cr-Commit-Position: refs/heads/master@{#486885}
Committed: https://chromium.googlesource.com/chromium/src/+/26a60c2908155fcba28a21b1065d21adbc39a1c6

[Liquan (Max) Gu, 2017-07-04 19:50:35]

The CQ bit was checked by maxlg@chromium.org

[Liquan (Max) Gu, 2017-07-04 19:50:35]

The CQ bit was unchecked by maxlg@chromium.org

[Liquan (Max) Gu, 2017-07-04 20:23:44]

maxlg@chromium.org changed reviewers:
+ panicker@chromium.org, tdresser@chromium.org

[Liquan (Max) Gu, 2017-07-04 20:23:45]

Which information do we need to log to the events?

[tdresser, 2017-07-04 20:37:58]

tdresser@chromium.org changed reviewers:
+ paulirish@chromium.org

[tdresser, 2017-07-04 20:37:59]

+paulirish@, for what devtools folks would want to surface here.

[tdresser, 2017-07-04 20:41:20]

Eventually, I'd like to see tests for all trace points which devtools is going
to consume.

It's super painful right now though - there's an example browsertest which
asserts on trace output here:
https://cs.chromium.org/chromium/src/content/browser/renderer_host/input/mous....

We could do something similar.

Alternatively, maybe we should invest in some tooling here at some point.

[Liquan (Max) Gu, 2017-07-07 17:49:18]

maxlg@chromium.org changed reviewers:
+ caseq@chromium.org

[Liquan (Max) Gu, 2017-07-07 17:49:19]

+caseq

Since Shuhbie said long task trace events should be created regardless of
subscription. I've moved it out into task_queue_manager. I guess it's the right
place to put it. PTAL.

[tdresser, 2017-07-07 17:51:31]

Looks like you added a few files accidentally.

Other than that, LGTM.

[Liquan (Max) Gu, 2017-07-07 18:04:38]

maxlg@chromium.org changed reviewers:
+ altimin@chromium.org

[Liquan (Max) Gu, 2017-07-07 18:04:39]

+altimin

Please take a look at task_queue_manager. I am adding a trace event there.
Thanks!

[Liquan (Max) Gu, 2017-07-07 18:11:15]

maxlg@chromium.org changed reviewers:
+ dtapuska@chromium.org

[Liquan (Max) Gu, 2017-07-07 18:11:16]

+dtapuska for Performance.cpp. Because I created another threshold in
task_queue_manager, I am wondering whether I should change the name of the long
task threshold in performance.cpp to distinguish between their purposes.

[dtapuska, 2017-07-07 18:19:16]

On 2017/07/07 18:11:16, Liquan (Max) Gu wrote:
> +dtapuska for Performance.cpp. Because I created another threshold in
> task_queue_manager, I am wondering whether I should change the name of the
long
> task threshold in performance.cpp to distinguish between their purposes.

Performace.cpp lgtm

[altimin, 2017-07-07 18:24:16]

altimin@chromium.org changed reviewers:
+ primiano@chromium.org

[altimin, 2017-07-07 18:24:17]

+primiano@ as a tracing owner.

scheduler lgtm, but please get lgtm from primiano@ before submitting.

https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
File third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc
(right):

https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc:557:
TRACE_EVENT2("blink", "LongTask", "start_time", task_start_time, "end_time",
This will be shown in the UI as an extremely short event. This seems rather odd
and counterintuitive.

+primiano@ as a tracing owner — do we have better mechanisms that this?

[caseq, 2017-07-07 18:54:44]

https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
File third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc
(right):

https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc:557:
TRACE_EVENT2("blink", "LongTask", "start_time", task_start_time, "end_time",
On 2017/07/07 18:24:17, altimin wrote:
> This will be shown in the UI as an extremely short event. This seems rather
odd
> and counterintuitive.

+1 to this, I don't think it makes sense in the present form. One way to address
this would be to just emit an instant event, then use custom logic in the UI to
render the existing top-level event differently. Or, better, don't emit anything
at all and just have the logic entirely on the client side -- we already have
trace events for all tasks anyway.

[Primiano Tucci (use gerrit), 2017-07-07 18:59:29]

On 2017/07/07 18:54:44, caseq wrote:
>
https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
> File third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc
> (right):
> 
>
https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
> third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc:557:
> TRACE_EVENT2("blink", "LongTask", "start_time", task_start_time, "end_time",
> On 2017/07/07 18:24:17, altimin wrote:
> > This will be shown in the UI as an extremely short event. This seems rather
> odd
> > and counterintuitive.
> 
> +1 to this, I don't think it makes sense in the present form. One way to
address
> this would be to just emit an instant event, then use custom logic in the UI
to
> render the existing top-level event differently. Or, better, don't emit
anything
> at all and just have the logic entirely on the client side -- we already have
> trace events for all tasks anyway.

+1 to what caseq suggested. adding a trace event at the end seems very odd.
If you want you could add logic in the UI to turn this into some alert, Android
systrace (that shares the same UI) does that for long frames:
http://blog.udinic.com/assets/media/images/speed-up-your-app/systrace-overvie...

[Liquan (Max) Gu, 2017-07-07 20:01:25]

https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
File third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc
(right):

https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc:557:
TRACE_EVENT2("blink", "LongTask", "start_time", task_start_time, "end_time",
On 2017/07/07 18:54:44, caseq wrote:
> On 2017/07/07 18:24:17, altimin wrote:
> > This will be shown in the UI as an extremely short event. This seems rather
> odd
> > and counterintuitive.
> 
> +1 to this, I don't think it makes sense in the present form. One way to
address
> this would be to just emit an instant event, then use custom logic in the UI
to
> render the existing top-level event differently. Or, better, don't emit
anything
> at all and just have the logic entirely on the client side -- we already have
> trace events for all tasks anyway.

I have changed to emit an instant event. 

From the issue description, it intends to surface this signal to devtools as
well. If it's implemented on the client side, can it be surfaced to devtools.?

[caseq, 2017-07-07 21:01:54]

On 2017/07/07 20:01:25, Liquan (Max) Gu wrote:
>
https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
> File third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc
> (right):
> 
>
https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
> third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc:557:
> TRACE_EVENT2("blink", "LongTask", "start_time", task_start_time, "end_time",
> On 2017/07/07 18:54:44, caseq wrote:
> > On 2017/07/07 18:24:17, altimin wrote:
> > > This will be shown in the UI as an extremely short event. This seems
rather
> > odd
> > > and counterintuitive.
> > 
> > +1 to this, I don't think it makes sense in the present form. One way to
> address
> > this would be to just emit an instant event, then use custom logic in the UI
> to
> > render the existing top-level event differently. Or, better, don't emit
> anything
> > at all and just have the logic entirely on the client side -- we already
have
> > trace events for all tasks anyway.
> 
> I have changed to emit an instant event. 
> 
> From the issue description, it intends to surface this signal to devtools as
> well. If it's implemented on the client side, can it be surfaced to devtools.?

Sure, it just needs to be supported in the DevTools front-end. We already have
some logic that produces different warnings there, so adding more wouldn't be an
issue.

[panicker, 2017-07-11 21:17:55]

On 2017/07/07 21:01:54, caseq wrote:
> On 2017/07/07 20:01:25, Liquan (Max) Gu wrote:
> >
>
https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
> > File third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc
> > (right):
> > 
> >
>
https://codereview.chromium.org/2966073003/diff/40001/third_party/WebKit/Sour...
> > third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc:557:
> > TRACE_EVENT2("blink", "LongTask", "start_time", task_start_time, "end_time",
> > On 2017/07/07 18:54:44, caseq wrote:
> > > On 2017/07/07 18:24:17, altimin wrote:
> > > > This will be shown in the UI as an extremely short event. This seems
> rather
> > > odd
> > > > and counterintuitive.
> > > 
> > > +1 to this, I don't think it makes sense in the present form. One way to
> > address
> > > this would be to just emit an instant event, then use custom logic in the
UI
> > to
> > > render the existing top-level event differently. Or, better, don't emit
> > anything
> > > at all and just have the logic entirely on the client side -- we already
> have
> > > trace events for all tasks anyway.
> > 
> > I have changed to emit an instant event. 
> > 
> > From the issue description, it intends to surface this signal to devtools as
> > well. If it's implemented on the client side, can it be surfaced to
devtools.?
> 
> Sure, it just needs to be supported in the DevTools front-end. We already have
> some logic that produces different warnings there, so adding more wouldn't be
an
> issue.

Instant event SGTM.
It's useful to have have a quick and easy way to see long tasks in traces.
Ideally UI / client side feature will follow and make this unnecessary, but
until then - this is a useful signal.

[panicker, 2017-07-11 21:18:04]

lgtm

[caseq, 2017-07-11 21:19:27]

On 2017/07/11 21:17:55, panicker wrote:

> It's useful to have have a quick and easy way to see long tasks in traces.

Agree, but an instant event isn't something you can easily spot with the default
visualization.

[panicker, 2017-07-11 21:21:21]

On 2017/07/11 21:19:27, caseq wrote:
> On 2017/07/11 21:17:55, panicker wrote:
> 
> > It's useful to have have a quick and easy way to see long tasks in traces.
> 
> Agree, but an instant event isn't something you can easily spot with the
default
> visualization.

You can sweep a region and filter -- not super nice, but doable.

[panicker, 2017-07-11 21:30:59]

panicker@chromium.org changed reviewers:
+ fmeawad@chromium.org

[panicker, 2017-07-11 21:31:00]

+fmeawad suggested adding async event for the fill time slice, that would be
easier to visualize.

[fmeawad, 2017-07-11 22:06:06]

On 2017/07/11 21:31:00, panicker wrote:
> +fmeawad suggested adding async event for the fill time slice, that would be
> easier to visualize.

Another idea is to add an arg to the message loop event where the long task is
triggered for to indicate that this is a long task.

That might not work if we cannot add an arg to an existing complete event (vs.
Begin/End events).

[Liquan (Max) Gu, 2017-07-12 21:04:15]

On 2017/07/11 22:06:06, fmeawad wrote:
> On 2017/07/11 21:31:00, panicker wrote:
> > +fmeawad suggested adding async event for the fill time slice, that would be
> > easier to visualize.
> 
> Another idea is to add an arg to the message loop event where the long task is
> triggered for to indicate that this is a long task.
> 
> That might not work if we cannot add an arg to an existing complete event (vs.
> Begin/End events).

Why don't we just add an arg to TaskQueueManager::ProcessTaskFromWorkQueue if we
can add an arg to a complete event? I have digged into trace event a bit but
haven't found how we can  add arg to existing events. altimin@ could you suggest
about this?

[Liquan (Max) Gu, 2017-07-14 15:37:35]

The CQ bit was checked by maxlg@chromium.org

[Liquan (Max) Gu, 2017-07-14 15:37:36]

The patchset sent to the CQ was uploaded after l-g-t-m from
tdresser@chromium.org, altimin@chromium.org, dtapuska@chromium.org
Link to the patchset: https://codereview.chromium.org/2966073003/#ps60001
(title: "change to use event instant")

[commit-bot: I haz the power, 2017-07-14 15:37:44]

CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-07-14 15:40:32]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-07-14 15:40:34]

Try jobs failed on following builders:
  ios-simulator on master.tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/ios-simulator/bui...)

[Primiano Tucci (use gerrit), 2017-07-14 15:43:31]

FWIW TRACE_EVENT_INSTANT2 in the current PS4 LGTM (not an owner of anything it's
touching now though)

[Liquan (Max) Gu, 2017-07-14 17:32:03]

The CQ bit was checked by maxlg@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-07-14 17:32:14]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Liquan (Max) Gu, 2017-07-14 19:19:05]

I've changed to use duration as arg instead. It's because start_time and
end_time were not offset-ed by trace start, and the offset is a private value. 

So I switch to use the end time of the event and an arg duration, which are
adequate to locate the long task.

[Liquan (Max) Gu, 2017-07-14 19:20:18]

Patchset #6 (id:100001) has been deleted

[Liquan (Max) Gu, 2017-07-14 19:20:36]

The CQ bit was checked by maxlg@chromium.org

[Liquan (Max) Gu, 2017-07-14 19:20:36]

The patchset sent to the CQ was uploaded after l-g-t-m from
primiano@chromium.org, altimin@chromium.org, panicker@chromium.org,
dtapuska@chromium.org, tdresser@chromium.org
Link to the patchset: https://codereview.chromium.org/2966073003/#ps120001
(title: "use duration instead")

[commit-bot: I haz the power, 2017-07-14 19:20:51]

CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-07-14 21:04:45]

CQ is committing da patch.

Bot data: {"patchset_id": 120001, "attempt_start_ts": 1500060036398940,
"parent_rev": "c2a38810b2a997665d422d2a48b023aa35c87b7f", "commit_rev":
"26a60c2908155fcba28a21b1065d21adbc39a1c6"}

[commit-bot: I haz the power, 2017-07-14 21:05:03]

Description was changed from

==========
Long tasks: add a trace event for long tasks

Add a trace event for long task entries, so this can be better surfaced in
devtools, traceviewer etc.

BUG=738752
==========

to

==========
Long tasks: add a trace event for long tasks

Add a trace event for long task entries, so this can be better surfaced in
devtools, traceviewer etc.

BUG=738752

Review-Url: https://codereview.chromium.org/2966073003
Cr-Commit-Position: refs/heads/master@{#486885}
Committed:
https://chromium.googlesource.com/chromium/src/+/26a60c2908155fcba28a21b1065d...
==========

[commit-bot: I haz the power, 2017-07-14 21:05:07]

Committed patchset #6 (id:120001) as
https://chromium.googlesource.com/chromium/src/+/26a60c2908155fcba28a21b1065d...