diff options
author | jar@chromium.org <jar@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2011-10-31 22:36:21 +0000 |
---|---|---|
committer | jar@chromium.org <jar@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2011-10-31 22:36:21 +0000 |
commit | b2a9bbd42c6d5215c43067582fa2bca3cfc5e20e (patch) | |
tree | 3a19dea8153c354505ede0d67f4dd20fb03c4326 | |
parent | daf82f8e54e875ad6e97aef6952ef181de65caeb (diff) | |
download | chromium_src-b2a9bbd42c6d5215c43067582fa2bca3cfc5e20e.zip chromium_src-b2a9bbd42c6d5215c43067582fa2bca3cfc5e20e.tar.gz chromium_src-b2a9bbd42c6d5215c43067582fa2bca3cfc5e20e.tar.bz2 |
Enable tracking of objects by default
This is a reland of accumulated patches including CLs
8414036, 8425010, 8425013, 8424013.
It fully enables tracking of objects, as seen in about:tracking
in teh release build.
The problem this had in its initaial landing centered on
Mac instability in base_unittest. We were encountering crash
on exit of the tests, with a stack dump involving pthreads.
r=rtenneti
BUG=101856
Review URL: http://codereview.chromium.org/8429009
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@108026 0039d316-1c4b-4281-b951-d872f2087c98
-rw-r--r-- | base/base.gypi | 2 | ||||
-rw-r--r-- | base/location.h | 6 | ||||
-rw-r--r-- | base/message_loop.cc | 20 | ||||
-rw-r--r-- | base/message_loop.h | 16 | ||||
-rw-r--r-- | base/threading/thread.cc | 2 | ||||
-rw-r--r-- | base/threading/worker_pool_posix.cc | 19 | ||||
-rw-r--r-- | base/threading/worker_pool_posix.h | 6 | ||||
-rw-r--r-- | base/threading/worker_pool_win.cc | 24 | ||||
-rw-r--r-- | base/tracked_objects.cc | 382 | ||||
-rw-r--r-- | base/tracked_objects.h | 289 | ||||
-rw-r--r-- | base/tracked_objects_unittest.cc | 412 | ||||
-rw-r--r-- | base/tracking_info.cc | 23 | ||||
-rw-r--r-- | base/tracking_info.h | 41 | ||||
-rw-r--r-- | chrome/browser/browser_about_handler.cc | 12 | ||||
-rw-r--r-- | chrome/browser/chrome_browser_main.cc | 8 | ||||
-rw-r--r-- | chrome/browser/chrome_browser_main.h | 2 | ||||
-rw-r--r-- | chrome/common/chrome_switches.cc | 25 | ||||
-rw-r--r-- | chrome/common/chrome_switches.h | 3 | ||||
-rw-r--r-- | content/browser/browser_main_loop.cc | 3 | ||||
-rw-r--r-- | tools/heapcheck/suppressions.txt | 17 | ||||
-rw-r--r-- | tools/valgrind/tsan/suppressions_mac.txt | 7 |
21 files changed, 901 insertions, 418 deletions
diff --git a/base/base.gypi b/base/base.gypi index 8fa20dc..dd99be3 100644 --- a/base/base.gypi +++ b/base/base.gypi @@ -336,6 +336,8 @@ 'timer.h', 'tracked_objects.cc', 'tracked_objects.h', + 'tracking_info.cc', + 'tracking_info.h', 'tuple.h', 'utf_offset_string_conversions.cc', 'utf_offset_string_conversions.h', diff --git a/base/location.h b/base/location.h index 42b3a92..523bfaf 100644 --- a/base/location.h +++ b/base/location.h @@ -10,12 +10,6 @@ #include "base/base_export.h" #include "base/values.h" -#ifndef NDEBUG -#ifndef TRACK_ALL_TASK_OBJECTS -#define TRACK_ALL_TASK_OBJECTS -#endif // TRACK_ALL_TASK_OBJECTS -#endif // NDEBUG - namespace tracked_objects { // Location provides basic info where of an object was constructed, or was diff --git a/base/message_loop.cc b/base/message_loop.cc index 553efb1..c1d4abb 100644 --- a/base/message_loop.cc +++ b/base/message_loop.cc @@ -486,20 +486,16 @@ void MessageLoop::RunTask(const PendingTask& pending_task) { HistogramEvent(kTaskRunEvent); -#if defined(TRACK_ALL_TASK_OBJECTS) - TimeTicks start_of_run = tracked_objects::ThreadData::Now(); -#endif // defined(TRACK_ALL_TASK_OBJECTS) + tracked_objects::TrackedTime start_time = tracked_objects::ThreadData::Now(); FOR_EACH_OBSERVER(TaskObserver, task_observers_, WillProcessTask(pending_task.time_posted)); pending_task.task.Run(); FOR_EACH_OBSERVER(TaskObserver, task_observers_, DidProcessTask(pending_task.time_posted)); -#if defined(TRACK_ALL_TASK_OBJECTS) - tracked_objects::ThreadData::TallyADeathIfActive(pending_task.post_births, - pending_task.time_posted, pending_task.delayed_run_time, start_of_run, - tracked_objects::ThreadData::Now()); -#endif // defined(TRACK_ALL_TASK_OBJECTS) + + tracked_objects::ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, + start_time, tracked_objects::ThreadData::Now()); nestable_tasks_allowed_ = true; } @@ -779,15 +775,11 @@ MessageLoop::PendingTask::PendingTask( const tracked_objects::Location& posted_from, TimeTicks delayed_run_time, bool nestable) - : task(task), - time_posted(TimeTicks::Now()), - delayed_run_time(delayed_run_time), + : base::TrackingInfo(posted_from, delayed_run_time), + task(task), posted_from(posted_from), sequence_num(0), nestable(nestable) { -#if defined(TRACK_ALL_TASK_OBJECTS) - post_births = tracked_objects::ThreadData::TallyABirthIfActive(posted_from); -#endif // defined(TRACK_ALL_TASK_OBJECTS) } MessageLoop::PendingTask::~PendingTask() { diff --git a/base/message_loop.h b/base/message_loop.h index 732de03..d94dc2f 100644 --- a/base/message_loop.h +++ b/base/message_loop.h @@ -19,6 +19,7 @@ #include "base/observer_list.h" #include "base/synchronization/lock.h" #include "base/task.h" +#include "base/tracking_info.h" #include "base/time.h" #if defined(OS_WIN) @@ -44,11 +45,9 @@ namespace base { class Histogram; } -#if defined(TRACK_ALL_TASK_OBJECTS) namespace tracked_objects { class Births; } -#endif // defined(TRACK_ALL_TASK_OBJECTS) // A MessageLoop is used to process events for a particular thread. There is // at most one MessageLoop instance per thread. @@ -410,7 +409,7 @@ class BASE_EXPORT MessageLoop : public base::MessagePump::Delegate { #endif // This structure is copied around by value. - struct PendingTask { + struct PendingTask : public base::TrackingInfo { PendingTask(const base::Closure& task, const tracked_objects::Location& posted_from, base::TimeTicks delayed_run_time, @@ -423,17 +422,6 @@ class BASE_EXPORT MessageLoop : public base::MessagePump::Delegate { // The task to run. base::Closure task; -#if defined(TRACK_ALL_TASK_OBJECTS) - // Counter for location where the Closure was posted from. - tracked_objects::Births* post_births; -#endif // defined(TRACK_ALL_TASK_OBJECTS) - - // Time this PendingTask was posted. - base::TimeTicks time_posted; - - // The time when the task should be run. - base::TimeTicks delayed_run_time; - // The site this PendingTask was posted from. tracked_objects::Location posted_from; diff --git a/base/threading/thread.cc b/base/threading/thread.cc index 2a8d999..d49f247 100644 --- a/base/threading/thread.cc +++ b/base/threading/thread.cc @@ -152,9 +152,7 @@ void Thread::ThreadMain() { ANNOTATE_THREAD_NAME(name_.c_str()); // Tell the name to race detector. message_loop.set_thread_name(name_); message_loop_ = &message_loop; -#if defined(TRACK_ALL_TASK_OBJECTS) tracked_objects::ThreadData::InitializeThreadContext(name_); -#endif // TRACK_ALL_TASK_OBJECTS // Let the thread do extra initialization. // Let's do this before signaling we are started. diff --git a/base/threading/worker_pool_posix.cc b/base/threading/worker_pool_posix.cc index 41fa01a..917565d 100644 --- a/base/threading/worker_pool_posix.cc +++ b/base/threading/worker_pool_posix.cc @@ -88,15 +88,14 @@ void WorkerThread::ThreadMain() { "src_file", pending_task.posted_from.file_name(), "src_func", pending_task.posted_from.function_name()); -#if defined(TRACK_ALL_TASK_OBJECTS) - TimeTicks start_of_run = tracked_objects::ThreadData::Now(); -#endif // defined(TRACK_ALL_TASK_OBJECTS) + tracked_objects::TrackedTime start_time = + tracked_objects::ThreadData::Now(); + pending_task.task.Run(); -#if defined(TRACK_ALL_TASK_OBJECTS) - tracked_objects::ThreadData::TallyADeathIfActive(pending_task.post_births, - pending_task.time_posted, TimeTicks(), start_of_run, - tracked_objects::ThreadData::Now()); -#endif // defined(TRACK_ALL_TASK_OBJECTS) + + tracked_objects::ThreadData::TallyRunOnWorkerThreadIfTracking( + pending_task.birth_tally, pending_task.time_posted, + start_time, tracked_objects::ThreadData::Now()); } // The WorkerThread is non-joinable, so it deletes itself. @@ -122,10 +121,8 @@ PosixDynamicThreadPool::PendingTask::PendingTask( const base::Closure& task) : posted_from(posted_from), task(task) { -#if defined(TRACK_ALL_TASK_OBJECTS) - post_births = tracked_objects::ThreadData::TallyABirthIfActive(posted_from); + birth_tally = tracked_objects::ThreadData::TallyABirthIfActive(posted_from); time_posted = tracked_objects::ThreadData::Now(); -#endif // defined(TRACK_ALL_TASK_OBJECTS) } PosixDynamicThreadPool::PendingTask::~PendingTask() { diff --git a/base/threading/worker_pool_posix.h b/base/threading/worker_pool_posix.h index c0a60cc..2cc1150 100644 --- a/base/threading/worker_pool_posix.h +++ b/base/threading/worker_pool_posix.h @@ -53,13 +53,11 @@ class BASE_EXPORT PosixDynamicThreadPool const base::Closure& task); ~PendingTask(); -#if defined(TRACK_ALL_TASK_OBJECTS) // Counter for location where the Closure was posted from. - tracked_objects::Births* post_births; + tracked_objects::Births* birth_tally; // Time the task was posted. - TimeTicks time_posted; -#endif // defined(TRACK_ALL_TASK_OBJECTS) + tracked_objects::TrackedTime time_posted; const tracked_objects::Location posted_from; diff --git a/base/threading/worker_pool_win.cc b/base/threading/worker_pool_win.cc index 0cd3d96..b73cabd 100644 --- a/base/threading/worker_pool_win.cc +++ b/base/threading/worker_pool_win.cc @@ -20,19 +20,15 @@ struct PendingTask { const base::Closure& task) : posted_from(posted_from), task(task) { -#if defined(TRACK_ALL_TASK_OBJECTS) - post_births = tracked_objects::ThreadData::TallyABirthIfActive(posted_from); + birth_tally = tracked_objects::ThreadData::TallyABirthIfActive(posted_from); time_posted = tracked_objects::ThreadData::Now(); -#endif // defined(TRACK_ALL_TASK_OBJECTS) } -#if defined(TRACK_ALL_TASK_OBJECTS) // Counter for location where the Closure was posted from. - tracked_objects::Births* post_births; + tracked_objects::Births* birth_tally; // Time the task was posted. - TimeTicks time_posted; -#endif // defined(TRACK_ALL_TASK_OBJECTS) + tracked_objects::TrackedTime time_posted; // The site this PendingTask was posted from. tracked_objects::Location posted_from; @@ -47,15 +43,13 @@ DWORD CALLBACK WorkItemCallback(void* param) { "src_file", pending_task->posted_from.file_name(), "src_func", pending_task->posted_from.function_name()); -#if defined(TRACK_ALL_TASK_OBJECTS) - TimeTicks start_of_run = tracked_objects::ThreadData::Now(); -#endif // defined(TRACK_ALL_TASK_OBJECTS) + tracked_objects::TrackedTime start_time = tracked_objects::ThreadData::Now(); + pending_task->task.Run(); -#if defined(TRACK_ALL_TASK_OBJECTS) - tracked_objects::ThreadData::TallyADeathIfActive(pending_task->post_births, - pending_task->time_posted, TimeTicks::TimeTicks(), start_of_run, - tracked_objects::ThreadData::Now()); -#endif // defined(TRACK_ALL_TASK_OBJECTS) + + tracked_objects::ThreadData::TallyRunOnWorkerThreadIfTracking( + pending_task->birth_tally, pending_task->time_posted, + start_time, tracked_objects::ThreadData::Now()); delete pending_task; return 0; diff --git a/base/tracked_objects.cc b/base/tracked_objects.cc index dfb88eb..7833129 100644 --- a/base/tracked_objects.cc +++ b/base/tracked_objects.cc @@ -11,57 +11,54 @@ #include "base/string_util.h" #include "base/stringprintf.h" #include "base/threading/thread_restrictions.h" +#include "build/build_config.h" using base::TimeDelta; namespace tracked_objects { - -#if defined(TRACK_ALL_TASK_OBJECTS) -static const bool kTrackAllTaskObjects = true; -#else +namespace { +// Flag to compile out almost all of the task tracking code. +#if defined(NDEBUG) && defined(OS_MAC) +// Avoid problems with base_unittest crashes in Mac for now. static const bool kTrackAllTaskObjects = false; +#else +static const bool kTrackAllTaskObjects = true; #endif -// Can we count on thread termination to call for thread cleanup? If not, then -// we can't risk putting references to ThreadData in TLS, as it will leak on -// worker thread termination. -static const bool kWorkerThreadCleanupSupported = true; - -// A TLS slot which points to the ThreadData instance for the current thread. We -// do a fake initialization here (zeroing out data), and then the real in-place -// construction happens when we call tls_index_.Initialize(). -// static -base::ThreadLocalStorage::Slot ThreadData::tls_index_(base::LINKER_INITIALIZED); - -// A global state variable to prevent repeated initialization during tests. -// static -AutoTracking::State AutoTracking::state_ = AutoTracking::kNeverBeenRun; - -// A locked protected counter to assign sequence number to threads. -// static -int ThreadData::thread_number_counter_ = 0; +// When ThreadData is first initialized, should we start in an ACTIVE state to +// record all of the startup-time tasks, or should we start up DEACTIVATED, so +// that we only record after parsing the command line flag --enable-tracking. +// Note that the flag may force either state, so this really controls only the +// period of time up until that flag is parsed. If there is no flag seen, then +// this state may prevail for much or all of the process lifetime. +static const ThreadData::Status kInitialStartupState = ThreadData::ACTIVE; +} // anonymous namespace. //------------------------------------------------------------------------------ // Death data tallies durations when a death takes place. -void DeathData::RecordDeath(const TimeDelta& queue_duration, - const TimeDelta& run_duration) { +void DeathData::RecordDeath(const Duration& queue_duration, + const Duration& run_duration) { ++count_; queue_duration_ += queue_duration; run_duration_ += run_duration; } int DeathData::AverageMsRunDuration() const { - if (run_duration_ == base::TimeDelta()) + if (run_duration_ == Duration() || !count_) return 0; - return static_cast<int>(run_duration_.InMilliseconds() / count_); + // Add half of denominator to achieve rounding. + return static_cast<int>(run_duration_.InMilliseconds() + count_ / 2) / + count_; } int DeathData::AverageMsQueueDuration() const { - if (queue_duration_ == base::TimeDelta()) + if (queue_duration_ == Duration() || !count_) return 0; - return static_cast<int>(queue_duration_.InMilliseconds() / count_); + // Add half of denominator to achieve rounding. + return (static_cast<int>(queue_duration_.InMilliseconds() + count_ / 2) / + count_); } void DeathData::AddDeathData(const DeathData& other) { @@ -75,11 +72,14 @@ void DeathData::WriteHTML(std::string* output) const { return; base::StringAppendF(output, "%s:%d, ", (count_ == 1) ? "Life" : "Lives", count_); - base::StringAppendF(output, "Run:%"PRId64"ms(%dms/life) ", - run_duration_.InMilliseconds(), + // Be careful to leave static_casts intact, as the type returned by + // InMilliseconds() may not always be an int, even if it can generally fit + // into an int. + base::StringAppendF(output, "Run:%dms(%dms/life) ", + static_cast<int>(run_duration_.InMilliseconds()), AverageMsRunDuration()); - base::StringAppendF(output, "Queue:%"PRId64"ms(%dms/life) ", - queue_duration_.InMilliseconds(), + base::StringAppendF(output, "Queue:%dms(%dms/life) ", + static_cast<int>(queue_duration_.InMilliseconds()), AverageMsQueueDuration()); } @@ -95,8 +95,8 @@ base::DictionaryValue* DeathData::ToValue() const { void DeathData::Clear() { count_ = 0; - queue_duration_ = TimeDelta(); - run_duration_ = TimeDelta(); + queue_duration_ = Duration(); + run_duration_ = Duration(); } //------------------------------------------------------------------------------ @@ -113,6 +113,23 @@ Births::Births(const Location& location, const ThreadData& current) //------------------------------------------------------------------------------ // ThreadData maintains the central data for all births and deaths. +// TODO(jar): We should pull all these static vars together, into a struct, and +// optimize layout so that we benefit from locality of reference during accesses +// to them. + +// A TLS slot which points to the ThreadData instance for the current thread. We +// do a fake initialization here (zeroing out data), and then the real in-place +// construction happens when we call tls_index_.Initialize(). +// static +base::ThreadLocalStorage::Slot ThreadData::tls_index_(base::LINKER_INITIALIZED); + +// A lock-protected counter to assign sequence number to threads. +// static +int ThreadData::thread_number_counter_ = 0; + +// static +int ThreadData::incarnation_counter_ = 0; + // static ThreadData* ThreadData::all_thread_data_list_head_ = NULL; @@ -120,44 +137,52 @@ ThreadData* ThreadData::all_thread_data_list_head_ = NULL; ThreadData::ThreadDataPool* ThreadData::unregistered_thread_data_pool_ = NULL; // static -base::Lock ThreadData::list_lock_; +base::Lock* ThreadData::list_lock_; // static ThreadData::Status ThreadData::status_ = ThreadData::UNINITIALIZED; ThreadData::ThreadData(const std::string& suggested_name) - : next_(NULL), + : incarnation_count_for_pool_(-1), + next_(NULL), is_a_worker_thread_(false) { DCHECK_GE(suggested_name.size(), 0u); thread_name_ = suggested_name; - PushToHeadOfList(); + PushToHeadOfList(); // Which sets real incarnation_count_for_pool_. } -ThreadData::ThreadData() : next_(NULL), is_a_worker_thread_(true) { +ThreadData::ThreadData() + : incarnation_count_for_pool_(-1), + next_(NULL), + is_a_worker_thread_(true) { int thread_number; { - base::AutoLock lock(list_lock_); + base::AutoLock lock(*list_lock_); thread_number = ++thread_number_counter_; } base::StringAppendF(&thread_name_, "WorkerThread-%d", thread_number); - PushToHeadOfList(); + PushToHeadOfList(); // Which sets real incarnation_count_for_pool_. } ThreadData::~ThreadData() {} void ThreadData::PushToHeadOfList() { DCHECK(!next_); - base::AutoLock lock(list_lock_); + base::AutoLock lock(*list_lock_); + incarnation_count_for_pool_ = incarnation_counter_; next_ = all_thread_data_list_head_; all_thread_data_list_head_ = this; } // static void ThreadData::InitializeThreadContext(const std::string& suggested_name) { - if (!tls_index_.initialized()) - return; // For unittests only. - DCHECK_EQ(tls_index_.Get(), reinterpret_cast<void*>(NULL)); - ThreadData* current_thread_data = new ThreadData(suggested_name); + if (!Initialize()) // Always initialize if needed. + return; + ThreadData* current_thread_data = + reinterpret_cast<ThreadData*>(tls_index_.Get()); + if (current_thread_data) + return; // Browser tests instigate this. + current_thread_data = new ThreadData(suggested_name); tls_index_.Set(current_thread_data); } @@ -172,7 +197,7 @@ ThreadData* ThreadData::Get() { // We must be a worker thread, since we didn't pre-register. ThreadData* worker_thread_data = NULL; { - base::AutoLock lock(list_lock_); + base::AutoLock lock(*list_lock_); if (!unregistered_thread_data_pool_->empty()) { worker_thread_data = const_cast<ThreadData*>(unregistered_thread_data_pool_->top()); @@ -192,24 +217,29 @@ ThreadData* ThreadData::Get() { void ThreadData::OnThreadTermination(void* thread_data) { if (!kTrackAllTaskObjects) return; // Not compiled in. - DCHECK(tls_index_.initialized()); if (!thread_data) return; reinterpret_cast<ThreadData*>(thread_data)->OnThreadTerminationCleanup(); - DCHECK_EQ(tls_index_.Get(), reinterpret_cast<ThreadData*>(NULL)); } void ThreadData::OnThreadTerminationCleanup() const { - tls_index_.Set(NULL); if (!is_a_worker_thread_) return; - base::AutoLock lock(list_lock_); - unregistered_thread_data_pool_->push(this); + base::AutoLock lock(*list_lock_); + if (incarnation_counter_ != incarnation_count_for_pool_) + return; // ThreadData was constructed in an earlier unit test. + + // Handle case where we are in unit tests, and have become UNINITIALIZED. + // In that case, the pool might be NULL. We really should detect this via the + // incarnation_counter_, but this call is rarely made, so we can afford to + // code defensively. + if (unregistered_thread_data_pool_) + unregistered_thread_data_pool_->push(this); } // static void ThreadData::WriteHTML(const std::string& query, std::string* output) { - if (!ThreadData::IsActive()) + if (status_ == UNINITIALIZED) return; // Not yet initialized. DataCollector collected_data; // Gather data. @@ -316,13 +346,12 @@ void ThreadData::WriteHTMLTotalAndSubtotals( } // static -base::Value* ThreadData::ToValue(int process_type) { +base::DictionaryValue* ThreadData::ToValue() { DataCollector collected_data; // Gather data. collected_data.AddListOfLivingObjects(); // Add births that are still alive. base::ListValue* list = collected_data.ToValue(); base::DictionaryValue* dictionary = new base::DictionaryValue(); dictionary->Set("list", list); - dictionary->SetInteger("process", process_type); return dictionary; } @@ -342,8 +371,8 @@ Births* ThreadData::TallyABirth(const Location& location) { } void ThreadData::TallyADeath(const Births& birth, - const TimeDelta& queue_duration, - const TimeDelta& run_duration) { + const Duration& queue_duration, + const Duration& run_duration) { DeathMap::iterator it = death_map_.find(&birth); DeathData* death_data; if (it != death_map_.end()) { @@ -360,7 +389,7 @@ Births* ThreadData::TallyABirthIfActive(const Location& location) { if (!kTrackAllTaskObjects) return NULL; // Not compiled in. - if (!IsActive()) + if (!tracking_status()) return NULL; ThreadData* current_thread_data = Get(); if (!current_thread_data) @@ -369,37 +398,89 @@ Births* ThreadData::TallyABirthIfActive(const Location& location) { } // static -void ThreadData::TallyADeathIfActive(const Births* birth, - const base::TimeTicks& time_posted, - const base::TimeTicks& delayed_start_time, - const base::TimeTicks& start_of_run, - const base::TimeTicks& end_of_run) { +void ThreadData::TallyRunOnNamedThreadIfTracking( + const base::TrackingInfo& completed_task, + const TrackedTime& start_of_run, + const TrackedTime& end_of_run) { if (!kTrackAllTaskObjects) return; // Not compiled in. - if (!IsActive() || !birth) + // Even if we have been DEACTIVATED, we will process any pending births so + // that our data structures (which counted the outstanding births) remain + // consistent. + const Births* birth = completed_task.birth_tally; + if (!birth) return; - ThreadData* current_thread_data = Get(); if (!current_thread_data) return; // To avoid conflating our stats with the delay duration in a PostDelayedTask, // we identify such tasks, and replace their post_time with the time they - // were sechudled (requested?) to emerge from the delayed task queue. This + // were scheduled (requested?) to emerge from the delayed task queue. This // means that queueing delay for such tasks will show how long they went // unserviced, after they *could* be serviced. This is the same stat as we // have for non-delayed tasks, and we consistently call it queueing delay. - base::TimeTicks effective_post_time = - (delayed_start_time.is_null()) ? time_posted : delayed_start_time; - base::TimeDelta queue_duration = start_of_run - effective_post_time; - base::TimeDelta run_duration = end_of_run - start_of_run; + TrackedTime effective_post_time = completed_task.delayed_run_time.is_null() + ? tracked_objects::TrackedTime(completed_task.time_posted) + : tracked_objects::TrackedTime(completed_task.delayed_run_time); + + // Watch out for a race where status_ is changing, and hence one or both + // of start_of_run or end_of_run is zero. IN that case, we didn't bother to + // get a time value since we "weren't tracking" and we were trying to be + // efficient by not calling for a genuine time value. For simplicity, we'll + // use a default zero duration when we can't calculate a true value. + Duration queue_duration; + Duration run_duration; + if (!start_of_run.is_null()) { + queue_duration = start_of_run - effective_post_time; + if (!end_of_run.is_null()) + run_duration = end_of_run - start_of_run; + } + current_thread_data->TallyADeath(*birth, queue_duration, run_duration); +} + +// static +void ThreadData::TallyRunOnWorkerThreadIfTracking( + const Births* birth, + const TrackedTime& time_posted, + const TrackedTime& start_of_run, + const TrackedTime& end_of_run) { + if (!kTrackAllTaskObjects) + return; // Not compiled in. + + // Even if we have been DEACTIVATED, we will process any pending births so + // that our data structures (which counted the outstanding births) remain + // consistent. + if (!birth) + return; + + // TODO(jar): Support the option to coalesce all worker-thread activity under + // one ThreadData instance that uses locks to protect *all* access. This will + // reduce memory (making it provably bounded), but run incrementally slower + // (since we'll use locks on TallyBirth and TallyDeath). The good news is + // that the locks on TallyDeath will be *after* the worker thread has run, and + // hence nothing will be waiting for the completion (... besides some other + // thread that might like to run). Also, the worker threads tasks are + // generally longer, and hence the cost of the lock may perchance be amortized + // over the long task's lifetime. + ThreadData* current_thread_data = Get(); + if (!current_thread_data) + return; + + Duration queue_duration; + Duration run_duration; + if (!start_of_run.is_null()) { + queue_duration = start_of_run - time_posted; + if (!end_of_run.is_null()) + run_duration = end_of_run - start_of_run; + } current_thread_data->TallyADeath(*birth, queue_duration, run_duration); } // static ThreadData* ThreadData::first() { - base::AutoLock lock(list_lock_); + base::AutoLock lock(*list_lock_); return all_thread_data_list_head_; } @@ -439,71 +520,86 @@ void ThreadData::Reset() { it->second->Clear(); } -// static -bool ThreadData::StartTracking(bool status) { +bool ThreadData::Initialize() { if (!kTrackAllTaskObjects) return false; // Not compiled in. - - // Do a bit of class initialization. - if (!unregistered_thread_data_pool_) { - ThreadDataPool* initial_pool = new ThreadDataPool; - { - base::AutoLock lock(list_lock_); - if (!unregistered_thread_data_pool_) { - unregistered_thread_data_pool_ = initial_pool; - initial_pool = NULL; - } - } - delete initial_pool; // In case it was not used. - } - - // Perform the "real" initialization now, and leave it intact through + if (status_ != UNINITIALIZED) + return true; + // Initialize all leaking constants that are difficult to toggle in and out + // of existance. + // First call must be made when single threaded at startup. + // Perform the "real" TLS initialization now, and leave it intact through // process termination. - if (!tls_index_.initialized()) + if (!tls_index_.initialized()) // Testing may have initialized this. tls_index_.Initialize(&ThreadData::OnThreadTermination); DCHECK(tls_index_.initialized()); + ThreadDataPool* pool = new ThreadDataPool; + // TODO(jar): A linker initialized spin lock would be much safer than this + // allocation, which relies on being called while single threaded. + if (!list_lock_) // In case testing deleted this. + list_lock_ = new base::Lock; + status_ = kInitialStartupState; + + base::AutoLock lock(*list_lock_); + DCHECK_EQ(unregistered_thread_data_pool_, + reinterpret_cast<ThreadDataPool*>(NULL)); + unregistered_thread_data_pool_ = pool; + ++incarnation_counter_; + return true; +} - if (!status) { - base::AutoLock lock(list_lock_); - DCHECK(status_ == ACTIVE || status_ == SHUTDOWN); - status_ = SHUTDOWN; - return true; - } - base::AutoLock lock(list_lock_); - DCHECK_EQ(UNINITIALIZED, status_); - status_ = ACTIVE; +// static +bool ThreadData::InitializeAndSetTrackingStatus(bool status) { + if (!Initialize()) // No-op if already initialized. + return false; // Not compiled in. + + status_ = status ? ACTIVE : DEACTIVATED; return true; } // static -bool ThreadData::IsActive() { +bool ThreadData::tracking_status() { return status_ == ACTIVE; } // static -base::TimeTicks ThreadData::Now() { - if (kTrackAllTaskObjects && status_ == ACTIVE) - return base::TimeTicks::Now(); - return base::TimeTicks(); // Super fast when disabled, or not compiled in. +TrackedTime ThreadData::Now() { + if (kTrackAllTaskObjects && tracking_status()) + return TrackedTime::Now(); + return TrackedTime(); // Super fast when disabled, or not compiled. } // static -void ThreadData::ShutdownSingleThreadedCleanup() { +void ThreadData::ShutdownSingleThreadedCleanup(bool leak) { // This is only called from test code, where we need to cleanup so that // additional tests can be run. // We must be single threaded... but be careful anyway. - if (!StartTracking(false)) + if (!InitializeAndSetTrackingStatus(false)) return; ThreadData* thread_data_list; ThreadDataPool* final_pool; { - base::AutoLock lock(list_lock_); + base::AutoLock lock(*list_lock_); thread_data_list = all_thread_data_list_head_; all_thread_data_list_head_ = NULL; final_pool = unregistered_thread_data_pool_; unregistered_thread_data_pool_ = NULL; + ++incarnation_counter_; } + // Put most global static back in pristine shape. + thread_number_counter_ = 0; + tls_index_.Set(NULL); + status_ = UNINITIALIZED; + + // To avoid any chance of racing in unit tests, which is the only place we + // call this function, we may sometimes leak all the data structures we + // recovered, as they may still be in use on threads from prior tests! + if (leak) + return; + + // When we want to cleanup (on a single thread), here is what we do. + if (final_pool) { // The thread_data_list contains *all* the instances, and we'll use it to // delete them. This pool has pointers to some instances, and we just @@ -525,10 +621,6 @@ void ThreadData::ShutdownSingleThreadedCleanup() { next_thread_data->death_map_.clear(); delete next_thread_data; // Includes all Death Records. } - // Put most global static back in pristine shape. - thread_number_counter_ = 0; - tls_index_.Set(NULL); - status_ = UNINITIALIZED; } //------------------------------------------------------------------------------ @@ -574,16 +666,12 @@ base::DictionaryValue* Snapshot::ToValue() const { return dictionary; } -void Snapshot::Add(const Snapshot& other) { - death_data_.AddDeathData(other.death_data_); -} - //------------------------------------------------------------------------------ // DataCollector DataCollector::DataCollector() { - if (!ThreadData::IsActive()) - return; + if (!kTrackAllTaskObjects) + return; // Not compiled in. // Get an unchanging copy of a ThreadData list. ThreadData* my_list = ThreadData::first(); @@ -740,6 +828,35 @@ void Comparator::Clear() { selector_ = NIL; } +// static +Comparator::Selector Comparator::FindSelector(const std::string& keyword) { + // Sorting and aggretation keywords, which specify how to sort the data, or + // can specify a required match from the specified field in the record. + if (0 == keyword.compare("count")) + return COUNT; + if (0 == keyword.compare("totalduration")) + return TOTAL_RUN_DURATION; + if (0 == keyword.compare("duration")) + return AVERAGE_RUN_DURATION; + if (0 == keyword.compare("totalqueueduration")) + return TOTAL_QUEUE_DURATION; + if (0 == keyword.compare("averagequeueduration")) + return AVERAGE_QUEUE_DURATION; + if (0 == keyword.compare("birth")) + return BIRTH_THREAD; + if (0 == keyword.compare("death")) + return DEATH_THREAD; + if (0 == keyword.compare("file")) + return BIRTH_FILE; + if (0 == keyword.compare("function")) + return BIRTH_FUNCTION; + if (0 == keyword.compare("line")) + return BIRTH_LINE; + if (0 == keyword.compare("reset")) + return RESET_ALL_DATA; + return UNKNOWN_KEYWORD; +} + bool Comparator::operator()(const Snapshot& left, const Snapshot& right) const { switch (selector_) { @@ -956,28 +1073,6 @@ void Comparator::SetSubgroupTiebreaker(Selector selector) { } void Comparator::ParseKeyphrase(const std::string& key_phrase) { - typedef std::map<const std::string, Selector> KeyMap; - static KeyMap key_map; - static bool initialized = false; - if (!initialized) { - initialized = true; - // Sorting and aggretation keywords, which specify how to sort the data, or - // can specify a required match from the specified field in the record. - key_map["count"] = COUNT; - key_map["totalduration"] = TOTAL_RUN_DURATION; - key_map["duration"] = AVERAGE_RUN_DURATION; - key_map["totalqueueduration"] = TOTAL_QUEUE_DURATION; - key_map["averagequeueduration"] = AVERAGE_QUEUE_DURATION; - key_map["birth"] = BIRTH_THREAD; - key_map["death"] = DEATH_THREAD; - key_map["file"] = BIRTH_FILE; - key_map["function"] = BIRTH_FUNCTION; - key_map["line"] = BIRTH_LINE; - - // Immediate commands that do not involve setting sort order. - key_map["reset"] = RESET_ALL_DATA; - } - std::string required; // Watch for: "sort_key=value" as we parse. size_t equal_offset = key_phrase.find('=', 0); @@ -987,13 +1082,14 @@ void Comparator::ParseKeyphrase(const std::string& key_phrase) { } std::string keyword(key_phrase.substr(0, equal_offset)); keyword = StringToLowerASCII(keyword); - KeyMap::iterator it = key_map.find(keyword); - if (key_map.end() == it) - return; // Unknown keyword. - if (it->second == RESET_ALL_DATA) + Selector selector = FindSelector(keyword); + if (selector == UNKNOWN_KEYWORD) + return; + if (selector == RESET_ALL_DATA) { ThreadData::ResetAllThreadData(); - else - SetTiebreaker(key_map[keyword], required); + return; + } + SetTiebreaker(selector, required); } bool Comparator::ParseQuery(const std::string& query) { diff --git a/base/tracked_objects.h b/base/tracked_objects.h index 1593991..a3735d2 100644 --- a/base/tracked_objects.h +++ b/base/tracked_objects.h @@ -16,8 +16,13 @@ #include "base/time.h" #include "base/synchronization/lock.h" #include "base/threading/thread_local_storage.h" +#include "base/tracking_info.h" #include "base/values.h" +#if defined(OS_WIN) +#include <mmsystem.h> // Declare timeGetTime(); +#endif + // TrackedObjects provides a database of stats about objects (generally Tasks) // that are tracked. Tracking means their birth, death, duration, birth thread, // death thread, and birth place are recorded. This data is carefully spread @@ -69,7 +74,7 @@ // any locks, as all that data is constant across the life of the process. // // The above work *could* also be done for any other object as well by calling -// TallyABirthIfActive() and TallyADeathIfActive() as appropriate. +// TallyABirthIfActive() and TallyRunOnNamedThreadIfTracking() as appropriate. // // The amount of memory used in the above data structures depends on how many // threads there are, and how many Locations of construction there are. @@ -167,6 +172,96 @@ class MessageLoop; namespace tracked_objects { //------------------------------------------------------------------------------ + +#define USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS + +#if defined(USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS) + +// TimeTicks maintains a wasteful 64 bits of data (we need less than 32), and on +// windows, a 64 bit timer is expensive to even obtain. We use a simple +// millisecond counter for most of our time values, as well as millisecond units +// of duration between those values. This means we can only handle durations +// up to 49 days (range), or 24 days (non-negative time durations). +// We only define enough methods to service the needs of the tracking classes, +// and our interfaces are modeled after what TimeTicks and TimeDelta use (so we +// can swap them into place if we want to use the "real" classes). + +class BASE_EXPORT Duration { // Similar to base::TimeDelta. + public: + Duration() : ms_(0) {} + + Duration& operator+=(const Duration& other) { + ms_ += other.ms_; + return *this; + } + + Duration operator+(const Duration& other) const { + return Duration(ms_ + other.ms_); + } + + bool operator==(const Duration& other) const { return ms_ == other.ms_; } + bool operator!=(const Duration& other) const { return ms_ != other.ms_; } + bool operator>(const Duration& other) const { return ms_ > other.ms_; } + + static Duration FromMilliseconds(int ms) { return Duration(ms); } + + int32 InMilliseconds() const { return ms_; } + + private: + friend class TrackedTime; + explicit Duration(int32 duration) : ms_(duration) {} + + // Internal time is stored directly in milliseconds. + int32 ms_; +}; + +class BASE_EXPORT TrackedTime { // Similar to base::TimeTicks. + public: + TrackedTime() : ms_(0) {} + explicit TrackedTime(const base::TimeTicks& time) + : ms_((time - base::TimeTicks()).InMilliseconds()) { + } + + static TrackedTime Now() { +#if defined(OS_WIN) + // Use lock-free accessor to 32 bit time. + // Note that TimeTicks::Now() is built on this, so we have "compatible" + // times when we down-convert a TimeTicks sample. + // TODO(jar): Surface this interface via something in base/time.h. + return TrackedTime(static_cast<int32>(::timeGetTime())); +#else + // Posix has nice cheap 64 bit times, so we just down-convert it. + return TrackedTime(base::TimeTicks::Now()); +#endif // OS_WIN + } + + Duration operator-(const TrackedTime& other) const { + return Duration(ms_ - other.ms_); + } + + TrackedTime operator+(const Duration& other) const { + return TrackedTime(ms_ + other.ms_); + } + + bool is_null() const { return ms_ == 0; } + + private: + friend class Duration; + explicit TrackedTime(int32 ms) : ms_(ms) {} + + // Internal duration is stored directly in milliseconds. + uint32 ms_; +}; + +#else + +// Just use full 64 bit time calculations, and the slower TimeTicks::Now(). +typedef base::TimeTicks TrackedTime; +typedef base::TimeDelta Duration; + +#endif // USE_FAST_TIME_CLASS_FOR_DURATION_CALCULATIONS + +//------------------------------------------------------------------------------ // For a specific thread, and a specific birth place, the collection of all // death info (with tallies for each death thread, to prevent access conflicts). class ThreadData; @@ -217,8 +312,8 @@ class BASE_EXPORT Births: public BirthOnThread { }; //------------------------------------------------------------------------------ -// Basic info summarizing multiple destructions of an object with a single -// birthplace (fixed Location). Used both on specific threads, and also used +// Basic info summarizing multiple destructions of a tracked object with a +// single birthplace (fixed Location). Used both on specific threads, and also // in snapshots when integrating assembled data. class BASE_EXPORT DeathData { @@ -233,14 +328,14 @@ class BASE_EXPORT DeathData { // Update stats for a task destruction (death) that had a Run() time of // |duration|, and has had a queueing delay of |queue_duration|. - void RecordDeath(const base::TimeDelta& queue_duration, - const base::TimeDelta& run_duration); + void RecordDeath(const Duration& queue_duration, + const Duration& run_duration); // Metrics accessors. int count() const { return count_; } - base::TimeDelta run_duration() const { return run_duration_; } + Duration run_duration() const { return run_duration_; } int AverageMsRunDuration() const; - base::TimeDelta queue_duration() const { return queue_duration_; } + Duration queue_duration() const { return queue_duration_; } int AverageMsQueueDuration() const; // Accumulate metrics from other into this. This method is never used on @@ -250,7 +345,7 @@ class BASE_EXPORT DeathData { // Simple print of internal state for use in line of HTML. void WriteHTML(std::string* output) const; - // Constructe a DictionaryValue instance containing all our stats. The caller + // Construct a DictionaryValue instance containing all our stats. The caller // assumes ownership of the returned instance. base::DictionaryValue* ToValue() const; @@ -259,8 +354,8 @@ class BASE_EXPORT DeathData { private: int count_; // Number of destructions. - base::TimeDelta run_duration_; // Sum of all Run()time durations. - base::TimeDelta queue_duration_; // Sum of all queue time durations. + Duration run_duration_; // Sum of all Run()time durations. + Duration queue_duration_; // Sum of all queue time durations. }; //------------------------------------------------------------------------------ @@ -287,13 +382,11 @@ class BASE_EXPORT Snapshot { const std::string DeathThreadName() const; int count() const { return death_data_.count(); } - base::TimeDelta run_duration() const { return death_data_.run_duration(); } + Duration run_duration() const { return death_data_.run_duration(); } + Duration queue_duration() const { return death_data_.queue_duration(); } int AverageMsRunDuration() const { return death_data_.AverageMsRunDuration(); } - base::TimeDelta queue_duration() const { - return death_data_.queue_duration(); - } int AverageMsQueueDuration() const { return death_data_.AverageMsQueueDuration(); } @@ -305,8 +398,6 @@ class BASE_EXPORT Snapshot { // The caller assumes ownership of the memory in the returned instance. base::DictionaryValue* ToValue() const; - void Add(const Snapshot& other); - private: const BirthOnThread* birth_; // Includes Location and birth_thread. const ThreadData* death_thread_; @@ -326,20 +417,23 @@ class BASE_EXPORT DataCollector { DataCollector(); ~DataCollector(); - // Add all stats from the indicated thread into our arrays. This function is - // mutex protected, and *could* be called from any threads (although current - // implementation serialized calls to Append). + // Adds all stats from the indicated thread into our arrays. This function + // uses locks at the lowest level (when accessing the underlying maps which + // could change when not locked), and can be called from any threads. void Append(const ThreadData& thread_data); // After the accumulation phase, the following accessor is used to process the - // data. + // data (i.e., sort it, filter it, etc.). Collection* collection(); - // After collection of death data is complete, we can add entries for all the - // remaining living objects. + // Adds entries for all the remaining living objects (objects that have + // tallied a birth, but have not yet tallied a matching death, and hence must + // be either running, queued up, or being held in limbo for future posting). + // This should be called after all known ThreadData instances have been + // processed using Append(). void AddListOfLivingObjects(); - // Generate a ListValue representation of the vector of snapshots. The caller + // Generates a ListValue representation of the vector of snapshots. The caller // assumes ownership of the memory in the returned instance. base::ListValue* ToValue() const; @@ -350,7 +444,8 @@ class BASE_EXPORT DataCollector { Collection collection_; // The total number of births recorded at each location for which we have not - // seen a death count. + // seen a death count. This map changes as we do Append() calls, and is later + // used by AddListOfLivingObjects() to gather up unaccounted for births. BirthCount global_birth_count_; DISALLOW_COPY_AND_ASSIGN(DataCollector); @@ -359,6 +454,9 @@ class BASE_EXPORT DataCollector { //------------------------------------------------------------------------------ // Aggregation contains summaries (totals and subtotals) of groups of Snapshot // instances to provide printing of these collections on a single line. +// We generally provide an aggregate total for the entire list, as well as +// aggregate subtotals for groups of stats (example: group of all lives that +// died on the specific thread). class BASE_EXPORT Aggregation: public DeathData { public: @@ -414,6 +512,7 @@ class BASE_EXPORT Comparator { // Imediate action keywords. RESET_ALL_DATA = -1, + UNKNOWN_KEYWORD = -2, }; explicit Comparator(); @@ -470,6 +569,10 @@ class BASE_EXPORT Comparator { // members of the tested elements. enum Selector selector_; + // Translate a path keyword into a selector. This is a slow implementation, + // but this is rarely done, and only for HTML presentations. + static Selector FindSelector(const std::string& keyword); + // For filtering into acceptable and unacceptable snapshot instance, the // following is required to be a substring of the selector_ field. std::string required_; @@ -493,16 +596,27 @@ class BASE_EXPORT Comparator { //------------------------------------------------------------------------------ // For each thread, we have a ThreadData that stores all tracking info generated // on this thread. This prevents the need for locking as data accumulates. +// We use ThreadLocalStorage to quickly identfy the current ThreadData context. +// We also have a linked list of ThreadData instances, and that list is used to +// harvest data from all existing instances. class BASE_EXPORT ThreadData { public: + // Current allowable states of the tracking system. The states can vary + // between ACTIVE and DEACTIVATED, but can never go back to UNINITIALIZED. + enum Status { + UNINITIALIZED, + ACTIVE, + DEACTIVATED, + }; + typedef std::map<Location, Births*> BirthMap; typedef std::map<const Births*, DeathData> DeathMap; // Initialize the current thread context with a new instance of ThreadData. - // This is used by all threads that have names, and can be explicitly - // set *before* any births are threads have taken place. It is generally - // only used by the message loop, which has a well defined name. + // This is used by all threads that have names, and should be explicitly + // set *before* any births on the threads have taken place. It is generally + // only used by the message loop, which has a well defined thread name. static void InitializeThreadContext(const std::string& suggested_name); // Using Thread Local Store, find the current instance for collecting data. @@ -515,33 +629,47 @@ class BASE_EXPORT ThreadData { // append to output. static void WriteHTML(const std::string& query, std::string* output); - // Constructe a ListValue instance containing all recursive results in our - // process. The caller assumes ownership of the memory in the returned - // instance. The |process_type| should become an enum, which corresponds - // to all possible process types. I'm using an int as a placeholder. - static base::Value* ToValue(int process_type); - // For a given accumulated array of results, use the comparator to sort and // subtotal, writing the results to the output. static void WriteHTMLTotalAndSubtotals( const DataCollector::Collection& match_array, const Comparator& comparator, std::string* output); - // Find (or create) a place to count births from the given location in this + // Constructs a DictionaryValue instance containing all recursive results in + // our process. The caller assumes ownership of the memory in the returned + // instance. + static base::DictionaryValue* ToValue(); + + // Finds (or creates) a place to count births from the given location in this // thread, and increment that tally. // TallyABirthIfActive will returns NULL if the birth cannot be tallied. static Births* TallyABirthIfActive(const Location& location); + // Records the end of a timed run of an object. The |completed_task| contains + // a pointer to a Births, the time_posted, and a delayed_start_time if any. + // The |start_of_run| indicates when we started to perform the run of the + // task. The delayed_start_time is non-null for tasks that were posted as + // delayed tasks, and it indicates when the task should have run (i.e., when + // it should have posted out of the timer queue, and into the work queue. + // The |end_of_run| was just obtained by a call to Now() (just after the task + // finished). It is provided as an argument to help with testing. + static void TallyRunOnNamedThreadIfTracking( + const base::TrackingInfo& completed_task, + const TrackedTime& start_of_run, + const TrackedTime& end_of_run); + // Record the end of a timed run of an object. The |birth| is the record for - // the instance, the |time_posted| and |start_of_run| are times of posting - // into a message loop queue, and of starting to perform the run of the task. + // the instance, the |time_posted| records that instant, which is presumed to + // be when the task was posted into a queue to run on a worker thread. + // The |start_of_run| is when the worker thread started to perform the run of + // the task. // The |end_of_run| was just obtained by a call to Now() (just after the task // finished). - static void TallyADeathIfActive(const Births* birth, - const base::TimeTicks& time_posted, - const base::TimeTicks& delayed_start_time, - const base::TimeTicks& start_of_run, - const base::TimeTicks& end_of_run); + static void TallyRunOnWorkerThreadIfTracking( + const Births* birth, + const TrackedTime& time_posted, + const TrackedTime& start_of_run, + const TrackedTime& end_of_run); const std::string thread_name() const { return thread_name_; } @@ -567,34 +695,34 @@ class BASE_EXPORT ThreadData { // bogus counts VERY rarely. static void ResetAllThreadData(); - // Set internal status_ to either become ACTIVE, or later, to be SHUTDOWN, + // Initializes all statics if needed (this initialization call should be made + // while we are single threaded). Returns false if unable to initialize. + static bool Initialize(); + + // Sets internal status_ to either become ACTIVE, or DEACTIVATED, // based on argument being true or false respectively. - // IF tracking is not compiled in, this function will return false. - static bool StartTracking(bool status); - static bool IsActive(); + // If tracking is not compiled in, this function will return false. + static bool InitializeAndSetTrackingStatus(bool status); + static bool tracking_status(); // Provide a time function that does nothing (runs fast) when we don't have // the profiler enabled. It will generally be optimized away when it is // ifdef'ed to be small enough (allowing the profiler to be "compiled out" of // the code). - static base::TimeTicks Now(); - - // WARNING: ONLY call this function when you are running single threaded - // (again) and all message loops and threads have terminated. Until that - // point some threads may still attempt to write into our data structures. - // Delete recursively all data structures, starting with the list of + static TrackedTime Now(); + + // Cleans up data structures, and returns statics to near pristine (mostly + // uninitialized) state. If there is any chance that other threads are still + // using the data structures, then the |leak| argument should be passed in as + // true, and the data structures (birth maps, death maps, ThreadData + // insntances, etc.) will be leaked and not deleted. If you have joined all + // threads since the time that InitializeAndSetTrackingStatus() was called, + // then you can pass in a |leak| value of false, and this function will + // delete recursively all data structures, starting with the list of // ThreadData instances. - static void ShutdownSingleThreadedCleanup(); + static void ShutdownSingleThreadedCleanup(bool leak); private: - // Current allowable states of the tracking system. The states always - // proceed towards SHUTDOWN, and never go backwards. - enum Status { - UNINITIALIZED, - ACTIVE, - SHUTDOWN, - }; - typedef std::stack<const ThreadData*> ThreadDataPool; // Worker thread construction creates a name since there is none. @@ -614,8 +742,8 @@ class BASE_EXPORT ThreadData { // Find a place to record a death on this thread. void TallyADeath(const Births& birth, - const base::TimeDelta& queue_duration, - const base::TimeDelta& duration); + const Duration& queue_duration, + const Duration& duration); // Using our lock to protect the iteration, Clear all birth and death data. void Reset(); @@ -633,15 +761,30 @@ class BASE_EXPORT ThreadData { // Link to the most recently created instance (starts a null terminated list). // The list is traversed by about:tracking when it needs to snapshot data. + // This is only accessed while list_lock_ is held. static ThreadData* all_thread_data_list_head_; // Set of ThreadData instances for use with worker threads. When a worker // thread is done (terminating), we push it into this pool. When a new worker // thread is created, we first try to re-use a ThreadData instance from the // pool, and if none are available, construct a new one. + // This is only accessed while list_lock_ is held. static ThreadDataPool* unregistered_thread_data_pool_; + // The next available thread number. This should only be accessed when the + // list_lock_ is held. + static int thread_number_counter_; + // Incarnation sequence number, indicating how many times (during unittests) + // we've either transitioned out of UNINITIALIZED, or into that state. This + // value is only accessed while the list_lock_ is held. + static int incarnation_counter_; // Protection for access to all_thread_data_list_head_, and to - // unregistered_thread_data_pool_. - static base::Lock list_lock_; + // unregistered_thread_data_pool_. This lock is leaked at shutdown. + static base::Lock* list_lock_; + + // Record of what the incarnation_counter_ was when this instance was created. + // If the incarnation_counter_ has changed, then we avoid pushing into the + // pool (this is only critical in tests which go through multiple + // incarations). + int incarnation_count_for_pool_; // We set status_ to SHUTDOWN when we shut down the tracking service. static Status status_; @@ -679,10 +822,6 @@ class BASE_EXPORT ThreadData { // writing is only done from this thread. mutable base::Lock lock_; - // The next available thread number. This should only be accessed when the - // list_lock_ is held. - static int thread_number_counter_; - DISALLOW_COPY_AND_ASSIGN(ThreadData); }; @@ -695,21 +834,17 @@ class BASE_EXPORT ThreadData { class BASE_EXPORT AutoTracking { public: AutoTracking() { - if (state_ != kNeverBeenRun) - return; - ThreadData::StartTracking(true); - state_ = kRunning; + ThreadData::Initialize(); } ~AutoTracking() { + // TODO(jar): Consider emitting a CSV dump of the data at this point. This + // should be called after the message loops have all terminated (or at least + // the main message loop is gone), so there is little chance for additional + // tasks to be Run. } private: - enum State { - kNeverBeenRun, - kRunning, - }; - static State state_; DISALLOW_COPY_AND_ASSIGN(AutoTracking); }; diff --git a/base/tracked_objects_unittest.cc b/base/tracked_objects_unittest.cc index ef88183..f09e444 100644 --- a/base/tracked_objects_unittest.cc +++ b/base/tracked_objects_unittest.cc @@ -15,15 +15,22 @@ namespace tracked_objects { class TrackedObjectsTest : public testing::Test { public: - ~TrackedObjectsTest() { - ThreadData::ShutdownSingleThreadedCleanup(); - } - + TrackedObjectsTest() { + // On entry, leak any database structures in case they are still in use by + // prior threads. + ThreadData::ShutdownSingleThreadedCleanup(true); + } + + ~TrackedObjectsTest() { + // We should not need to leak any structures we create, since we are + // single threaded, and carefully accounting for items. + ThreadData::ShutdownSingleThreadedCleanup(false); + } }; TEST_F(TrackedObjectsTest, MinimalStartupShutdown) { // Minimal test doesn't even create any tasks. - if (!ThreadData::StartTracking(true)) + if (!ThreadData::InitializeAndSetTrackingStatus(true)) return; EXPECT_FALSE(ThreadData::first()); // No activity even on this thread. @@ -38,10 +45,11 @@ TEST_F(TrackedObjectsTest, MinimalStartupShutdown) { ThreadData::DeathMap death_map; data->SnapshotDeathMap(&death_map); EXPECT_EQ(0u, death_map.size()); - ThreadData::ShutdownSingleThreadedCleanup(); + // Cleanup with no leaking. + ThreadData::ShutdownSingleThreadedCleanup(false); // Do it again, just to be sure we reset state completely. - ThreadData::StartTracking(true); + ThreadData::InitializeAndSetTrackingStatus(true); EXPECT_FALSE(ThreadData::first()); // No activity even on this thread. data = ThreadData::Get(); EXPECT_TRUE(ThreadData::first()); // Now class was constructed. @@ -57,7 +65,7 @@ TEST_F(TrackedObjectsTest, MinimalStartupShutdown) { } TEST_F(TrackedObjectsTest, TinyStartupShutdown) { - if (!ThreadData::StartTracking(true)) + if (!ThreadData::InitializeAndSetTrackingStatus(true)) return; // Instigate tracking on a single tracked object, on our thread. @@ -77,14 +85,14 @@ TEST_F(TrackedObjectsTest, TinyStartupShutdown) { EXPECT_EQ(0u, death_map.size()); // No deaths. - // Now instigate a birth, and a death. - const Births* second_birth = ThreadData::TallyABirthIfActive(location); - ThreadData::TallyADeathIfActive( - second_birth, - base::TimeTicks(), /* Bogus post_time. */ - base::TimeTicks(), /* Bogus delayed_start_time. */ - base::TimeTicks(), /* Bogus start_run_time. */ - base::TimeTicks() /* Bogus end_run_time */ ); + // Now instigate another birth, and a first death at the same location. + // TrackingInfo will call TallyABirth() during construction. + base::TimeTicks kBogusStartTime; + base::TrackingInfo pending_task(location, kBogusStartTime); + TrackedTime kBogusStartRunTime; + TrackedTime kBogusEndRunTime; + ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, kBogusStartRunTime, + kBogusEndRunTime); birth_map.clear(); data->SnapshotBirthMap(&birth_map); @@ -100,13 +108,13 @@ TEST_F(TrackedObjectsTest, TinyStartupShutdown) { } TEST_F(TrackedObjectsTest, DeathDataTest) { - if (!ThreadData::StartTracking(true)) + if (!ThreadData::InitializeAndSetTrackingStatus(true)) return; scoped_ptr<DeathData> data(new DeathData()); ASSERT_NE(data, reinterpret_cast<DeathData*>(NULL)); - EXPECT_EQ(data->run_duration(), base::TimeDelta()); - EXPECT_EQ(data->queue_duration(), base::TimeDelta()); + EXPECT_EQ(data->run_duration(), Duration()); + EXPECT_EQ(data->queue_duration(), Duration()); EXPECT_EQ(data->AverageMsRunDuration(), 0); EXPECT_EQ(data->AverageMsQueueDuration(), 0); EXPECT_EQ(data->count(), 0); @@ -114,8 +122,8 @@ TEST_F(TrackedObjectsTest, DeathDataTest) { int run_ms = 42; int queue_ms = 8; - base::TimeDelta run_duration = base::TimeDelta().FromMilliseconds(run_ms); - base::TimeDelta queue_duration = base::TimeDelta().FromMilliseconds(queue_ms); + Duration run_duration = Duration().FromMilliseconds(run_ms); + Duration queue_duration = Duration().FromMilliseconds(queue_ms); data->RecordDeath(queue_duration, run_duration); EXPECT_EQ(data->run_duration(), run_duration); EXPECT_EQ(data->queue_duration(), queue_duration); @@ -135,7 +143,7 @@ TEST_F(TrackedObjectsTest, DeathDataTest) { EXPECT_TRUE(dictionary->GetInteger("run_ms", &integer)); EXPECT_EQ(integer, 2 * run_ms); EXPECT_TRUE(dictionary->GetInteger("queue_ms", &integer)); - EXPECT_EQ(integer, 2* queue_ms); + EXPECT_EQ(integer, 2 * queue_ms); EXPECT_TRUE(dictionary->GetInteger("count", &integer)); EXPECT_EQ(integer, 2); @@ -151,20 +159,69 @@ TEST_F(TrackedObjectsTest, DeathDataTest) { EXPECT_EQ(json, birth_only_result); } +TEST_F(TrackedObjectsTest, DeactivatedBirthOnlyToValueWorkerThread) { + // Transition to Deactivated state before doing anything. + if (!ThreadData::InitializeAndSetTrackingStatus(false)) + return; + // We don't initialize system with a thread name, so we're viewed as a worker + // thread. + const int kFakeLineNumber = 173; + const char* kFile = "FixedFileName"; + const char* kFunction = "BirthOnlyToValueWorkerThread"; + Location location(kFunction, kFile, kFakeLineNumber, NULL); + Births* birth = ThreadData::TallyABirthIfActive(location); + // We should now see a NULL birth record. + EXPECT_EQ(birth, reinterpret_cast<Births*>(NULL)); + + scoped_ptr<base::Value> value(ThreadData::ToValue()); + std::string json; + base::JSONWriter::Write(value.get(), false, &json); + std::string birth_only_result = "{" + "\"list\":[" + "]" + "}"; + EXPECT_EQ(json, birth_only_result); +} + +TEST_F(TrackedObjectsTest, DeactivatedBirthOnlyToValueMainThread) { + // Start in the deactivated state. + if (!ThreadData::InitializeAndSetTrackingStatus(false)) + return; + + // Use a well named thread. + ThreadData::InitializeThreadContext("SomeMainThreadName"); + const int kFakeLineNumber = 173; + const char* kFile = "FixedFileName"; + const char* kFunction = "BirthOnlyToValueMainThread"; + Location location(kFunction, kFile, kFakeLineNumber, NULL); + // Do not delete birth. We don't own it. + Births* birth = ThreadData::TallyABirthIfActive(location); + // We expect to not get a birth record. + EXPECT_EQ(birth, reinterpret_cast<Births*>(NULL)); + + scoped_ptr<base::Value> value(ThreadData::ToValue()); + std::string json; + base::JSONWriter::Write(value.get(), false, &json); + std::string birth_only_result = "{" + "\"list\":[" + "]" + "}"; + EXPECT_EQ(json, birth_only_result); +} + TEST_F(TrackedObjectsTest, BirthOnlyToValueWorkerThread) { - if (!ThreadData::StartTracking(true)) + if (!ThreadData::InitializeAndSetTrackingStatus(true)) return; // We don't initialize system with a thread name, so we're viewed as a worker // thread. - int fake_line_number = 173; + const int kFakeLineNumber = 173; const char* kFile = "FixedFileName"; const char* kFunction = "BirthOnlyToValueWorkerThread"; - Location location(kFunction, kFile, fake_line_number, NULL); + Location location(kFunction, kFile, kFakeLineNumber, NULL); Births* birth = ThreadData::TallyABirthIfActive(location); EXPECT_NE(birth, reinterpret_cast<Births*>(NULL)); - int process_type = 3; - scoped_ptr<base::Value> value(ThreadData::ToValue(process_type)); + scoped_ptr<base::Value> value(ThreadData::ToValue()); std::string json; base::JSONWriter::Write(value.get(), false, &json); std::string birth_only_result = "{" @@ -183,28 +240,26 @@ TEST_F(TrackedObjectsTest, BirthOnlyToValueWorkerThread) { "\"line_number\":173" "}" "}" - "]," - "\"process\":3" + "]" "}"; EXPECT_EQ(json, birth_only_result); } TEST_F(TrackedObjectsTest, BirthOnlyToValueMainThread) { - if (!ThreadData::StartTracking(true)) + if (!ThreadData::InitializeAndSetTrackingStatus(true)) return; // Use a well named thread. ThreadData::InitializeThreadContext("SomeMainThreadName"); - int fake_line_number = 173; + const int kFakeLineNumber = 173; const char* kFile = "FixedFileName"; const char* kFunction = "BirthOnlyToValueMainThread"; - Location location(kFunction, kFile, fake_line_number, NULL); + Location location(kFunction, kFile, kFakeLineNumber, NULL); // Do not delete birth. We don't own it. Births* birth = ThreadData::TallyABirthIfActive(location); EXPECT_NE(birth, reinterpret_cast<Births*>(NULL)); - int process_type = 34; - scoped_ptr<base::Value> value(ThreadData::ToValue(process_type)); + scoped_ptr<base::Value> value(ThreadData::ToValue()); std::string json; base::JSONWriter::Write(value.get(), false, &json); std::string birth_only_result = "{" @@ -223,40 +278,97 @@ TEST_F(TrackedObjectsTest, BirthOnlyToValueMainThread) { "\"line_number\":173" "}" "}" - "]," - "\"process\":34" + "]" "}"; EXPECT_EQ(json, birth_only_result); } TEST_F(TrackedObjectsTest, LifeCycleToValueMainThread) { - if (!ThreadData::StartTracking(true)) + if (!ThreadData::InitializeAndSetTrackingStatus(true)) + return; + + // Use a well named thread. + ThreadData::InitializeThreadContext("SomeMainThreadName"); + const int kFakeLineNumber = 236; + const char* kFile = "FixedFileName"; + const char* kFunction = "LifeCycleToValueMainThread"; + Location location(kFunction, kFile, kFakeLineNumber, NULL); + // Do not delete birth. We don't own it. + Births* birth = ThreadData::TallyABirthIfActive(location); + EXPECT_NE(birth, reinterpret_cast<Births*>(NULL)); + + const base::TimeTicks kTimePosted = base::TimeTicks() + + base::TimeDelta::FromMilliseconds(1); + const base::TimeTicks kDelayedStartTime = base::TimeTicks(); + // TrackingInfo will call TallyABirth() during construction. + base::TrackingInfo pending_task(location, kDelayedStartTime); + pending_task.time_posted = kTimePosted; // Overwrite implied Now(). + + const TrackedTime kStartOfRun = TrackedTime() + + Duration::FromMilliseconds(5); + const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7); + ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, + kStartOfRun, kEndOfRun); + + scoped_ptr<base::Value> value(ThreadData::ToValue()); + std::string json; + base::JSONWriter::Write(value.get(), false, &json); + std::string one_line_result = "{" + "\"list\":[" + "{" + "\"birth_thread\":\"SomeMainThreadName\"," + "\"death_data\":{" + "\"count\":1," + "\"queue_ms\":4," + "\"run_ms\":2" + "}," + "\"death_thread\":\"SomeMainThreadName\"," + "\"location\":{" + "\"file_name\":\"FixedFileName\"," + "\"function_name\":\"LifeCycleToValueMainThread\"," + "\"line_number\":236" + "}" + "}" + "]" + "}"; + EXPECT_EQ(one_line_result, json); +} + +// We will deactivate tracking after the birth, and before the death, and +// demonstrate that the lifecycle is completely tallied. This ensures that +// our tallied births are matched by tallied deaths (except for when the +// task is still running, or is queued). +TEST_F(TrackedObjectsTest, LifeCycleMidDeactivatedToValueMainThread) { + if (!ThreadData::InitializeAndSetTrackingStatus(true)) return; // Use a well named thread. ThreadData::InitializeThreadContext("SomeMainThreadName"); - int fake_line_number = 236; + const int kFakeLineNumber = 236; const char* kFile = "FixedFileName"; const char* kFunction = "LifeCycleToValueMainThread"; - Location location(kFunction, kFile, fake_line_number, NULL); + Location location(kFunction, kFile, kFakeLineNumber, NULL); // Do not delete birth. We don't own it. Births* birth = ThreadData::TallyABirthIfActive(location); EXPECT_NE(birth, reinterpret_cast<Births*>(NULL)); - // TimeTicks initializers ar ein microseconds. Durations are calculated in - // milliseconds, so we need to use 1000x. - const base::TimeTicks time_posted = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(1); - const base::TimeTicks delayed_start_time = base::TimeTicks(); - const base::TimeTicks start_of_run = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(5); - const base::TimeTicks end_of_run = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(7); - ThreadData::TallyADeathIfActive(birth, time_posted, delayed_start_time, - start_of_run, end_of_run); - - int process_type = 7; - scoped_ptr<base::Value> value(ThreadData::ToValue(process_type)); + const base::TimeTicks kTimePosted = base::TimeTicks() + + base::TimeDelta::FromMilliseconds(1); + const base::TimeTicks kDelayedStartTime = base::TimeTicks(); + // TrackingInfo will call TallyABirth() during construction. + base::TrackingInfo pending_task(location, kDelayedStartTime); + pending_task.time_posted = kTimePosted; // Overwrite implied Now(). + + // Turn off tracking now that we have births. + EXPECT_TRUE(ThreadData::InitializeAndSetTrackingStatus(false)); + + const TrackedTime kStartOfRun = TrackedTime() + + Duration::FromMilliseconds(5); + const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7); + ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, + kStartOfRun, kEndOfRun); + + scoped_ptr<base::Value> value(ThreadData::ToValue()); std::string json; base::JSONWriter::Write(value.get(), false, &json); std::string one_line_result = "{" @@ -275,44 +387,132 @@ TEST_F(TrackedObjectsTest, LifeCycleToValueMainThread) { "\"line_number\":236" "}" "}" - "]," - "\"process\":7" + "]" + "}"; + EXPECT_EQ(one_line_result, json); +} + +// We will deactivate tracking before starting a life cycle, and neither +// the birth nor the death will be recorded. +TEST_F(TrackedObjectsTest, LifeCyclePreDeactivatedToValueMainThread) { + if (!ThreadData::InitializeAndSetTrackingStatus(false)) + return; + + // Use a well named thread. + ThreadData::InitializeThreadContext("SomeMainThreadName"); + const int kFakeLineNumber = 236; + const char* kFile = "FixedFileName"; + const char* kFunction = "LifeCycleToValueMainThread"; + Location location(kFunction, kFile, kFakeLineNumber, NULL); + // Do not delete birth. We don't own it. + Births* birth = ThreadData::TallyABirthIfActive(location); + EXPECT_EQ(birth, reinterpret_cast<Births*>(NULL)); + + const base::TimeTicks kTimePosted = base::TimeTicks() + + base::TimeDelta::FromMilliseconds(1); + const base::TimeTicks kDelayedStartTime = base::TimeTicks(); + // TrackingInfo will call TallyABirth() during construction. + base::TrackingInfo pending_task(location, kDelayedStartTime); + pending_task.time_posted = kTimePosted; // Overwrite implied Now(). + + const TrackedTime kStartOfRun = TrackedTime() + + Duration::FromMilliseconds(5); + const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7); + ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, + kStartOfRun, kEndOfRun); + + scoped_ptr<base::Value> value(ThreadData::ToValue()); + std::string json; + base::JSONWriter::Write(value.get(), false, &json); + std::string one_line_result = "{" + "\"list\":[" + "]" + "}"; + EXPECT_EQ(one_line_result, json); +} + +TEST_F(TrackedObjectsTest, LifeCycleToValueWorkerThread) { + if (!ThreadData::InitializeAndSetTrackingStatus(true)) + return; + + // Don't initialize thread, so that we appear as a worker thread. + // ThreadData::InitializeThreadContext("SomeMainThreadName"); + + const int kFakeLineNumber = 236; + const char* kFile = "FixedFileName"; + const char* kFunction = "LifeCycleToValueWorkerThread"; + Location location(kFunction, kFile, kFakeLineNumber, NULL); + // Do not delete birth. We don't own it. + Births* birth = ThreadData::TallyABirthIfActive(location); + EXPECT_NE(birth, reinterpret_cast<Births*>(NULL)); + + const TrackedTime kTimePosted = TrackedTime() + Duration::FromMilliseconds(1); + const TrackedTime kStartOfRun = TrackedTime() + + Duration::FromMilliseconds(5); + const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7); + ThreadData::TallyRunOnWorkerThreadIfTracking(birth, kTimePosted, + kStartOfRun, kEndOfRun); + + scoped_ptr<base::Value> value(ThreadData::ToValue()); + std::string json; + base::JSONWriter::Write(value.get(), false, &json); + std::string one_line_result = "{" + "\"list\":[" + "{" + "\"birth_thread\":\"WorkerThread-1\"," + "\"death_data\":{" + "\"count\":1," + "\"queue_ms\":4," + "\"run_ms\":2" + "}," + "\"death_thread\":\"WorkerThread-1\"," + "\"location\":{" + "\"file_name\":\"FixedFileName\"," + "\"function_name\":\"LifeCycleToValueWorkerThread\"," + "\"line_number\":236" + "}" + "}" + "]" "}"; - EXPECT_EQ(json, one_line_result); + EXPECT_EQ(one_line_result, json); } TEST_F(TrackedObjectsTest, TwoLives) { - if (!ThreadData::StartTracking(true)) + if (!ThreadData::InitializeAndSetTrackingStatus(true)) return; // Use a well named thread. ThreadData::InitializeThreadContext("SomeFileThreadName"); - int fake_line_number = 222; + const int kFakeLineNumber = 222; const char* kFile = "AnotherFileName"; const char* kFunction = "TwoLives"; - Location location(kFunction, kFile, fake_line_number, NULL); + Location location(kFunction, kFile, kFakeLineNumber, NULL); // Do not delete birth. We don't own it. Births* birth = ThreadData::TallyABirthIfActive(location); EXPECT_NE(birth, reinterpret_cast<Births*>(NULL)); - // TimeTicks initializers ar ein microseconds. Durations are calculated in - // milliseconds, so we need to use 1000x. - const base::TimeTicks time_posted = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(1); - const base::TimeTicks delayed_start_time = base::TimeTicks(); - const base::TimeTicks start_of_run = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(5); - const base::TimeTicks end_of_run = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(7); - ThreadData::TallyADeathIfActive(birth, time_posted, delayed_start_time, - start_of_run, end_of_run); - - birth = ThreadData::TallyABirthIfActive(location); - ThreadData::TallyADeathIfActive(birth, time_posted, delayed_start_time, - start_of_run, end_of_run); - - int process_type = 7; - scoped_ptr<base::Value> value(ThreadData::ToValue(process_type)); + + const base::TimeTicks kTimePosted = base::TimeTicks() + + base::TimeDelta::FromMilliseconds(1); + const base::TimeTicks kDelayedStartTime = base::TimeTicks(); + // TrackingInfo will call TallyABirth() during construction. + base::TrackingInfo pending_task(location, kDelayedStartTime); + pending_task.time_posted = kTimePosted; // Overwrite implied Now(). + + const TrackedTime kStartOfRun = TrackedTime() + + Duration::FromMilliseconds(5); + const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7); + ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, + kStartOfRun, kEndOfRun); + + // TrackingInfo will call TallyABirth() during construction. + base::TrackingInfo pending_task2(location, kDelayedStartTime); + pending_task2.time_posted = kTimePosted; // Overwrite implied Now(). + + ThreadData::TallyRunOnNamedThreadIfTracking(pending_task2, + kStartOfRun, kEndOfRun); + + scoped_ptr<base::Value> value(ThreadData::ToValue()); std::string json; base::JSONWriter::Write(value.get(), false, &json); std::string one_line_result = "{" @@ -331,44 +531,43 @@ TEST_F(TrackedObjectsTest, TwoLives) { "\"line_number\":222" "}" "}" - "]," - "\"process\":7" + "]" "}"; - EXPECT_EQ(json, one_line_result); + EXPECT_EQ(one_line_result, json); } TEST_F(TrackedObjectsTest, DifferentLives) { - if (!ThreadData::StartTracking(true)) + if (!ThreadData::InitializeAndSetTrackingStatus(true)) return; // Use a well named thread. ThreadData::InitializeThreadContext("SomeFileThreadName"); - int fake_line_number = 567; + const int kFakeLineNumber = 567; const char* kFile = "AnotherFileName"; const char* kFunction = "DifferentLives"; - Location location(kFunction, kFile, fake_line_number, NULL); - // Do not delete birth. We don't own it. - Births* birth = ThreadData::TallyABirthIfActive(location); - EXPECT_NE(birth, reinterpret_cast<Births*>(NULL)); + Location location(kFunction, kFile, kFakeLineNumber, NULL); + + const base::TimeTicks kTimePosted = base::TimeTicks() + + base::TimeDelta::FromMilliseconds(1); + const base::TimeTicks kDelayedStartTime = base::TimeTicks(); + // TrackingInfo will call TallyABirth() during construction. + base::TrackingInfo pending_task(location, kDelayedStartTime); + pending_task.time_posted = kTimePosted; // Overwrite implied Now(). + + const TrackedTime kStartOfRun = TrackedTime() + + Duration::FromMilliseconds(5); + const TrackedTime kEndOfRun = TrackedTime() + Duration::FromMilliseconds(7); + ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, + kStartOfRun, kEndOfRun); + + const int kSecondFakeLineNumber = 999; + Location second_location(kFunction, kFile, kSecondFakeLineNumber, NULL); + + // TrackingInfo will call TallyABirth() during construction. + base::TrackingInfo pending_task2(second_location, kDelayedStartTime); + pending_task2.time_posted = kTimePosted; // Overwrite implied Now(). - // TimeTicks initializers ar ein microseconds. Durations are calculated in - // milliseconds, so we need to use 1000x. - const base::TimeTicks time_posted = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(1); - const base::TimeTicks delayed_start_time = base::TimeTicks(); - const base::TimeTicks start_of_run = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(5); - const base::TimeTicks end_of_run = base::TimeTicks() + - base::TimeDelta::FromMilliseconds(7); - ThreadData::TallyADeathIfActive(birth, time_posted, delayed_start_time, - start_of_run, end_of_run); - - int second_fake_line_number = 999; - Location second_location(kFunction, kFile, second_fake_line_number, NULL); - birth = ThreadData::TallyABirthIfActive(second_location); - - int process_type = 2; - scoped_ptr<base::Value> value(ThreadData::ToValue(process_type)); + scoped_ptr<base::Value> value(ThreadData::ToValue()); std::string json; base::JSONWriter::Write(value.get(), false, &json); std::string one_line_result = "{" @@ -401,10 +600,9 @@ TEST_F(TrackedObjectsTest, DifferentLives) { "\"line_number\":999" "}" "}" - "]," - "\"process\":2" + "]" "}"; - EXPECT_EQ(json, one_line_result); + EXPECT_EQ(one_line_result, json); } } // namespace tracked_objects diff --git a/base/tracking_info.cc b/base/tracking_info.cc new file mode 100644 index 0000000..7ac4221 --- /dev/null +++ b/base/tracking_info.cc @@ -0,0 +1,23 @@ +// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "base/tracking_info.h" + +#include "base/tracked_objects.h" + +namespace base { + +TrackingInfo::TrackingInfo( + const tracked_objects::Location& posted_from, + base::TimeTicks delayed_run_time) + : birth_tally( + tracked_objects::ThreadData::TallyABirthIfActive(posted_from)), + time_posted(TimeTicks::Now()), + delayed_run_time(delayed_run_time) { +} + +TrackingInfo::~TrackingInfo() {} + +} // namespace base + diff --git a/base/tracking_info.h b/base/tracking_info.h new file mode 100644 index 0000000..0886fdf --- /dev/null +++ b/base/tracking_info.h @@ -0,0 +1,41 @@ +// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +// This is a simple struct with tracking information that is stored +// with a PendingTask (when message_loop is handling the task). +// Only the information that is shared with the profiler in tracked_objects +// are included in this structure. + + +#ifndef BASE_TRACKING_INFO_H_ +#define BASE_TRACKING_INFO_H_ + +#include "base/time.h" + +namespace tracked_objects { +class Location; +class Births; +} + +namespace base { + +// This structure is copied around by value. +struct BASE_EXPORT TrackingInfo { + TrackingInfo(const tracked_objects::Location& posted_from, + base::TimeTicks delayed_run_time); + ~TrackingInfo(); + + // Record of location and thread that the task came from. + tracked_objects::Births* birth_tally; + + // Time when the related task was posted. + base::TimeTicks time_posted; + + // The time when the task should be run. + base::TimeTicks delayed_run_time; +}; + +} // namespace base + +#endif // BASE_TRACKING_INFO_H_ diff --git a/chrome/browser/browser_about_handler.cc b/chrome/browser/browser_about_handler.cc index 8d005b5..16d2dcf 100644 --- a/chrome/browser/browser_about_handler.cc +++ b/chrome/browser/browser_about_handler.cc @@ -145,11 +145,9 @@ const char* const kChromePaths[] = { chrome::kChromeUITCMallocHost, chrome::kChromeUITermsHost, chrome::kChromeUITracingHost, + chrome::kChromeUITrackingHost, chrome::kChromeUIVersionHost, chrome::kChromeUIWorkersHost, -#if defined(TRACK_ALL_TASK_OBJECTS) - chrome::kChromeUITrackingHost, -#endif #if defined(OS_WIN) chrome::kChromeUIConflictsHost, #endif @@ -184,10 +182,8 @@ const char* const kAboutSourceNames[] = { chrome::kChromeUIStatsHost, chrome::kChromeUITaskManagerHost, chrome::kChromeUITermsHost, - chrome::kChromeUIVersionHost, -#if defined(TRACK_ALL_TASK_OBJECTS) chrome::kChromeUITrackingHost, -#endif + chrome::kChromeUIVersionHost, #if defined(USE_TCMALLOC) chrome::kChromeUITCMallocHost, #endif @@ -889,7 +885,6 @@ void AboutMemory(const std::string& path, AboutSource* source, int request_id) { } } -#if defined(TRACK_ALL_TASK_OBJECTS) static std::string AboutTracking(const std::string& query) { std::string unescaped_title("About Tracking"); if (!query.empty()) { @@ -903,7 +898,6 @@ static std::string AboutTracking(const std::string& query) { AppendFooter(&data); return data; } -#endif // TRACK_ALL_TASK_OBJECTS // Handler for filling in the "about:stats" page, as called by the browser's // About handler processing. @@ -1474,10 +1468,8 @@ void AboutSource::StartDataRequest(const std::string& path, #endif } else if (host == chrome::kChromeUIStatsHost) { response = AboutStats(path); -#if defined(TRACK_ALL_TASK_OBJECTS) } else if (host == chrome::kChromeUITrackingHost) { response = AboutTracking(path); -#endif #if defined(USE_TCMALLOC) } else if (host == chrome::kChromeUITCMallocHost) { response = AboutTcmalloc(); diff --git a/chrome/browser/chrome_browser_main.cc b/chrome/browser/chrome_browser_main.cc index 4844237..d7cd5b1 100644 --- a/chrome/browser/chrome_browser_main.cc +++ b/chrome/browser/chrome_browser_main.cc @@ -1223,6 +1223,14 @@ int ChromeBrowserMainParts::PreMainMessageLoopRunImpl() { browser_process_.reset(new BrowserProcessImpl(parsed_command_line())); } + if (parsed_command_line().HasSwitch(switches::kEnableTracking)) { + // User wants to override default tracking status. + std::string flag = + parsed_command_line().GetSwitchValueASCII(switches::kEnableTracking); + bool enabled = flag.compare("0") != 0; + tracked_objects::ThreadData::InitializeAndSetTrackingStatus(enabled); + } + // This forces the TabCloseableStateWatcher to be created and, on chromeos, // register for the notifications it needs to track the closeable state of // tabs. diff --git a/chrome/browser/chrome_browser_main.h b/chrome/browser/chrome_browser_main.h index 13f0675..9e386ad 100644 --- a/chrome/browser/chrome_browser_main.h +++ b/chrome/browser/chrome_browser_main.h @@ -122,12 +122,10 @@ class ChromeBrowserMainParts : public content::BrowserMainParts { // it is destroyed last. scoped_ptr<ShutdownWatcherHelper> shutdown_watcher_; -#if defined(TRACK_ALL_TASK_OBJECTS) // Creating this object starts tracking the creation and deletion of Task // instance. This MUST be done before main_message_loop, so that it is // destroyed after the main_message_loop. tracked_objects::AutoTracking tracking_objects_; -#endif // Statistical testing infrastructure for the entire browser. NULL until // SetupMetricsAndFieldTrials is called. diff --git a/chrome/common/chrome_switches.cc b/chrome/common/chrome_switches.cc index 06c120b..e4db0c6f 100644 --- a/chrome/common/chrome_switches.cc +++ b/chrome/common/chrome_switches.cc @@ -519,6 +519,12 @@ const char kDisablePanels[] = "disable-panels"; // Enables speculative TCP/IP preconnection. const char kEnablePreconnect[] = "enable-preconnect"; +// Controls the support for SDCH filtering (dictionary based expansion of +// content). By default SDCH filtering is enabled. To disable SDCH filtering, +// use "--enable-sdch=0" as command line argument. SDCH is currently only +// supported server-side for searches on google.com. +const char kEnableSdch[] = "enable-sdch"; + // Enables the IsSearchProviderInstalled and InstallSearchProvider with an // extra parameter to indicate if the provider should be the default. const char kEnableSearchProviderApiV2[] = "enable-search-provider-api-v2"; @@ -539,21 +545,28 @@ const char kEnableSyncOAuth[] = "enable-sync-oauth"; const char kEnableSyncSearchEngines[] = "enable-sync-search-engines"; // Enables syncing browser sessions. -const char kEnableSyncTabs[] = "enable-sync-tabs"; +const char kEnableSyncTabs[] = "enable-sync-tabs"; // Enables syncing browser sessions for other synced clients. const char kEnableSyncTabsForOtherClients[] = "enable-sync-tabs-for-other-clients"; // Enable syncing app notifications. -const char kEnableSyncAppNotifications[] = "enable-sync-app-notifications"; +const char kEnableSyncAppNotifications[] = "enable-sync-app-notifications"; // Enables context menu for selecting groups of tabs. -const char kEnableTabGroupsContextMenu[] = "enable-tab-groups-context-menu"; +const char kEnableTabGroupsContextMenu[] = "enable-tab-groups-context-menu"; // Enables the "synced bookmarks" folder. const char kEnableSyncedBookmarksFolder[] = "enable-synced-bookmarks-folder"; +// Enables tracking of tasks in profiler for viewing via about:tracking. +// To predominantly disable tracking (profiling), use the command line switch: +// --enable-tracking=0 +// Some tracking will still take place at startup, but it will be turned off +// during chrome_browser_main. +const char kEnableTracking[] = "enable-tracking"; + // Spawns threads to watch for excessive delays in specified message loops. // User should set breakpoints on Alarm() to examine problematic thread. // @@ -963,12 +976,6 @@ const char kSbDisableAutoUpdate[] = "safebrowsing-disable-auto-update"; const char kSbDisableDownloadProtection[] = "safebrowsing-disable-download-protection"; -// Controls the support for SDCH filtering (dictionary based expansion of -// content). By default SDCH filtering is enabled. To disable SDCH filtering, -// use "--enable-sdch=0" as command line argument. SDCH is currently only -// supported server-side for searches on google.com. -const char kEnableSdch[] = "enable-sdch"; - // Enables the showing of an info-bar instructing user they can search directly // from the omnibox. const char kSearchInOmniboxHint[] = "search-in-omnibox-hint"; diff --git a/chrome/common/chrome_switches.h b/chrome/common/chrome_switches.h index 19a09d8..31bee61 100644 --- a/chrome/common/chrome_switches.h +++ b/chrome/common/chrome_switches.h @@ -148,6 +148,7 @@ extern const char kEnableNTPBookmarkFeatures[]; extern const char kDisablePanels[]; extern const char kEnablePreconnect[]; extern const char kEnableResourceContentSettings[]; +extern const char kEnableSdch[]; extern const char kEnableSearchProviderApiV2[]; extern const char kEnableShortcutsProvider[]; extern const char kEnableSmoothScrolling[]; @@ -160,6 +161,7 @@ extern const char kEnableSyncTabs[]; extern const char kEnableSyncTabsForOtherClients[]; extern const char kEnableSyncAppNotifications[]; extern const char kEnableSyncedBookmarksFolder[]; +extern const char kEnableTracking[]; extern const char kEnableTabGroupsContextMenu[]; extern const char kEnableTopSites[]; extern const char kEnableWatchdog[]; @@ -262,7 +264,6 @@ extern const char kSbInfoURLPrefix[]; extern const char kSbMacKeyURLPrefix[]; extern const char kSbDisableAutoUpdate[]; extern const char kSbDisableDownloadProtection[]; -extern const char kEnableSdch[]; extern const char kSearchInOmniboxHint[]; extern const char kServiceAccountLsid[]; extern const char kShowAutofillTypePredictions[]; diff --git a/content/browser/browser_main_loop.cc b/content/browser/browser_main_loop.cc index 6d49467..8c2d58f 100644 --- a/content/browser/browser_main_loop.cc +++ b/content/browser/browser_main_loop.cc @@ -292,10 +292,7 @@ void BrowserMainLoop::InitializeMainThread() { const char* kThreadName = "CrBrowserMain"; base::PlatformThread::SetName(kThreadName); main_message_loop_->set_thread_name(kThreadName); - -#if defined(TRACK_ALL_TASK_OBJECTS) tracked_objects::ThreadData::InitializeThreadContext(kThreadName); -#endif // TRACK_ALL_TASK_OBJECTS // Register the main thread by instantiating it, but don't call any methods. main_thread_.reset(new BrowserThreadImpl(BrowserThread::UI, diff --git a/tools/heapcheck/suppressions.txt b/tools/heapcheck/suppressions.txt index 5fa51dd..08cfe7d 100644 --- a/tools/heapcheck/suppressions.txt +++ b/tools/heapcheck/suppressions.txt @@ -193,6 +193,23 @@ fun:base::LeakyLazyInstanceTraits::New fun:base::LazyInstance::Pointer } +{ + Intentional leak in object tracking statics to avoid shutdown race + Heapcheck:Leak + ... + fun:tracked_objects::ThreadData::Initialize* +} +{ + Intentional leak in object tracking of thread context to avoid shutdown race + Heapcheck:Leak + fun:tracked_objects::ThreadData::Get +} +{ + Intentional leak of task birth and death data to avoid shutdown race + Heapcheck:Leak + ... + fun:tracked_objects::ThreadData::TallyA* +} #----------------------------------------------------------------------- diff --git a/tools/valgrind/tsan/suppressions_mac.txt b/tools/valgrind/tsan/suppressions_mac.txt index 88d5c46..97336f2 100644 --- a/tools/valgrind/tsan/suppressions_mac.txt +++ b/tools/valgrind/tsan/suppressions_mac.txt @@ -167,6 +167,13 @@ fun:base::SharedMemory::CreateNamed } +{ + Benign race to access status during TrackedObject unittests + ThreadSanitizer:Race + ... + fun:tracked_objects::ThreadData::ShutdownSingleThreadedCleanup +} + #----------------------------------------------------------------------- # 3. Suppressions for real chromium bugs that are not yet fixed. # These should all be in chromium's bug tracking system (but a few aren't yet). |