[Tracing Clock Sync] Implement clock sync in Chrome

This CL implements tracing clock sync in Chrome.
PowerTracingAgent is the first example.

Design doc: https://goo.gl/8Vy6qX

BUG=542390

Review URL: https://codereview.chromium.org/1526883005

Cr-Commit-Position: refs/heads/master@{#366429}

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<unsigned int>(0))

base/trace_event/tracing_agent.h

@@ -32,8 +32,8 @@ class BASE_EXPORT TracingAgent {
       const scoped_refptr<base::RefCountedString>& events_str_ptr)>;
   using RecordClockSyncMarkerCallback = base::Callback<void(
       int sync_id,
-      const TimeTicks& sync_ts,
-      const TimeTicks& sync_end_ts)>;
+      const TimeTicks& issue_ts,
+      const TimeTicks& issue_end_ts)>;
 
   virtual ~TracingAgent();
 

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 = "";

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();
 

content/browser/tracing/power_tracing_agent.cc

@@ -23,7 +23,7 @@ PowerTracingAgent* PowerTracingAgent::GetInstance() {
   return base::Singleton<PowerTracingAgent>::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<base::RefCountedString>& 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

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<base::RefCountedString>& result);
 
+  void TraceOnThread();
   void FlushOnThread(const StopAgentTracingCallback& callback);
+  void RecordClockSyncMarkerOnThread(
+      int sync_id,
+      const RecordClockSyncMarkerCallback& callback);
 
+  base::Thread thread_;
   scoped_ptr<BattorPowerTraceProvider> battor_trace_provider_;
-  bool is_tracing_;
 
   DISALLOW_COPY_AND_ASSIGN(PowerTracingAgent);
 };

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(

content/browser/tracing/tracing_controller_impl.h

@@ -10,6 +10,7 @@
 #include <vector>
 
 #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<scoped_refptr<TraceMessageFilter>> TraceMessageFilterSet;
   TraceMessageFilterSet trace_message_filters_;
@@ -201,6 +208,9 @@ class TracingControllerImpl
 
   StartTracingDoneCallback start_tracing_done_callback_;
   std::vector<base::trace_event::TracingAgent*> additional_tracing_agents_;
+  int clock_sync_id_;
+  int pending_clock_sync_ack_count_;
+  base::OneShotTimer clock_sync_timer_;
 
   bool is_tracing_;
   bool is_monitoring_;