trace_event support for thread names

Implement backend for thread names and process names.

Added a new trace event phase 'M'/TRACE_EVENT_PHASE_METADATA,
which can become a general mechanism for adding metadata to traces.

The two M-type events that we then add are:
	{ph=M pid=<pid> name="process_name" args={ name="name of pid" }}
	{ph=M pid=<pid> tid=<tid> name="thread_name" args={ name="name of tid" }}

base::thread is instrumented to set names automatically. I will do a followon
changelist to add instrumentation to Chrome for its various processes and
threads.

Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=95997

[nduca, 2011-07-26 06:43:08]

Here's the beginnings of names for threads in trace_event recordings. I will be
working on the frontend changes in parallel.

brettw: I can't quite figure out a clean place to hook thread names. I
originally placed them in base::Thread, but while that class is initialized with
a name for both main and non-main threads, it can't tell when its being bound to
an existing thread versus creating a new thread. That makes it hard to call
SetThreadName from in there. Any suggestions? I'm open to refactoring the way
threads get set up if you feel that the parallel changes I made here to the
platform-specific threads is too ugly.

vince: I cannot for the life of me figure out why these changes cause the AtExit
test to fail. Any insights?

[joth, 2011-07-26 09:53:17]

Great, thanks for adding this! A couple drive-by-ish comments attached.

One thing I wonder is whether we could wire up PlatformThread::SetName to
actually work for everyone (at least on linux) rather than hook it to keep this
independent map of threadID -> name? In particular, this way  around it seems
tricky to ensure all threads go through a SetName call whilst tracing is enabled
in order to get an entry in the map?
With the alternative, we'd just have to keep a set of thread IDs seen, and then
in SetEnabled(false) walk the set looking up the thread name for each tid and
emit the meta event for it.

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event.cc
File base/debug/trace_event.cc (right):

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event.cc#ne...
base/debug/trace_event.cc:432: const TraceCategory* metadata_category =
GetCategoryInternal("__metadata");
static const?

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event.cc#ne...
base/debug/trace_event.cc:449: true));
you can pass false here. (The only thing that needs copying is the arg value,
and that's always copied)

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event_unitt...
File base/debug/trace_event_unittest.cc (right):

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event_unitt...
base/debug/trace_event_unittest.cc:182: const char *string_to_match) {
nit: most of this file attaches the * to the type not the var name. (Exception
is FindTraceEntry above...)

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event_unitt...
base/debug/trace_event_unittest.cc:563: item = items[i];
maybe just ASSERT_TRUE(item) here, then you don't need to test it in all the
EXPECTs below?

http://codereview.chromium.org/7495031/diff/1005/base/threading/platform_thre...
File base/threading/platform_thread_mac.mm (right):

http://codereview.chromium.org/7495031/diff/1005/base/threading/platform_thre...
base/threading/platform_thread_mac.mm:14: #include "base/debug/trace_event.h"
alpha order

http://codereview.chromium.org/7495031/diff/1005/base/threading/platform_thre...
File base/threading/platform_thread_posix.cc (right):

http://codereview.chromium.org/7495031/diff/1005/base/threading/platform_thre...
base/threading/platform_thread_posix.cc:156: // Linux SetName is currently
disabled, as we need to distinguish between
FWIW we should be able to distinguish the main thread from others by testing for
pid == tid.

http://codereview.chromium.org/7495031/diff/1005/base/threading/platform_thre...
base/threading/platform_thread_posix.cc:159: // to stop working).
we should be able to distinguish the main thread from others by testing for pid
== tid.

[scheib, 2011-07-26 18:47:16]

1 comment.

Re: AtExit, something is causing the singleton to not be released, will chat in
person about it, it's not obvious to me either.

http://codereview.chromium.org/7495031/diff/1005/base/threading/thread.cc
File base/threading/thread.cc (right):

http://codereview.chromium.org/7495031/diff/1005/base/threading/thread.cc#new...
base/threading/thread.cc:154:
debug::TraceLog::GetInstance()->SetCurrentThreadName(name_.c_str());
Isn't this redundant with the call to PlatformThread::SetName just above?

[jbates, 2011-07-26 20:57:00]

I know you're already thinking about how to work around the threading startup
issues, so my feedback may be irrelevant, but anyhoo...

It would be great to avoid adding tracing stuff to the thread classes.

Isn't it possible to ask our threading API to map tid to Thread and then get the
Thread::thread_name() if the mapping was successful? (It doesn't look possible,
but maybe that should be added...) Then you could just loop through the events
at the end of tracing and create the set of tid's, and then add the metadata for
those tids outside of the loop. Then you wouldn't need the hash_map member in
trace_event.h. It seems unnecessary to track tids during trace, because the
DisableTrace call is slow anyway, right?

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event.cc
File base/debug/trace_event.cc (right):

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event.cc#ne...
base/debug/trace_event.cc:434: TimeTicks now = TimeTicks::HighResNow();
can we replace the timestamp with 0 for metadata events or would that trip up
the javascript range calculation?

[nduca, 2011-07-28 20:38:30]

So I've simplified this patch ab it based on feedback, namely by a  patch to
base::Thread  (http://codereview.chromium.org/7529003/). This means platform
threads don't require instrumentation.

As far as both jbates and joth's comments on tid maps, the key thing going on
here is that we track tid->name bindings even when not recording. The two cases
that are tricky but important to capture are:
1. Threads that are created before tracing begins
2. Threads that die before tracing ends

The ideas of having the thread system know existing threads, or walking the
active thread list at trace end don't handle #2 well. Or, if we fixed that
somehow, then we'd have the same singleton problem we have in the trace system.

Also, there's the issue of walking the thread list without races. :(

Any other options? Did I misunderstand anyone?

[Sigurður Ásgeirsson, 2011-08-02 19:36:41]

As we discussed, maybe it'd be better to stash the thread name in TLS at the
PlatformThread level, then push it into the trace when you get the first event
on that thread?

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event.h
File base/debug/trace_event.h (right):

http://codereview.chromium.org/7495031/diff/1005/base/debug/trace_event.h#new...
base/debug/trace_event.h:530: base::hash_map<PlatformThreadId, std::string>
thread_names_;
It looks like this map will grow without bounds as there's no thread termination
notification.

[nduca, 2011-08-02 20:51:23]

I'm psyched about this approach. Jbates, I know you suggested this previously in
a discussion, too. I owe you an apology for being stubborn. :$

[nduca, 2011-08-03 21:56:53]

Any feedback, folks? Lets get this shipped or shot. :)

[scheib, 2011-08-03 22:18:13]

Did you catch what was causing the AtExit failures? Otherwise looked good to me.

[jbates, 2011-08-03 22:20:40]

On 2011/08/03 21:56:53, nduca wrote:
> Any feedback, folks? Lets get this shipped or shot. :)

The hashmap find call in AddTraceEvent adds some runtime overhead, but the only
alternative would be to have PlatformThread maintain the hashmap for tid->name
lookup. We can do that later if we have perf issues. LGTM.

[nduca, 2011-08-03 22:58:07]

On 2011/08/03 22:18:13, scheib wrote:
> Did you catch what was causing the AtExit failures? Otherwise looked good to
me.

Yeah, the atexit failures come from threads that got made before the atexit
manager calling TraceEvent::GetInstance. This patch doesn't call into traceevent
until you actually make a trace call. As jbates points out, this has some
overhead, but its a LOT less risky from an ordering point of view.

The reason I opted to not store a hashmap in the PlatformThread is because you'd
run into the same singleton race again. I have some ideas to avoid that, but
they're hard to implement, and like jbates says, lets do that only if we really
need to down the road.

[Sigurður Ásgeirsson, 2011-08-04 12:31:39]

very neat!

http://codereview.chromium.org/7495031/diff/13001/base/debug/trace_event.cc
File base/debug/trace_event.cc (right):

http://codereview.chromium.org/7495031/diff/13001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:369: if (thread_names_.find(thread_id) ==
thread_names_.end()) {
On Windows, thread and process IDs are reused quite aggressively, so this may
end up not recording the thread name for a thread that's inherited a previously
used thread ID.
You can either (simply) set this on every event, or else you could maintain a
thread-local boolean variable "did_record_name".

http://codereview.chromium.org/7495031/diff/13001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:437: for(base::hash_map<PlatformThreadId,
std::string>::iterator it =
lock_.AssertHeld().
However, I don't think you're holding the lock here, so you have a race on the
map?

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
File base/threading/platform_thread.h (right):

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
base/threading/platform_thread.h:78: // otherwise.
As you don't copy the name, I think you've added a requirement on this function
that the string must outlive the PlatformThread?

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
base/threading/platform_thread.h:81: // Gets the thread name, if previously set
by SetTName.
SetTName->SetName

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
File base/threading/platform_thread_posix.cc (right):

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
base/threading/platform_thread_posix.cc:65: 
nit: spurious space?

[nduca, 2011-08-04 18:17:38]

http://codereview.chromium.org/7495031/diff/13001/base/debug/trace_event.cc
File base/debug/trace_event.cc (right):

http://codereview.chromium.org/7495031/diff/13001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:369: if (thread_names_.find(thread_id) ==
thread_names_.end()) {
On 2011/08/04 12:31:39, Ruðrugis wrote:
> On Windows, thread and process IDs are reused quite aggressively...
Thats an awesome idea.

http://codereview.chromium.org/7495031/diff/13001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:437: for(base::hash_map<PlatformThreadId,
std::string>::iterator it =
Nice catch!

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
File base/threading/platform_thread.h (right):

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
base/threading/platform_thread.h:78: // otherwise.
On 2011/08/04 12:31:39, Ruðrugis wrote:
> As you don't copy the name, I think you've added a requirement on this
function
> that the string must outlive the PlatformThread?

Actually, that's not the case --- the pointer here only goes into TLS, so its
inaccessible once the thread dies. And, we only retrieve the thread name when
called from that thread. 

The restriction is that the thread name has to survive for the duration of the
thread. I will clarify that.

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
base/threading/platform_thread.h:81: // Gets the thread name, if previously set
by SetTName.
On 2011/08/04 12:31:39, Ruðrugis wrote:
> SetTName->SetName

Done.

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
File base/threading/platform_thread_posix.cc (right):

http://codereview.chromium.org/7495031/diff/13001/base/threading/platform_thr...
base/threading/platform_thread_posix.cc:65: 
On 2011/08/04 12:31:39, Ruðrugis wrote:
> nit: spurious space?

Done.

[Sigurður Ásgeirsson, 2011-08-04 20:07:05]

lgtm as far as base is concerned.

http://codereview.chromium.org/7495031/diff/22001/base/debug/trace_event.cc
File base/debug/trace_event.cc (right):

http://codereview.chromium.org/7495031/diff/22001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:386: // This is a thread id that we've seen before,
but potentially with a
so, you want to keep all names you've seen?

http://codereview.chromium.org/7495031/diff/22001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:391: for (size_t i = 0; i < existing_names.size();
++i) {
nit: to the naked eye this looks equivalent to

bool found = std::find(existing_names.begin(),
                       existing_names.end(),
                       cur_name) != existing_names.end();

with a shorter variable name, it might even fit a single line :).

[nduca, 2011-08-04 20:16:24]

Mmm, find! Whod'a thunk? :)

Since we don't capture thread creation or deletion events, in the case that
tid's are being reused, we would see those as a single thread in the actual
trace file. Maybe someday we should fix that, but in the interim, I figured it'd
be better to not lose information

The changes to chrome/ dir are accidental --- new patchset should be base
changes only.

Brett, I think we need your review and then its good to go.

[brettw, 2011-08-08 20:10:37]

LGTM mostly rubber stamp.

http://codereview.chromium.org/7495031/diff/25001/base/debug/trace_event_unit...
File base/debug/trace_event_unittest.cc (right):

http://codereview.chromium.org/7495031/diff/25001/base/debug/trace_event_unit...
base/debug/trace_event_unittest.cc:584: void
TraceCallsWithCachedCategoryPointersPointers(const char* name_str) {
Can you put this at the top? Generally we shouldn't have random namespaces
sprinkled throughout the file.

http://codereview.chromium.org/7495031/diff/25001/base/threading/platform_thr...
File base/threading/platform_thread_mac.mm (right):

http://codereview.chromium.org/7495031/diff/25001/base/threading/platform_thr...
base/threading/platform_thread_mac.mm:22: }
Nee // namespace

[nduca, 2011-08-08 22:51:16]

Thanks again, folks.