diff --git a/base/trace_event/common/trace_event_common.h b/base/trace_event/common/trace_event_common.h index 72202f3cc16e89..a266cd53dabce5 100644 --- a/base/trace_event/common/trace_event_common.h +++ b/base/trace_event/common/trace_event_common.h @@ -926,6 +926,17 @@ name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \ arg1_val, arg2_name, arg2_val) +// Records a clock sync event. +#define TRACE_EVENT_CLOCK_SYNC_RECEIVER(sync_id) \ + INTERNAL_TRACE_EVENT_ADD( \ + TRACE_EVENT_PHASE_CLOCK_SYNC, "__metadata", "clock_sync", \ + TRACE_EVENT_FLAG_NONE, "sync_id", sync_id) +#define TRACE_EVENT_CLOCK_SYNC_ISSUER(sync_id, issue_ts, issue_end_ts) \ + INTERNAL_TRACE_EVENT_ADD_WITH_TIMESTAMP( \ + TRACE_EVENT_PHASE_CLOCK_SYNC, "__metadata", "clock_sync", \ + issue_end_ts.ToInternalValue(), TRACE_EVENT_FLAG_NONE, \ + "sync_id", sync_id, "issue_ts", issue_ts.ToInternalValue()) + // Macros to track the life time and value of arbitrary client objects. // See also TraceTrackableObject. #define TRACE_EVENT_OBJECT_CREATED_WITH_ID(category_group, name, id) \ @@ -1013,6 +1024,7 @@ #define TRACE_EVENT_PHASE_DELETE_OBJECT ('D') #define TRACE_EVENT_PHASE_MEMORY_DUMP ('v') #define TRACE_EVENT_PHASE_MARK ('R') +#define TRACE_EVENT_PHASE_CLOCK_SYNC ('c') // Flags for changing the behavior of TRACE_EVENT_API_ADD_TRACE_EVENT. #define TRACE_EVENT_FLAG_NONE (static_cast(0)) diff --git a/base/trace_event/tracing_agent.h b/base/trace_event/tracing_agent.h index 05f44a6ee9c049..f8ca78e92dbd07 100644 --- a/base/trace_event/tracing_agent.h +++ b/base/trace_event/tracing_agent.h @@ -32,8 +32,8 @@ class BASE_EXPORT TracingAgent { const scoped_refptr& events_str_ptr)>; using RecordClockSyncMarkerCallback = base::Callback; + const TimeTicks& issue_ts, + const TimeTicks& issue_end_ts)>; virtual ~TracingAgent(); diff --git a/content/browser/tracing/battor_power_trace_provider.cc b/content/browser/tracing/battor_power_trace_provider.cc index c4c90bdda26999..41e991103817e8 100644 --- a/content/browser/tracing/battor_power_trace_provider.cc +++ b/content/browser/tracing/battor_power_trace_provider.cc @@ -22,6 +22,8 @@ bool BattorPowerTraceProvider::StopTracing() { return false; } +void BattorPowerTraceProvider::RecordClockSyncMarker(int sync_id) {} + void BattorPowerTraceProvider::GetLog(std::string* log_str) { // Get logs from battor. *log_str = ""; diff --git a/content/browser/tracing/battor_power_trace_provider.h b/content/browser/tracing/battor_power_trace_provider.h index 26ab3e01e30818..8a9a5b5e8908c2 100644 --- a/content/browser/tracing/battor_power_trace_provider.h +++ b/content/browser/tracing/battor_power_trace_provider.h @@ -13,13 +13,14 @@ namespace content { // This class handles the connection with the battor h/w using // chrome serial port interfaces. -// TODO (aschulman) port over battor C code. +// TODO(charliea): port over battor C code. class BattorPowerTraceProvider { public: BattorPowerTraceProvider(); bool IsConnected(); bool StartTracing(); bool StopTracing(); + void RecordClockSyncMarker(int sync_id); void GetLog(std::string* log_str); ~BattorPowerTraceProvider(); diff --git a/content/browser/tracing/power_tracing_agent.cc b/content/browser/tracing/power_tracing_agent.cc index 6be153a81759bc..6bf47e66bd2993 100644 --- a/content/browser/tracing/power_tracing_agent.cc +++ b/content/browser/tracing/power_tracing_agent.cc @@ -23,7 +23,7 @@ PowerTracingAgent* PowerTracingAgent::GetInstance() { return base::Singleton::get(); } -PowerTracingAgent::PowerTracingAgent() : is_tracing_(false) { +PowerTracingAgent::PowerTracingAgent() : thread_("PowerTracingAgentThread") { battor_trace_provider_.reset(new BattorPowerTraceProvider()); } @@ -39,45 +39,57 @@ std::string PowerTracingAgent::GetTraceEventLabel() { bool PowerTracingAgent::StartAgentTracing( const base::trace_event::TraceConfig& trace_config) { - // Tracing session already in progress. - if (is_tracing_) + DCHECK_CURRENTLY_ON(BrowserThread::UI); + + // TODO(charliea): When system tracing is enabled in about://tracing, it will + // trigger power tracing. We need a way of checking if BattOr is connected. + // Currently, IsConnected() always returns false, so that we do not include + // BattOr trace until it is hooked up. + if (!battor_trace_provider_->IsConnected()) return false; - // TODO(prabhur) Start tracing probably needs to be done in a - // separate thread since it involves talking to the h/w. - // Revisit once battor h/w communication is enabled. - is_tracing_ = battor_trace_provider_->StartTracing(); - return is_tracing_; + thread_.Start(); + + thread_.task_runner()->PostTask( + FROM_HERE, + base::Bind(&PowerTracingAgent::TraceOnThread, base::Unretained(this))); + return true; } void PowerTracingAgent::StopAgentTracing( const StopAgentTracingCallback& callback) { - // No tracing session in progress. - if (!is_tracing_) - return; + DCHECK_CURRENTLY_ON(BrowserThread::UI); + DCHECK(thread_.IsRunning()); - // Stop tracing & collect logs. - BrowserThread::PostTask( - BrowserThread::UI, FROM_HERE, - base::Bind(&PowerTracingAgent::FlushOnThread, - base::Unretained(this), + thread_.task_runner()->PostTask( + FROM_HERE, + base::Bind(&PowerTracingAgent::FlushOnThread, base::Unretained(this), callback)); } void PowerTracingAgent::OnStopTracingDone( const StopAgentTracingCallback& callback, const scoped_refptr& result) { - is_tracing_ = false; + DCHECK_CURRENTLY_ON(BrowserThread::UI); + // Pass the serialized events. callback.Run(GetTracingAgentName(), GetTraceEventLabel(), result); + + // Stop the power tracing agent thread on file thread. + BrowserThread::PostTask( + BrowserThread::FILE, FROM_HERE, + base::Bind(&base::Thread::Stop, base::Unretained(&thread_))); +} + +void PowerTracingAgent::TraceOnThread() { + DCHECK(thread_.task_runner()->BelongsToCurrentThread()); + battor_trace_provider_->StartTracing(); } void PowerTracingAgent::FlushOnThread( const StopAgentTracingCallback& callback) { - // Pass the result to the UI Thread. + DCHECK(thread_.task_runner()->BelongsToCurrentThread()); - // TODO(prabhur) StopTracing & GetLog need to be called on a - // separate thread depending on how BattorPowerTraceProvider is implemented. battor_trace_provider_->StopTracing(); std::string battor_logs; battor_trace_provider_->GetLog(&battor_logs); @@ -92,15 +104,36 @@ void PowerTracingAgent::FlushOnThread( } bool PowerTracingAgent::SupportsExplicitClockSync() { - // TODO(zhenw): return true after implementing explicit clock sync. - return false; + return true; } void PowerTracingAgent::RecordClockSyncMarker( int sync_id, const RecordClockSyncMarkerCallback& callback) { + DCHECK_CURRENTLY_ON(BrowserThread::UI); + DCHECK(SupportsExplicitClockSync()); + + thread_.task_runner()->PostTask( + FROM_HERE, + base::Bind(&PowerTracingAgent::RecordClockSyncMarkerOnThread, + base::Unretained(this), + sync_id, + callback)); +} + +void PowerTracingAgent::RecordClockSyncMarkerOnThread( + int sync_id, + const RecordClockSyncMarkerCallback& callback) { + DCHECK(thread_.task_runner()->BelongsToCurrentThread()); DCHECK(SupportsExplicitClockSync()); - // TODO(zhenw): implement explicit clock sync. + + base::TimeTicks issue_ts = base::TimeTicks::Now(); + battor_trace_provider_->RecordClockSyncMarker(sync_id); + base::TimeTicks issue_end_ts = base::TimeTicks::Now(); + + BrowserThread::PostTask( + BrowserThread::UI, FROM_HERE, + base::Bind(callback, sync_id, issue_ts, issue_end_ts)); } } // namespace content diff --git a/content/browser/tracing/power_tracing_agent.h b/content/browser/tracing/power_tracing_agent.h index d72b1cb3f57c17..e690faff895bcb 100644 --- a/content/browser/tracing/power_tracing_agent.h +++ b/content/browser/tracing/power_tracing_agent.h @@ -48,10 +48,14 @@ class PowerTracingAgent : public base::trace_event::TracingAgent { void OnStopTracingDone(const StopAgentTracingCallback& callback, const scoped_refptr& result); + void TraceOnThread(); void FlushOnThread(const StopAgentTracingCallback& callback); + void RecordClockSyncMarkerOnThread( + int sync_id, + const RecordClockSyncMarkerCallback& callback); + base::Thread thread_; scoped_ptr battor_trace_provider_; - bool is_tracing_; DISALLOW_COPY_AND_ASSIGN(PowerTracingAgent); }; diff --git a/content/browser/tracing/tracing_controller_impl.cc b/content/browser/tracing/tracing_controller_impl.cc index 33c236117761a0..b119b011b98ea5 100644 --- a/content/browser/tracing/tracing_controller_impl.cc +++ b/content/browser/tracing/tracing_controller_impl.cc @@ -49,6 +49,8 @@ const char kChromeTracingAgentName[] = "chrome"; const char kETWTracingAgentName[] = "etw"; const char kChromeTraceLabel[] = "traceEvents"; +const int kIssueClockSyncTimeout = 30; + std::string GetNetworkTypeString() { switch (net::NetworkChangeNotifier::GetConnectionType()) { case net::NetworkChangeNotifier::CONNECTION_ETHERNET: @@ -148,6 +150,8 @@ TracingControllerImpl::TracingControllerImpl() approximate_event_count_(0), pending_memory_dump_ack_count_(0), failed_memory_dump_count_(0), + clock_sync_id_(0), + pending_clock_sync_ack_count_(0), is_tracing_(false), is_monitoring_(false) { base::trace_event::MemoryDumpManager::GetInstance()->Initialize( @@ -287,6 +291,20 @@ bool TracingControllerImpl::StopTracing( return false; trace_data_sink_ = trace_data_sink; + + // Issue clock sync marker before actually stopping tracing. + // StopTracingAfterClockSync() will be called after clock sync is done. + IssueClockSyncMarker(); + + return true; +} + +void TracingControllerImpl::StopTracingAfterClockSync() { + DCHECK_CURRENTLY_ON(BrowserThread::UI); + + // |pending_clock_sync_ack_count_| could be non-zero if clock sync times out. + pending_clock_sync_ack_count_ = 0; + // Disable local trace early to avoid traces during end-tracing process from // interfering with the process. base::Closure on_stop_tracing_done_callback = base::Bind( @@ -295,7 +313,6 @@ bool TracingControllerImpl::StopTracing( base::Bind(&TracingControllerImpl::SetDisabledOnFileThread, base::Unretained(this), on_stop_tracing_done_callback)); - return true; } void TracingControllerImpl::OnStopTracingDone() { @@ -913,19 +930,67 @@ void TracingControllerImpl::StopAgentTracing( } bool TracingControllerImpl::SupportsExplicitClockSync() { - // TODO(zhenw): return true after implementing explicit clock sync. - return false; + return true; } void TracingControllerImpl::RecordClockSyncMarker( int sync_id, const RecordClockSyncMarkerCallback& callback) { DCHECK(SupportsExplicitClockSync()); - // TODO(zhenw): implement explicit clock sync. + + TRACE_EVENT_CLOCK_SYNC_RECEIVER(sync_id); +} + +int TracingControllerImpl::GetUniqueClockSyncID() { + DCHECK_CURRENTLY_ON(BrowserThread::UI); + // There is no need to lock because this function only runs on UI thread. + return ++clock_sync_id_; } void TracingControllerImpl::IssueClockSyncMarker() { - // TODO(zhenw): implement explicit clock sync. + DCHECK_CURRENTLY_ON(BrowserThread::UI); + DCHECK(pending_clock_sync_ack_count_ == 0); + + for (const auto& it : additional_tracing_agents_) { + if (it->SupportsExplicitClockSync()) { + it->RecordClockSyncMarker( + GetUniqueClockSyncID(), + base::Bind(&TracingControllerImpl::OnClockSyncMarkerRecordedByAgent, + base::Unretained(this))); + pending_clock_sync_ack_count_++; + } + } + + // If no clock sync is needed, stop tracing right away. Otherwise, schedule + // to stop tracing after timeout. + if (pending_clock_sync_ack_count_ == 0) { + StopTracingAfterClockSync(); + } else { + clock_sync_timer_.Start( + FROM_HERE, + base::TimeDelta::FromSeconds(kIssueClockSyncTimeout), + this, + &TracingControllerImpl::StopTracingAfterClockSync); + } +} + +void TracingControllerImpl::OnClockSyncMarkerRecordedByAgent( + int sync_id, + const base::TimeTicks& issue_ts, + const base::TimeTicks& issue_end_ts) { + DCHECK_CURRENTLY_ON(BrowserThread::UI); + + TRACE_EVENT_CLOCK_SYNC_ISSUER(sync_id, issue_ts, issue_end_ts); + + // Timer is not running means that clock sync already timed out. + if (!clock_sync_timer_.IsRunning()) + return; + + // Stop tracing only if all agents report back. + if(--pending_clock_sync_ack_count_ == 0) { + clock_sync_timer_.Stop(); + StopTracingAfterClockSync(); + } } void TracingControllerImpl::RequestGlobalMemoryDump( diff --git a/content/browser/tracing/tracing_controller_impl.h b/content/browser/tracing/tracing_controller_impl.h index 5d1479a9029482..92ff739ad884b4 100644 --- a/content/browser/tracing/tracing_controller_impl.h +++ b/content/browser/tracing/tracing_controller_impl.h @@ -10,6 +10,7 @@ #include #include "base/lazy_instance.h" +#include "base/time/time.h" #include "base/trace_event/memory_dump_manager.h" #include "base/trace_event/tracing_agent.h" #include "content/public/browser/tracing_controller.h" @@ -164,6 +165,7 @@ class TracingControllerImpl void OnStartAgentTracingDone( const base::trace_event::TraceConfig& trace_config, const StartTracingDoneCallback& callback); + void StopTracingAfterClockSync(); void OnStopTracingDone(); void OnStartMonitoringDone( const base::trace_event::TraceConfig& trace_config, @@ -172,8 +174,13 @@ class TracingControllerImpl void OnMonitoringStateChanged(bool is_monitoring); + int GetUniqueClockSyncID(); // Issue clock sync markers to the tracing agents. void IssueClockSyncMarker(); + void OnClockSyncMarkerRecordedByAgent( + int sync_id, + const base::TimeTicks& issue_ts, + const base::TimeTicks& issue_end_ts); typedef std::set> TraceMessageFilterSet; TraceMessageFilterSet trace_message_filters_; @@ -201,6 +208,9 @@ class TracingControllerImpl StartTracingDoneCallback start_tracing_done_callback_; std::vector additional_tracing_agents_; + int clock_sync_id_; + int pending_clock_sync_ack_count_; + base::OneShotTimer clock_sync_timer_; bool is_tracing_; bool is_monitoring_;