New issue
Advanced search Search tips

Issue 732975 link

Starred by 1 user

Issue metadata

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



Sign in to add a comment

Potential memory leak in TraceLog::AddTraceEventWithThreadIdAndTimestamp

Project Member Reported by erikc...@chromium.org, Jun 13 2017

Issue description

This code has changed recently but the gist is the same:
https://chromium-review.googlesource.com/c/513444/34/cc/surfaces/display_scheduler.cc

"""
void DisplayScheduler::SurfaceDamageExpected(const SurfaceId& surface_id,
                                             const BeginFrameArgs& args) {
  TRACE_EVENT1("cc", "DisplayScheduler::SurfaceDamageExpected", "surface_id",
               surface_id.ToString());
  auto it = surface_states_.find(surface_id);
  if (it == surface_states_.end())
    return;
  it->second.last_args = args;
  if (UpdateHasPendingSurfaces())
    ScheduleBeginFrameDeadline();
}
"""

Somehow, this leaks ~10k objects over the course of a week.
------------------------------------------------------------------

I've been looking at sources of browser memory bloat by using native heap profiling on my own browser. Full details:
https://docs.google.com/document/d/1fN5balfyrd7sRpd6DRaUI1TwoOwYjLyRSd7mwZT5US8/edit#

Over the course of 1 week, the browser process created ~10k objects in Tracelog that it did not destroy.

This is suggestive of a large leak. 

Each screenshot shows:
  1) # of objects created [that have not been destroyed]
  2) The stack trace of the code that created the object.
 
Screen Shot 2017-06-13 at 2.40.43 PM.png
208 KB View Download
Screen Shot 2017-06-13 at 2.40.52 PM.png
277 KB View Download
Screen Shot 2017-06-13 at 2.41.06 PM.png
324 KB View Download
Screen Shot 2017-06-13 at 2.41.19 PM.png
296 KB View Download

Comment 1 by ssid@chromium.org, Jun 13 2017

This sounds like somehow "cc" category was enabled in tracing and then never disabled. The category will only be enabled if somehow tracing was enabled on the session and if for some reason tracing stopped without disabling the category. I would guess that there was a bad tracing session running in background that caused this category to stay enabled. Not sure how. Do you see this behavior on different Chrome sessions?
- TRACE_EVENT1("cc", "DisplayScheduler::SurfaceDamageExpected", "surface_id", surface_id.ToString());
  This one itself seems legit. Note, surface_id.ToString() returns a std::string.
- If you expand the macros, this will ultimately reach into this expansion [1]
- In turn this will hit this SetTraceValue overload [2], which accepts a std::String.
  This overload will temporary add the TRACE_VALUE_TYPE_COPY_STRING flag and copy the c_str() pointer inside. It's all good, we are still in the caller stack and that c_str() raw pointer is not going to outlive.
- At this point we get into TraceLog::AddTraceEventWithThreadIdAndTimestamp [3]
- Inside here we first do:
 if (*category_group_enabled & TraceCategory::ENABLED_FOR_FILTERING) {
   ...
   new_trace_event->Initialize(...)
  Because of the TRACE_VALUE_TYPE_COPY_STRING, TraceEvent::Initialize will actually copy the string into its |parameter_copy_storage_| [4]
  Note that if we are using heap profiling, there is a good chance that the trace might be actually enabled for filtering (somebody to confirm plz)
- Later
  if ((*category_group_enabled & TraceCategory::ENABLED_FOR_RECORDING) ...
    we move that trace event inside the trace log

Now, all those TraceEvent in tracelog are wrapped in a std::unique_ptr<TraceEvent>, and since |parameter_copy_storage_| is a std::unique_ptr<std::string>, the dtor of TraceEvent will always clear that.

So at this point, either there is something subtle that I am missing OR
- etienneb@ has trace ENABLED_FOR_RECORDING
- those strings are not leaked but they are just added to the TraceLog and owned by that.
Note that the TraceLog is bounded on the number of events, not their size, and depending on the recording mode can contain up to 512000000 events in "record as much as you can" mode, or kTraceEventVectorBufferChunks = 256000 in default mode.

So, in order to make progress here:
etienneb@ did you have tracing enabled for recording?
If yes, this is a WontFix
If no, we have to figure out if tracing was "accidentally" enabled for recording (This would be a bug and we need to figure out)
If no and trace was enabled only for filtering, there is something more subtle going on here, and the RAII of TraceEvent isn't working as expected.


[1] https://chromium.googlesource.com/chromium/src/+/356875c293ba3f33b0c5fd1b203bf91c2078a004/base/trace_event/trace_event.h#826
[2] https://chromium.googlesource.com/chromium/src/+/8c5e4fb1fced9af3d19e718e54e07ef8b8d2d1da/base/trace_event/trace_event.h#642
[3] https://chromium.googlesource.com/chromium/src/+/8c5e4fb1fced9af3d19e718e54e07ef8b8d2d1da/base/trace_event/trace_log.cc#1166
[4] https://chromium.googlesource.com/chromium/src/+/33321455a76da87330f5770ce092be8a06fd5df8/base/trace_event/trace_event_impl.cc#158
Components: Speed>Tracing
> etienneb@ has trace ENABLED_FOR_RECORDING
> etienneb@ did you have tracing enabled for recording?

This is not my trace. It's based on Erik Chen traces.
I'm only activating memory-infra when I'm grabbing a memory dumps.
I can't tell if this stackframe was part of my traces. I'm gonna keep eyes open for my next round.



I just use TraceOnTap to grab traces. 
Owner: primiano@chromium.org
Status: Assigned (was: Untriaged)
primiano: Please close if this doesn't seem relevant.

Comment 7 by etienneb@google.com, Jun 22 2017

This is still showing up in recent traces provided by Erik

Sign in to add a comment