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

Issue 609912 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Feb 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

MemoryInfra: Thread names are missing in the heap profiler dumps

Project Member Reported by ssid@chromium.org, May 6 2016

Issue description

Background context:go/memory-infra: memory profiling in chrome://tracing

There are a few cases where the SetCurrentThreadName is called before heap profiling capture_enabled is set. This causes all allocations in that thread to miss the thread names in the dumps forever.
 

Comment 1 by ssid@chromium.org, May 6 2016

Owner: ssid@chromium.org

Comment 2 by ssid@chromium.org, May 10 2016

Labels: -Pri-2 Pri-1
This is the sequence of events that is usually seen on android:
Browser:
thread created CrBrowserMain, capture_mode 0
thread created DnsConfigService, capture_mode 0
thread created WorkerPool/4517, capture_mode 0
mdm init mode=0 - set capture mode enabled

Renderer:
thread created CrRendererMain, capture_mode 0
thread created Chrome_ChildIOThread, capture_mode 0
thread created Compositor, capture_mode 0
setting trace filter, capture_mode 0
thread created CompositorTileWorker1/4741 capture_mode 0
thread created CompositorTileWorkerBackground/4742 capture_mode 0
mdm init mode=0 - set capture mode enabled

This happens because the heap profiling is enabled late on android.
On linux it starts with the initialization of TraceLog (at
ChromeMainDelegate::BasicStartupComplete). But on android command line is
initialized only when library load happens.
So capturing is enabled late - after creating 4 threads.
See
https://chromium.googlesource.com/chromium/src/+blame/master/content/app/cont....
I think the issue here is that the command line is initialized little late, and
heap profiling is enabled even later when MDM::Initialize happens.

Maybe the solution here is to initialize mdm earlier like
ContentMainRunnerImpl::Initialize instead of waiting for
ChildMemoryDumpManagerDelegateImpl::SetChildTraceMessageFilter.

Project Member

Comment 4 by bugdroid1@chromium.org, May 18 2016

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

commit 94291d6f25efbd4c28db5d6ba859cfcec61dc664
Author: ssid <ssid@chromium.org>
Date: Wed May 18 14:35:17 2016

[tracing] Fix mising thread names in heap profiler

The thread name goes missing in cases where the heap profiling is
enabled after SetThreadName is called. To fix this, the tracker now
tries to get the thread name from prctl sys call. Both Linux and Android
sets the thread name using prctl. The string allocated for thread name
in tracker needs to be guarded for rentracncy.
This CL also makes thread name as default first entry in the pseudo
stack with thread id if unable to get thread name.
Removes thread name unittest since other unittests cover these cases.

BUG= 609912 

Review-Url: https://codereview.chromium.org/1958703002
Cr-Commit-Position: refs/heads/master@{#394416}

[modify] https://crrev.com/94291d6f25efbd4c28db5d6ba859cfcec61dc664/base/trace_event/heap_profiler_allocation_context_tracker.cc
[modify] https://crrev.com/94291d6f25efbd4c28db5d6ba859cfcec61dc664/base/trace_event/heap_profiler_allocation_context_tracker_unittest.cc

Comment 5 Deleted

Comment 6 by dskiba@chromium.org, Sep 23 2016

It turned out there are two issues with prctl(PR_GET_NAME) approach implemented by #4:

1. Since PR_GET_NAME is capped at 15 chars, it produces weird names, for example "[Thread: oid.apps.chrome]" is the name for the main thread on Android. Not "[Thread: CrBrowserMain]" as it is on Linux (and as Chrome internally knows it), and not "[Thread: com.google.android.apps.chrome]" (as Java knows it).

2. PR_GET_NAME names are inherited. So if a thread with PR_GET_NAME "oid.apps.chrome" starts a new thread, that new thread will also have PR_GET_NAME of "oid.apps.chrome". Eventually the new thread sets correct name with PR_SET_NAME in PlatformThread::SetName(), but if anything triggers an allocation before that happens, AllocationContextTracker for that thread will set its thread_name_ variable to the wrong name, and all subsequent allocations for that thread will be misreported to the wrong (parent) thread.

I noticed (2) once in a Android trace, where "[Thread: oid.apps.chrome]" was reporting 30 allocations originating from ThreadFunc:

[Thread: oid.apps.chrome]
</system/lib/libc.so>
ThreadFunc
base::ThreadIdNameManager::RegisterThread(long, int)
std::__1::map<int, v8::internal::Handle<v8::internal::Script>, std::__1::less<int>, std::__1::allocator<std::__1::pair<int const, v8::internal::Handle<v8::internal::Script> > > >::operator[](int const&)
ShimCppNew

That's not possible on Android, where ThreadFunc never runs on the main thread, because it's created by Android, not Chrome.

So I instrumented PlatformThread::SetName() to log current PR_GET_NAME before changing it:

Changing name 'oid.apps.chrome' -> 'CrBrowserMain' for thread 8464
Changing name 'oid.apps.chrome' -> 'DnsConfigService' for thread 8557
Changing name 'DnsConfigServic' -> 'WorkerPool/8558' for thread 8558
Changing name 'DnsConfigServic' -> 'WorkerPool/8559' for thread 8559
Changing name 'oid.apps.chrome' -> 'MemoryInfra' for thread 8560
Changing name 'oid.apps.chrome' -> 'BrowserBlockingWorker1/8561' for thread 8561
Changing name 'oid.apps.chrome' -> 'BrowserBlockingWorker2/8562' for thread 8562
Changing name 'oid.apps.chrome' -> 'Chrome_FileThread' for thread 8564
Changing name 'oid.apps.chrome' -> 'Chrome_DBThread' for thread 8563
Changing name 'oid.apps.chrome' -> 'Chrome_FileUserBlockingThread' for thread 8565
Changing name 'oid.apps.chrome' -> 'Chrome_ProcessLauncherThread' for thread 8566
Changing name 'oid.apps.chrome' -> 'Chrome_CacheThread' for thread 8567
Changing name 'oid.apps.chrome' -> 'Chrome_IOThread' for thread 8568
Changing name 'oid.apps.chrome' -> 'IndexedDB' for thread 8569
Changing name 'oid.apps.chrome' -> 'AudioThread' for thread 8570
Changing name 'oid.apps.chrome' -> 'BrowserWatchdog' for thread 8571
Changing name 'oid.apps.chrome' -> 'Chrome_HistoryThread' for thread 8585
Changing name 'Thread-4611' -> 'BrowserBlockingWorker3/8586' for thread 8586
Changing name 'oid.apps.chrome' -> 'Startup watchdog thread Watchdog' for thread 8589
Changing name 'Thread-4617' -> 'SimpleCacheWorker1/8591' for thread 8591
Changing name 'ChildProcessMai' -> 'CrGpuMain' for thread 8588
Changing name 'CrGpuMain' -> 'Watchdog' for thread 8592
Changing name 'Thread-4617' -> 'Network File Thread' for thread 8593
Changing name 'oid.apps.chrome' -> 'CompositorTileWorker1/8595' for thread 8595
Changing name 'CrGpuMain' -> 'Chrome_ChildIOThread' for thread 8596
Changing name 'Chrome_ChildIOT' -> 'MemoryInfra' for thread 8600
Changing name 'ChildProcessMai' -> 'CrRendererMain' for thread 8554
Changing name 'CrRendererMain' -> 'Chrome_ChildIOThread' for thread 8603
Changing name 'CrGpuMain' -> 'Unknown' for thread 8604
Changing name 'CrRendererMain' -> 'Compositor' for thread 8605
Changing name 'CrRendererMain' -> 'Renderer::FILE' for thread 8606
Changing name 'CrRendererMain' -> 'CompositorTileWorker1/8607' for thread 8607
Changing name 'CrRendererMain' -> 'CompositorTileWorkerBackground/8608' for thread 8608
Changing name 'Chrome_ChildIOT' -> 'MemoryInfra' for thread 8609
Changing name 'Thread-4617' -> 'SimpleCacheWorker2/8613' for thread 8613
Changing name 'oid.apps.chrome' -> 'Chrome_SyncThread' for thread 8614
Changing name 'Thread-4617' -> 'SimpleCacheWorker3/8615' for thread 8615
Changing name 'Thread-4617' -> 'SimpleCacheWorker4/8616' for thread 8616
Changing name 'Thread-4617' -> 'SimpleCacheWorker5/8617' for thread 8617
Changing name 'CrRendererMain' -> 'WorkerPool/8620' for thread 8620
Changing name 'CrRendererMain' -> 'ScriptStreamerThread' for thread 8622
Changing name 'CrRendererMain' -> 'WorkerPool/8623' for thread 8623
Changing name 'CrRendererMain' -> 'WorkerPool/8624' for thread 8624
Changing name 'CrRendererMain' -> 'WorkerPool/8625' for thread 8625
Changing name 'CrRendererMain' -> 'WorkerPool/8626' for thread 8626
Changing name 'CrRendererMain' -> 'WorkerPool/8627' for thread 8627
Changing name 'CrRendererMain' -> 'WorkerPool/8628' for thread 8628
Changing name 'CrRendererMain' -> 'WorkerPool/8630' for thread 8630
Changing name 'CrRendererMain' -> 'WorkerPool/8629' for thread 8629
Changing name 'Thread-4617' -> 'WorkerPool/8638' for thread 8638
Changing name 'Thread-4617' -> 'WorkerPool/8642' for thread 8642
Changing name 'CrRendererMain' -> 'WorkerPool/8651' for thread 8651
Changing name 'CrRendererMain' -> 'WorkerPool/8652' for thread 8652
Changing name 'CrRendererMain' -> 'WorkerPool/8663' for thread 8663
Changing name 'Chrome_FileThre' -> 'Chrome_DevToolsHandlerThread' for thread 8670

We need to fix this, because otherwise allocation/thread association can't be trusted.
Labels: -Pri-1 Pri-3
Components: Internals>Instrumentation>Memory
Project Member

Comment 9 by bugdroid1@chromium.org, Feb 16 2017

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

commit 69e8419f8d98ee886c1f7b34413ab97d6237cba9
Author: ssid <ssid@chromium.org>
Date: Thu Feb 16 14:32:47 2017

Enable startup tracing from command line flags in components/tracing

This CL does:
1. Move the code that enables TraceLog early into
   components/tracing/common. This code is executed in all processes and
   duplicated in multiple locations.
2. Move TraceConfigFile into components/tracing/common since this code
   is used in all processes except renderer and zygote.
3. Enable heap profiling in trace_startup.

BUG= 609912 

Review-Url: https://codereview.chromium.org/2683913002
Cr-Commit-Position: refs/heads/master@{#450956}

[modify] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/base/trace_event/memory_dump_manager.h
[modify] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/components/tracing/BUILD.gn
[rename] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/components/tracing/common/trace_config_file.cc
[rename] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/components/tracing/common/trace_config_file.h
[rename] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/components/tracing/common/trace_config_file_unittest.cc
[add] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/components/tracing/common/trace_startup.cc
[add] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/components/tracing/common/trace_startup.h
[modify] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/content/app/android/library_loader_hooks.cc
[modify] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/content/app/content_main_runner.cc
[modify] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/content/browser/browser_main_loop.cc
[modify] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/content/browser/browser_main_runner.cc
[modify] https://crrev.com/69e8419f8d98ee886c1f7b34413ab97d6237cba9/content/browser/devtools/protocol/tracing_handler.cc

Project Member

Comment 10 by bugdroid1@chromium.org, Feb 16 2017

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

commit 5dd4fb35920fffa84d53cb908b83668b2c7db1b8
Author: ssid <ssid@chromium.org>
Date: Thu Feb 16 23:57:17 2017

Use the location where FileDescriptorWatcher is created to track the libevent handlers

Currently the trace events are without the location information and it
is of less use without the location for heap profiler. The libevent
handlers are now annotated with the location where the watcher
controller is created for tracing and heap profiler.

This only handles the posix version of watcher events. Windows will be
fixed in different CL.

BUG= 609912 

Review-Url: https://codereview.chromium.org/2695593009
Cr-Commit-Position: refs/heads/master@{#451142}

[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/base/files/file_descriptor_watcher_posix.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/base/message_loop/message_loop_unittest.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/base/message_loop/message_pump_io_ios.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/base/message_loop/message_pump_io_ios.h
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/base/message_loop/message_pump_io_ios_unittest.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/base/message_loop/message_pump_libevent.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/base/message_loop/message_pump_libevent.h
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/base/message_loop/message_pump_libevent_unittest.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/chrome/browser/apps/app_shim/unix_domain_socket_acceptor.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/chrome/browser/chrome_browser_main_extra_parts_exo.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/chrome/common/service_process_util_posix.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/chromeos/binder/ipc_thread.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/components/crash/content/browser/crash_handler_host_linux.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/dbus/bus.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/mojo/edk/system/channel_posix.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/net/base/address_tracker_linux.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/net/dns/notify_watcher_mac.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/net/proxy/proxy_config_service_linux.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/net/socket/socket_posix.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/net/socket/udp_socket_posix.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/ui/events/ozone/device/udev/device_manager_udev.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/ui/events/ozone/evdev/event_converter_evdev.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/ui/events/ozone/evdev/event_converter_evdev_impl.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/ui/events/ozone/evdev/tablet_event_converter_evdev.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/ui/events/platform/x11/x11_event_source_libevent.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/ui/ozone/platform/drm/gpu/drm_device.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/ui/ozone/platform/wayland/fake_server.cc
[modify] https://crrev.com/5dd4fb35920fffa84d53cb908b83668b2c7db1b8/ui/ozone/platform/wayland/wayland_connection.cc

Comment 11 by ssid@chromium.org, Feb 17 2017

Status: Fixed (was: Assigned)
Thread names should be better.

Sign in to add a comment