diff options
author | nduca@chromium.org <nduca@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2011-08-09 15:16:25 +0000 |
---|---|---|
committer | nduca@chromium.org <nduca@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2011-08-09 15:16:25 +0000 |
commit | 5b4926e1893925ce5be80d1e43fe753f27952e9c (patch) | |
tree | d35c2bbc7e91a18ea5256f0690912ff8493d5aa8 | |
parent | 151648c6d04cb19e8bfe868bb668342912952e44 (diff) | |
download | chromium_src-5b4926e1893925ce5be80d1e43fe753f27952e9c.zip chromium_src-5b4926e1893925ce5be80d1e43fe753f27952e9c.tar.gz chromium_src-5b4926e1893925ce5be80d1e43fe753f27952e9c.tar.bz2 |
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.
Review URL: http://codereview.chromium.org/7495031
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@95997 0039d316-1c4b-4281-b951-d872f2087c98
-rw-r--r-- | base/debug/trace_event.cc | 67 | ||||
-rw-r--r-- | base/debug/trace_event.h | 7 | ||||
-rw-r--r-- | base/debug/trace_event_unittest.cc | 207 | ||||
-rw-r--r-- | base/threading/platform_thread.h | 7 | ||||
-rw-r--r-- | base/threading/platform_thread_mac.mm | 10 | ||||
-rw-r--r-- | base/threading/platform_thread_posix.cc | 22 | ||||
-rw-r--r-- | base/threading/platform_thread_win.cc | 11 |
7 files changed, 262 insertions, 69 deletions
diff --git a/base/debug/trace_event.cc b/base/debug/trace_event.cc index d467055..c983df9 100644 --- a/base/debug/trace_event.cc +++ b/base/debug/trace_event.cc @@ -4,6 +4,8 @@ #include "base/debug/trace_event.h" +#include <algorithm> + #if defined(OS_WIN) #include "base/debug/trace_event_win.h" #endif @@ -11,6 +13,7 @@ #include "base/memory/ref_counted_memory.h" #include "base/process_util.h" #include "base/stringprintf.h" +#include "base/threading/thread_local.h" #include "base/utf_string_conversions.h" #include "base/stl_util.h" #include "base/time.h" @@ -30,13 +33,20 @@ const size_t kTraceEventBatchSize = 1000; static TraceCategory g_categories[TRACE_EVENT_MAX_CATEGORIES] = { { "tracing already shutdown", false }, { "tracing categories exhausted; must increase TRACE_EVENT_MAX_CATEGORIES", + false }, + { "__metadata", false } }; static const TraceCategory* const g_category_already_shutdown = &g_categories[0]; static const TraceCategory* const g_category_categories_exhausted = &g_categories[1]; -static int g_category_index = 2; // skip initial 2 error categories +static const TraceCategory* const g_category_metadata = + &g_categories[2]; +static int g_category_index = 3; // skip initial 3 categories + +// Flag to indicate whether we captured the current thread name +static ThreadLocalBoolean g_current_thread_name_captured; //////////////////////////////////////////////////////////////////////////////// // @@ -104,6 +114,8 @@ const char* GetPhaseStr(TraceEventPhase phase) { return "I"; case TRACE_EVENT_PHASE_END: return "E"; + case TRACE_EVENT_PHASE_METADATA: + return "M"; default: NOTREACHED() << "Invalid phase argument"; return "?"; @@ -294,9 +306,13 @@ void TraceLog::SetEnabled(bool enabled) { // check GetCategoryInternal creation code that users TraceLog::enabled_ g_categories[i].enabled = enabled; } + + if (!enabled) + AddCurrentMetadataEvents(); } // release lock - if (!enabled) + if (!enabled) { Flush(); + } } float TraceLog::GetBufferPercentFull() const { @@ -361,6 +377,33 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase, return -1; if (logged_events_.size() >= kTraceEventBufferSize) return -1; + + PlatformThreadId thread_id = PlatformThread::CurrentId(); + + // Record the name of the calling thread, if not done already. + if (!g_current_thread_name_captured.Get()) { + const char* cur_name = PlatformThread::GetName(); + base::hash_map<PlatformThreadId, std::string>::iterator existing_name = + thread_names_.find(thread_id); + if (existing_name == thread_names_.end()) { + // This is a new thread id, and a new name. + thread_names_[thread_id] = cur_name ? cur_name : ""; + } else if(cur_name != NULL) { + // This is a thread id that we've seen before, but potentially with a + // new name. + std::vector<std::string> existing_names; + Tokenize(existing_name->second, std::string(","), &existing_names); + bool found = std::find(existing_names.begin(), + existing_names.end(), + cur_name) != existing_names.end(); + if (!found) { + existing_names.push_back(cur_name); + thread_names_[thread_id] = + JoinString(existing_names, ','); + } + } + } + if (threshold_begin_id > -1) { DCHECK(phase == base::debug::TRACE_EVENT_PHASE_END); size_t begin_i = static_cast<size_t>(threshold_begin_id); @@ -380,7 +423,7 @@ int TraceLog::AddTraceEvent(TraceEventPhase phase, ret_begin_id = static_cast<int>(logged_events_.size()); logged_events_.push_back( TraceEvent(static_cast<unsigned long>(base::GetCurrentProcId()), - PlatformThread::CurrentId(), + thread_id, now, phase, category, name, arg1_name, arg1_val, arg2_name, arg2_val, @@ -419,6 +462,24 @@ void TraceLog::AddTraceEventEtw(TraceEventPhase phase, } } +void TraceLog::AddCurrentMetadataEvents() { + lock_.AssertAcquired(); + for(base::hash_map<PlatformThreadId, std::string>::iterator it = + thread_names_.begin(); + it != thread_names_.end(); + it++) { + if (!it->second.empty()) + logged_events_.push_back( + TraceEvent(static_cast<unsigned long>(base::GetCurrentProcId()), + it->first, + TimeTicks(), base::debug::TRACE_EVENT_PHASE_METADATA, + g_category_metadata, "thread_name", + "name", it->second.c_str(), + NULL, 0, + false)); + } +} + void TraceLog::Resurrect() { StaticMemorySingletonTraits<TraceLog>::Resurrect(); } diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h index 79690f1..0fcdaff 100644 --- a/base/debug/trace_event.h +++ b/base/debug/trace_event.h @@ -90,6 +90,7 @@ #include <vector> #include "base/callback.h" +#include "base/hash_tables.h" #include "base/memory/singleton.h" #include "base/string_util.h" #include "base/third_party/dynamic_annotations/dynamic_annotations.h" @@ -296,7 +297,8 @@ const size_t kTraceMaxNumArgs = 2; enum TraceEventPhase { TRACE_EVENT_PHASE_BEGIN, TRACE_EVENT_PHASE_END, - TRACE_EVENT_PHASE_INSTANT + TRACE_EVENT_PHASE_INSTANT, + TRACE_EVENT_PHASE_METADATA }; // Simple union of values. This is much lighter weight than base::Value, which @@ -512,6 +514,7 @@ class BASE_EXPORT TraceLog { TraceLog(); ~TraceLog(); const TraceCategory* GetCategoryInternal(const char* name); + void AddCurrentMetadataEvents(); // TODO(nduca): switch to per-thread trace buffers to reduce thread // synchronization. @@ -521,6 +524,8 @@ class BASE_EXPORT TraceLog { BufferFullCallback buffer_full_callback_; std::vector<TraceEvent> logged_events_; + base::hash_map<PlatformThreadId, std::string> thread_names_; + DISALLOW_COPY_AND_ASSIGN(TraceLog); }; diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc index 6b8f5f9..7217b1d 100644 --- a/base/debug/trace_event_unittest.cc +++ b/base/debug/trace_event_unittest.cc @@ -9,6 +9,7 @@ #include "base/json/json_reader.h" #include "base/json/json_writer.h" #include "base/memory/scoped_ptr.h" +#include "base/process_util.h" #include "base/stringprintf.h" #include "base/synchronization/waitable_event.h" #include "base/threading/thread.h" @@ -154,7 +155,7 @@ bool IsStringInDict(const char* string_to_match, DictionaryValue* dict) { } DictionaryValue* FindTraceEntry(const ListValue& trace_parsed, - const char *string_to_match, + const char* string_to_match, DictionaryValue* match_after_this_item = NULL) { // Scan all items size_t trace_parsed_count = trace_parsed.GetSize(); @@ -176,7 +177,25 @@ DictionaryValue* FindTraceEntry(const ListValue& trace_parsed, return NULL; } -void DataCapturedCallTraces(WaitableEvent* task_complete_event) { +std::vector<DictionaryValue*> FindTraceEntries( + const ListValue& trace_parsed, + const char* string_to_match) { + std::vector<DictionaryValue*> hits; + size_t trace_parsed_count = trace_parsed.GetSize(); + for (size_t i = 0; i < trace_parsed_count; i++) { + Value* value = NULL; + trace_parsed.Get(i, &value); + if (!value || value->GetType() != Value::TYPE_DICTIONARY) + continue; + DictionaryValue* dict = static_cast<DictionaryValue*>(value); + + if (IsStringInDict(string_to_match, dict)) + hits.push_back(dict); + } + return hits; +} + +void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) { { TRACE_EVENT_BEGIN_ETW("TRACE_EVENT_BEGIN_ETW call", 1122, "extrastring1"); TRACE_EVENT_END_ETW("TRACE_EVENT_END_ETW call", 3344, "extrastring2"); @@ -212,7 +231,7 @@ void DataCapturedCallTraces(WaitableEvent* task_complete_event) { task_complete_event->Signal(); } -void DataCapturedValidateTraces(const ListValue& trace_parsed, +void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed, const std::string& trace_string) { DictionaryValue* item = NULL; @@ -275,6 +294,57 @@ void DataCapturedValidateTraces(const ListValue& trace_parsed, EXPECT_SUB_FIND_("value2"); } +void TraceManyInstantEvents(int thread_id, int num_events, + WaitableEvent* task_complete_event) { + for (int i = 0; i < num_events; i++) { + TRACE_EVENT_INSTANT2("all", "multi thread event", + "thread", thread_id, + "event", i); + } + + if (task_complete_event) + task_complete_event->Signal(); +} + +void ValidateInstantEventPresentOnEveryThread(const ListValue& trace_parsed, + const std::string& trace_string, + int num_threads, int num_events) { + std::map<int, std::map<int, bool> > results; + + size_t trace_parsed_count = trace_parsed.GetSize(); + for (size_t i = 0; i < trace_parsed_count; i++) { + Value* value = NULL; + trace_parsed.Get(i, &value); + if (!value || value->GetType() != Value::TYPE_DICTIONARY) + continue; + DictionaryValue* dict = static_cast<DictionaryValue*>(value); + std::string name; + dict->GetString("name", &name); + if (name != "multi thread event") + continue; + + int thread = 0; + int event = 0; + EXPECT_TRUE(dict->GetInteger("args.thread", &thread)); + EXPECT_TRUE(dict->GetInteger("args.event", &event)); + results[thread][event] = true; + } + + EXPECT_FALSE(results[-1][-1]); + for (int thread = 0; thread < num_threads; thread++) { + for (int event = 0; event < num_events; event++) { + EXPECT_TRUE(results[thread][event]); + } + } +} + +void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) { + TRACE_EVENT0("category name1", name_str); + TRACE_EVENT_INSTANT0("category name2", name_str); + TRACE_EVENT_BEGIN0("category name3", name_str); + TRACE_EVENT_END0("category name4", name_str); +} + } // namespace // Simple Test for emitting data and validating it was received. @@ -282,11 +352,11 @@ TEST_F(TraceEventTestFixture, DataCaptured) { ManualTestSetUp(); TraceLog::GetInstance()->SetEnabled(true); - DataCapturedCallTraces(NULL); + TraceWithAllMacroVariants(NULL); TraceLog::GetInstance()->SetEnabled(false); - DataCapturedValidateTraces(trace_parsed_, trace_string_); + ValidateAllTraceMacrosCreatedData(trace_parsed_, trace_string_); } // Simple Test for time threshold events. @@ -402,103 +472,116 @@ TEST_F(TraceEventTestFixture, DataCapturedOnThread) { thread.Start(); thread.message_loop()->PostTask( - FROM_HERE, NewRunnableFunction(&DataCapturedCallTraces, + FROM_HERE, NewRunnableFunction(&TraceWithAllMacroVariants, &task_complete_event)); task_complete_event.Wait(); TraceLog::GetInstance()->SetEnabled(false); thread.Stop(); - DataCapturedValidateTraces(trace_parsed_, trace_string_); + ValidateAllTraceMacrosCreatedData(trace_parsed_, trace_string_); } -namespace { +// Test that data sent from multiple threads is gathered +TEST_F(TraceEventTestFixture, DataCapturedManyThreads) { + ManualTestSetUp(); + TraceLog::GetInstance()->SetEnabled(true); -void DataCapturedCallManyTraces(int thread_id, int num_events, - WaitableEvent* task_complete_event) { - for (int i = 0; i < num_events; i++) { - TRACE_EVENT_INSTANT2("all", "multi thread event", - "thread", thread_id, - "event", i); + const int num_threads = 4; + const int num_events = 4000; + Thread* threads[num_threads]; + WaitableEvent* task_complete_events[num_threads]; + for (int i = 0; i < num_threads; i++) { + threads[i] = new Thread(StringPrintf("Thread %d", i).c_str()); + task_complete_events[i] = new WaitableEvent(false, false); + threads[i]->Start(); + threads[i]->message_loop()->PostTask( + FROM_HERE, NewRunnableFunction(&TraceManyInstantEvents, + i, num_events, task_complete_events[i])); } - if (task_complete_event) - task_complete_event->Signal(); -} - -void DataCapturedValidateManyTraces(const ListValue& trace_parsed, - const std::string& trace_string, - int num_threads, int num_events) { - std::map<int, std::map<int, bool> > results; + for (int i = 0; i < num_threads; i++) { + task_complete_events[i]->Wait(); + } - size_t trace_parsed_count = trace_parsed.GetSize(); - for (size_t i = 0; i < trace_parsed_count; i++) { - Value* value = NULL; - trace_parsed.Get(i, &value); - if (!value || value->GetType() != Value::TYPE_DICTIONARY) - continue; - DictionaryValue* dict = static_cast<DictionaryValue*>(value); - std::string name; - dict->GetString("name", &name); - if (name != "multi thread event") - continue; + TraceLog::GetInstance()->SetEnabled(false); - int thread = 0; - int event = 0; - EXPECT_TRUE(dict->GetInteger("args.thread", &thread)); - EXPECT_TRUE(dict->GetInteger("args.event", &event)); - results[thread][event] = true; + for (int i = 0; i < num_threads; i++) { + threads[i]->Stop(); + delete threads[i]; + delete task_complete_events[i]; } - EXPECT_FALSE(results[-1][-1]); - for (int thread = 0; thread < num_threads; thread++) { - for (int event = 0; event < num_events; event++) { - EXPECT_TRUE(results[thread][event]); - } - } + ValidateInstantEventPresentOnEveryThread(trace_parsed_, trace_string_, + num_threads, num_events); } -} // namespace - -// Test that data sent from multiple threads is gathered -TEST_F(TraceEventTestFixture, DataCapturedManyThreads) { +// Test that thread and process names show up in the trace +TEST_F(TraceEventTestFixture, ThreadNames) { ManualTestSetUp(); - TraceLog::GetInstance()->SetEnabled(true); + // Create threads before we enable tracing to make sure + // that tracelog still captures them. const int num_threads = 4; - const int num_events = 4000; + const int num_events = 10; Thread* threads[num_threads]; + PlatformThreadId thread_ids[num_threads]; + for (int i = 0; i < num_threads; i++) + threads[i] = new Thread(StringPrintf("Thread %d", i).c_str()); + + // Enable tracing. + TraceLog::GetInstance()->SetEnabled(true); + + // Now run some trace code on these threads. WaitableEvent* task_complete_events[num_threads]; for (int i = 0; i < num_threads; i++) { - threads[i] = new Thread(StringPrintf("Thread %d", i).c_str()); task_complete_events[i] = new WaitableEvent(false, false); threads[i]->Start(); + thread_ids[i] = threads[i]->thread_id(); threads[i]->message_loop()->PostTask( - FROM_HERE, NewRunnableFunction(&DataCapturedCallManyTraces, + FROM_HERE, NewRunnableFunction(&TraceManyInstantEvents, i, num_events, task_complete_events[i])); } - for (int i = 0; i < num_threads; i++) { task_complete_events[i]->Wait(); } + // Shut things down. TraceLog::GetInstance()->SetEnabled(false); - for (int i = 0; i < num_threads; i++) { threads[i]->Stop(); delete threads[i]; delete task_complete_events[i]; } - DataCapturedValidateManyTraces(trace_parsed_, trace_string_, - num_threads, num_events); + std::string tmp; + int tmp_int; + DictionaryValue* item; + + // Make sure we get thread name metadata. + // Note, the test suite may have created a ton of threads. + // So, we'll have thread names for threads we didn't create. + std::vector<DictionaryValue*> items = + FindTraceEntries(trace_parsed_, "thread_name"); + for (int i = 0; i < static_cast<int>(items.size()); i++) { + item = items[i]; + EXPECT_TRUE(item); + EXPECT_TRUE(item->GetInteger("tid", &tmp_int)); + + // See if this thread name is one of the threads we just created + for (int j = 0; j < num_threads; j++) { + if(static_cast<int>(thread_ids[j]) != tmp_int) + continue; + + std::string expected_name = StringPrintf("Thread %d", j).c_str(); + EXPECT_TRUE(item->GetString("ph", &tmp) && tmp == "M"); + EXPECT_TRUE(item->GetInteger("pid", &tmp_int) && + tmp_int == static_cast<int>(base::GetCurrentProcId())); + EXPECT_TRUE(item->GetString("args.name", &tmp) && + tmp == expected_name); + } + } } -void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) { - TRACE_EVENT0("category name1", name_str); - TRACE_EVENT_INSTANT0("category name2", name_str); - TRACE_EVENT_BEGIN0("category name3", name_str); - TRACE_EVENT_END0("category name4", name_str); -} // Test trace calls made after tracing singleton shut down. // diff --git a/base/threading/platform_thread.h b/base/threading/platform_thread.h index 4703b96..8382bbe 100644 --- a/base/threading/platform_thread.h +++ b/base/threading/platform_thread.h @@ -74,9 +74,14 @@ class BASE_EXPORT PlatformThread { // Sleeps for the specified duration (units are milliseconds). static void Sleep(int duration_ms); - // Sets the thread name visible to a debugger. This has no effect otherwise. + // Sets the thread name visible to debuggers/tools. This has no effect + // otherwise. This name pointer is not copied internally. Thus, it must stay + // valid until the thread ends. static void SetName(const char* name); + // Gets the thread name, if previously set by SetName. + static const char* GetName(); + // Creates a new thread. The |stack_size| parameter can be 0 to indicate // that the default stack size should be used. Upon success, // |*thread_handle| will be assigned a handle to the newly created thread, diff --git a/base/threading/platform_thread_mac.mm b/base/threading/platform_thread_mac.mm index 7d59064..9894a1d 100644 --- a/base/threading/platform_thread_mac.mm +++ b/base/threading/platform_thread_mac.mm @@ -11,9 +11,12 @@ #include <mach/thread_policy.h> #include "base/logging.h" +#include "base/threading/thread_local.h" namespace base { +static ThreadLocalPointer<char> current_thread_name; + // If Cocoa is to be used on more than one thread, it must know that the // application is multithreaded. Since it's possible to enter Cocoa code // from threads created by pthread_thread_create, Cocoa won't necessarily @@ -37,6 +40,8 @@ void InitThreading() { // static void PlatformThread::SetName(const char* name) { + current_thread_name.Set(const_cast<char*>(name)); + // pthread_setname_np is only available in 10.6 or later, so test // for it at runtime. int (*dynamic_pthread_setname_np)(const char*); @@ -54,6 +59,11 @@ void PlatformThread::SetName(const char* name) { dynamic_pthread_setname_np(shortened_name.c_str()); } +// static +const char* PlatformThread::GetName() { + return current_thread_name.Get(); +} + namespace { void SetPriorityNormal(mach_port_t mach_thread_id) { diff --git a/base/threading/platform_thread_posix.cc b/base/threading/platform_thread_posix.cc index baa3ab1..c924a16 100644 --- a/base/threading/platform_thread_posix.cc +++ b/base/threading/platform_thread_posix.cc @@ -10,6 +10,7 @@ #include "base/logging.h" #include "base/memory/scoped_ptr.h" #include "base/safe_strerror_posix.h" +#include "base/threading/thread_local.h" #include "base/threading/thread_restrictions.h" #if defined(OS_MACOSX) @@ -41,6 +42,8 @@ void InitThreading(); namespace { +static ThreadLocalPointer<char> current_thread_name; + struct ThreadParams { PlatformThread::Delegate* delegate; bool joinable; @@ -168,6 +171,10 @@ void PlatformThread::Sleep(int duration_ms) { #if 0 && defined(OS_LINUX) // static void PlatformThread::SetName(const char* name) { + // have to cast away const because ThreadLocalPointer does not support const + // void* + current_thread_name.Set(const_cast<char*>(name)); + // http://0pointer.de/blog/projects/name-your-threads.html // glibc recently added support for pthread_setname_np, but it's not @@ -198,14 +205,25 @@ void PlatformThread::SetName(const char* name) { // Mac is implemented in platform_thread_mac.mm. #else // static -void PlatformThread::SetName(const char* /*name*/) { - // Leave it unimplemented. +void PlatformThread::SetName(const char* name) { + // have to cast away const because ThreadLocalPointer does not support const + // void* + current_thread_name.Set(const_cast<char*>(name)); // (This should be relatively simple to implement for the BSDs; I // just don't have one handy to test the code on.) } #endif // defined(OS_LINUX) + +#if !defined(OS_MACOSX) +// Mac is implemented in platform_thread_mac.mm. +// static +const char* PlatformThread::GetName() { + return current_thread_name.Get(); +} +#endif + // static bool PlatformThread::Create(size_t stack_size, Delegate* delegate, PlatformThreadHandle* thread_handle) { diff --git a/base/threading/platform_thread_win.cc b/base/threading/platform_thread_win.cc index 56d7381..e2d90d8 100644 --- a/base/threading/platform_thread_win.cc +++ b/base/threading/platform_thread_win.cc @@ -5,13 +5,17 @@ #include "base/threading/platform_thread.h" #include "base/logging.h" +#include "base/threading/thread_local.h" #include "base/threading/thread_restrictions.h" + #include "base/win/windows_version.h" namespace base { namespace { +static ThreadLocalPointer<char> current_thread_name; + // The information on how to set the thread name comes from // a MSDN article: http://msdn2.microsoft.com/en-us/library/xcb2z8hs.aspx const DWORD kVCThreadNameException = 0x406D1388; @@ -94,6 +98,8 @@ void PlatformThread::Sleep(int duration_ms) { // static void PlatformThread::SetName(const char* name) { + current_thread_name.Set(const_cast<char*>(name)); + // The debugger needs to be around to catch the name in the exception. If // there isn't a debugger, we are just needlessly throwing an exception. if (!::IsDebuggerPresent()) @@ -113,6 +119,11 @@ void PlatformThread::SetName(const char* name) { } // static +const char* PlatformThread::GetName() { + return current_thread_name.Get(); +} + +// static bool PlatformThread::Create(size_t stack_size, Delegate* delegate, PlatformThreadHandle* thread_handle) { DCHECK(thread_handle); |