New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.
Starred by 3 users

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 1
Type: Bug



Sign in to add a comment
link

Issue 909728: Trace viewer creates weird visualization when async trace events are involved

Reported by mlippautz@chromium.org, Nov 28 Project Member

Issue description

I don't know whether this is an issue with trace viewer or Perfetto, or on which level of the stack the actual problem is. That said, the trace that is visualized differs with and without Perfetto. Please re-assign if I got the area wrong.

What happens:
- V8 uses sync trace events
- Blink starts and ends an async trace event from within sync V8 trace events.

In the old world, the trace viewer would just overlap the events, which still keeps nesting in a sane state.

In the Perfetto world, the sync event gets extended (?) creating the illusion of a nested event. The async event is also dropped.

See the attached example of how things are visualized.

(I tested this by disabling Perfetto through tools/perf/core/perf_benchmark.py)
 
Perfetto trace viewer.pdf
17.9 KB Download

Comment 1 by bugdroid1@chromium.org, Nov 29

Project Member
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/53e8b2a294d66219b5c4daf00dda1cb9f822a54f

commit 53e8b2a294d66219b5c4daf00dda1cb9f822a54f
Author: Oystein Eftevaag <oysteine@google.com>
Date: Thu Nov 29 21:32:46 2018

Perfetto: Stop splitting _COMPLETE events

The current Perfetto backend splits _COMPLETE trace events into
separate _BEGIN and _END pairs, as it's not very feasible to modify
existing events after they're written into the Shared Memory Buffers.

This is causing some issues with the trace-viewer which has some
assumptions about the ordering of begin/end events vs. async events,
and is also bloating the sizes of traces and adding extra
overhead for the perf infra.

Instead, we now keep the _COMPLETE events in an internal stack in
TLS and only emit them when we have their duration.

R=eseckler@chromium.org,skyostil@chromium.org

Bug: 909728, 888558 
Change-Id: I80e37264de66d8bbcb6c9095d21047957fd6eb9f
Reviewed-on: https://chromium-review.googlesource.com/c/1354503
Commit-Queue: oysteine <oysteine@chromium.org>
Reviewed-by: Eric Seckler <eseckler@chromium.org>
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Cr-Commit-Position: refs/heads/master@{#612360}
[modify] https://crrev.com/53e8b2a294d66219b5c4daf00dda1cb9f822a54f/base/trace_event/trace_log.cc
[modify] https://crrev.com/53e8b2a294d66219b5c4daf00dda1cb9f822a54f/base/trace_event/trace_log.h
[modify] https://crrev.com/53e8b2a294d66219b5c4daf00dda1cb9f822a54f/base/trace_event/traced_value.cc
[modify] https://crrev.com/53e8b2a294d66219b5c4daf00dda1cb9f822a54f/services/tracing/public/cpp/perfetto/trace_event_data_source.cc
[modify] https://crrev.com/53e8b2a294d66219b5c4daf00dda1cb9f822a54f/services/tracing/public/cpp/perfetto/trace_event_data_source.h
[modify] https://crrev.com/53e8b2a294d66219b5c4daf00dda1cb9f822a54f/services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc

Comment 2 by oysteine@chromium.org, Nov 30

mlippautz: Can you confirm this looks normal again?

Comment 3 by bugdroid1@chromium.org, Nov 30

Project Member
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/6a796b426b1ff987c8e4fd63d838731bcfd50d54

commit 6a796b426b1ff987c8e4fd63d838731bcfd50d54
Author: oysteine <oysteine@chromium.org>
Date: Fri Nov 30 20:55:56 2018

Revert "Perfetto: Stop splitting _COMPLETE events"

This reverts commit 53e8b2a294d66219b5c4daf00dda1cb9f822a54f.

Reason for revert:  crbug.com/910704 

Original change's description:
> Perfetto: Stop splitting _COMPLETE events
> 
> The current Perfetto backend splits _COMPLETE trace events into
> separate _BEGIN and _END pairs, as it's not very feasible to modify
> existing events after they're written into the Shared Memory Buffers.
> 
> This is causing some issues with the trace-viewer which has some
> assumptions about the ordering of begin/end events vs. async events,
> and is also bloating the sizes of traces and adding extra
> overhead for the perf infra.
> 
> Instead, we now keep the _COMPLETE events in an internal stack in
> TLS and only emit them when we have their duration.
> 
> R=​eseckler@chromium.org,skyostil@chromium.org
> 
> Bug: 909728, 888558 
> Change-Id: I80e37264de66d8bbcb6c9095d21047957fd6eb9f
> Reviewed-on: https://chromium-review.googlesource.com/c/1354503
> Commit-Queue: oysteine <oysteine@chromium.org>
> Reviewed-by: Eric Seckler <eseckler@chromium.org>
> Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#612360}

TBR=oysteine@chromium.org,skyostil@chromium.org,eseckler@chromium.org

Change-Id: I0cda9ab36248042c3889d810bfd07a6d03a6d58e
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug: 909728,  888558 
Reviewed-on: https://chromium-review.googlesource.com/c/1357500
Reviewed-by: oysteine <oysteine@chromium.org>
Commit-Queue: oysteine <oysteine@chromium.org>
Cr-Commit-Position: refs/heads/master@{#612776}
[modify] https://crrev.com/6a796b426b1ff987c8e4fd63d838731bcfd50d54/base/trace_event/trace_log.cc
[modify] https://crrev.com/6a796b426b1ff987c8e4fd63d838731bcfd50d54/base/trace_event/trace_log.h
[modify] https://crrev.com/6a796b426b1ff987c8e4fd63d838731bcfd50d54/base/trace_event/traced_value.cc
[modify] https://crrev.com/6a796b426b1ff987c8e4fd63d838731bcfd50d54/services/tracing/public/cpp/perfetto/trace_event_data_source.cc
[modify] https://crrev.com/6a796b426b1ff987c8e4fd63d838731bcfd50d54/services/tracing/public/cpp/perfetto/trace_event_data_source.h
[modify] https://crrev.com/6a796b426b1ff987c8e4fd63d838731bcfd50d54/services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc

Comment 4 by bugdroid1@chromium.org, Dec 7

Project Member
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/9d830c214cd1c59958ee19403b446fa5b796e794

commit 9d830c214cd1c59958ee19403b446fa5b796e794
Author: Oystein Eftevaag <oysteine@google.com>
Date: Fri Dec 07 01:16:41 2018

Reland "Perfetto: Stop splitting _COMPLETE events"

This is a reland of 53e8b2a294d66219b5c4daf00dda1cb9f822a54f

Relanding after https://chromium-review.googlesource.com/c/catapult/+/1364251
which is what caused the failures triggering the revert last time.

Original change's description:
> Perfetto: Stop splitting _COMPLETE events
>
> The current Perfetto backend splits _COMPLETE trace events into
> separate _BEGIN and _END pairs, as it's not very feasible to modify
> existing events after they're written into the Shared Memory Buffers.
>
> This is causing some issues with the trace-viewer which has some
> assumptions about the ordering of begin/end events vs. async events,
> and is also bloating the sizes of traces and adding extra
> overhead for the perf infra.
>
> Instead, we now keep the _COMPLETE events in an internal stack in
> TLS and only emit them when we have their duration.
>
TBR=eseckler@chromium.org,skyostil@chromium.org
>
> Bug: 909728, 888558 
> Change-Id: I80e37264de66d8bbcb6c9095d21047957fd6eb9f
> Reviewed-on: https://chromium-review.googlesource.com/c/1354503
> Commit-Queue: oysteine <oysteine@chromium.org>
> Reviewed-by: Eric Seckler <eseckler@chromium.org>
> Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#612360}

Bug: 909728,  888558 
Change-Id: I5e3d6e0f170066011e2a5b452969d9c8cd18ac4f
Reviewed-on: https://chromium-review.googlesource.com/c/1359304
Reviewed-by: oysteine <oysteine@chromium.org>
Commit-Queue: oysteine <oysteine@chromium.org>
Cr-Commit-Position: refs/heads/master@{#614540}
[modify] https://crrev.com/9d830c214cd1c59958ee19403b446fa5b796e794/base/trace_event/trace_log.cc
[modify] https://crrev.com/9d830c214cd1c59958ee19403b446fa5b796e794/base/trace_event/trace_log.h
[modify] https://crrev.com/9d830c214cd1c59958ee19403b446fa5b796e794/base/trace_event/traced_value.cc
[modify] https://crrev.com/9d830c214cd1c59958ee19403b446fa5b796e794/services/tracing/public/cpp/perfetto/trace_event_data_source.cc
[modify] https://crrev.com/9d830c214cd1c59958ee19403b446fa5b796e794/services/tracing/public/cpp/perfetto/trace_event_data_source.h
[modify] https://crrev.com/9d830c214cd1c59958ee19403b446fa5b796e794/services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc

Sign in to add a comment