[Tracing Clock Sync] Implement clock sync in Chrome

content/browser/tracing/power_tracing_agent.cc

 // Copyright 2015 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/lazy_instance.h"
 #include "base/memory/singleton.h"
 #include "base/trace_event/trace_event_impl.h"
 #include "content/browser/tracing/battor_power_trace_provider.h"
 #include "content/browser/tracing/power_tracing_agent.h"
 #include "content/public/browser/browser_thread.h"
 
 namespace content {
 
 namespace {
 
 const char kPowerTracingAgentName[] = "battor";
 const char kPowerTraceLabel[] = "powerTraceAsString";
 
 }  // namespace
 
 // static
 PowerTracingAgent* PowerTracingAgent::GetInstance() {
   return base::Singleton<PowerTracingAgent>::get();
 }
 
-PowerTracingAgent::PowerTracingAgent() : is_tracing_(false) {
+PowerTracingAgent::PowerTracingAgent() : thread_("PowerTracingAgentThread") {
   battor_trace_provider_.reset(new BattorPowerTraceProvider());
+  thread_.Start();

[oystein (OOO til 10th of July), 2015/12/16 02:10:05]

I'm not sure if the lifespan of the thread should be tied to the lifespan of the
singleton like this. Can we tie it to the lifespan of the tracing session
instead? I.e. start it when we start tracing, stop it when we end tracing.

[Zhen Wang, 2015/12/16 23:49:12]

If stopping the thread when we end tracing, thread_.Stop() will be called on the
UI thread. It will fail the check to allow IO. See the stack below:

#0 0x7f71320151be base::debug::StackTrace::StackTrace()
#1 0x7f713206f17f logging::LogMessage::~LogMessage()
#2 0x7f713216c76f base::ThreadRestrictions::AssertIOAllowed()
#3 0x7f713214f7d4 base::PlatformThread::Join()
#4 0x7f7132161fca base::Thread::Stop()
#5 0x7f7137fa9e8b content::PowerTracingAgent::OnStopTracingDone()

Is there a way to get around this? I see EtwSystemEventConsumer stops the thread
on the UI thread, why can it do that?
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/tr...

 }
 
 PowerTracingAgent::~PowerTracingAgent() {}
 
 std::string PowerTracingAgent::GetTracingAgentName() {
   return kPowerTracingAgentName;
 }
 
 std::string PowerTracingAgent::GetTraceEventLabel() {
   return kPowerTraceLabel;
 }
 
 bool PowerTracingAgent::StartAgentTracing(
     const base::trace_event::TraceConfig& trace_config) {
-  // Tracing session already in progress.
-  if (is_tracing_)
-    return false;
+  DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  DCHECK(thread_.IsRunning());
 
-  // 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_.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);
 }
 
+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);
   scoped_refptr<base::RefCountedString> result =
       base::RefCountedString::TakeString(&battor_logs);
   BrowserThread::PostTask(
       BrowserThread::UI, FROM_HERE,
       base::Bind(&PowerTracingAgent::OnStopTracingDone,
                  base::Unretained(this),
                  callback,
                  result));
 }
 
 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());
-  // TODO(zhenw): implement explicit clock sync.
+
+  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());
+
+  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