Sampling profiling thread should be joined in a FILE thread

Sampling profiling thread should be joined in a FILE thread

BUG=271439
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=243129

[haraken, 2013-12-12 04:22:13]

PTAL

https://codereview.chromium.org/105893004/diff/1/content/browser/tracing/trac...
File content/browser/tracing/tracing_controller_impl.cc (right):

https://codereview.chromium.org/105893004/diff/1/content/browser/tracing/trac...
content/browser/tracing/tracing_controller_impl.cc:158:
TraceLog::GetInstance()->SetEnabled(

We need to dispatch SetEnabled in the FILE thread, because the thread that stops
the sampling thread must be the same as the thread that creates the sampling
thread. Otherwise, we will hit the ASSERT in Platform::Stop() in SetDisabled().

[dsinclair, 2013-12-12 15:14:04]

https://codereview.chromium.org/105893004/diff/1/content/browser/tracing/trac...
File content/browser/tracing/tracing_controller_impl.cc (right):

https://codereview.chromium.org/105893004/diff/1/content/browser/tracing/trac...
content/browser/tracing/tracing_controller_impl.cc:156:
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
Should we add logic in here that, if we aren't on the FILE thread it does a
PostTask to the correct thread?  Or, rename the method to be
SetEnabledOnFileThread to make the threading requirement specific?

[haraken, 2013-12-13 03:27:36]

Thanks for review! PTAL.

https://codereview.chromium.org/105893004/diff/1/content/browser/tracing/trac...
File content/browser/tracing/tracing_controller_impl.cc (right):

https://codereview.chromium.org/105893004/diff/1/content/browser/tracing/trac...
content/browser/tracing/tracing_controller_impl.cc:156:
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
On 2013/12/12 15:14:04, dsinclair wrote:
> Should we add logic in here that, if we aren't on the FILE thread it does a
> PostTask to the correct thread?  Or, rename the method to be
> SetEnabledOnFileThread to make the threading requirement specific?

Renamed the method to SetEnabledOnFileThread and SetDisabledOnFileThread.

[dsinclair, 2013-12-13 03:35:07]

lgtm

[commit-bot: I haz the power, 2013-12-13 03:36:47]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/20001

[commit-bot: I haz the power, 2013-12-13 03:55:11]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[commit-bot: I haz the power, 2013-12-13 04:02:27]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/40001

[commit-bot: I haz the power, 2013-12-13 05:47:31]

Retried try job too often on mac_rel for step(s) browser_tests
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=mac_rel&nu...

[commit-bot: I haz the power, 2013-12-13 10:12:27]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/40001

[commit-bot: I haz the power, 2013-12-13 12:12:25]

Retried try job too often on linux_rel for step(s) browser_tests
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=linux_rel&...

[commit-bot: I haz the power, 2013-12-18 17:07:19]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/40001

[commit-bot: I haz the power, 2013-12-18 18:29:07]

Retried try job too often on mac_rel for step(s) browser_tests
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=mac_rel&nu...

[haraken, 2013-12-19 02:20:49]

dsinclair@: This CL causes timeout in TracingBrowserTest::BeginTracingWithWatch.

https://code.google.com/p/chromium/codesearch#chromium/src/chrome/test/base/t...

Specifically, the following code causes timeout.

  ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, g_event, 1));  //
SetEnabled() is called in the file thread. So the tracing is not enabled at the
point when BeginTracingWithWatch() returns.
  AddEvents(1);  // Thus, this AddEvents() is ignored.
  EXPECT_TRUE(WaitForWatchEvent(no_timeout));  // Thus, this never returns.
  ASSERT_TRUE(EndTracing(&json_events));

The situation is as follows:

- We have to call SetDisabled() in the file thread, because Join() can block
execution.
- We have to call Join() and Create() from the same thread. This means that we
have to call SetEnabled() in the file thread as well.
- Thus, it is not guaranteed that tracing is enabled at the point when
BeginTracingWithWatch returns.

Do you have any idea? Should we rewrite the test so that AddEvents() is executed
after the tracing is enabled? (It's doable if we use
EnableRecordingDoneCallback(), but it will make the test more complicated.)

[dsinclair, 2013-12-20 14:55:34]

On 2013/12/19 02:20:49, haraken wrote:
> dsinclair@: This CL causes timeout in
TracingBrowserTest::BeginTracingWithWatch.
> 
>
https://code.google.com/p/chromium/codesearch#chromium/src/chrome/test/base/t...
> 
> Specifically, the following code causes timeout.
> 
>   ASSERT_TRUE(BeginTracingWithWatch(g_category, g_category, g_event, 1));  //
> SetEnabled() is called in the file thread. So the tracing is not enabled at
the
> point when BeginTracingWithWatch() returns.
>   AddEvents(1);  // Thus, this AddEvents() is ignored.
>   EXPECT_TRUE(WaitForWatchEvent(no_timeout));  // Thus, this never returns.
>   ASSERT_TRUE(EndTracing(&json_events));
> 
> The situation is as follows:
> 
> - We have to call SetDisabled() in the file thread, because Join() can block
> execution.
> - We have to call Join() and Create() from the same thread. This means that we
> have to call SetEnabled() in the file thread as well.
> - Thus, it is not guaranteed that tracing is enabled at the point when
> BeginTracingWithWatch returns.
> 
> Do you have any idea? Should we rewrite the test so that AddEvents() is
executed
> after the tracing is enabled? (It's doable if we use
> EnableRecordingDoneCallback(), but it will make the test more complicated.)


Could we do something simpler like add a WaitForEnabled() that checks returns
when the enable has happened on the file thread? Would be nice to not have to do
callback complications in the tests.

[haraken, 2013-12-25 09:14:37]

> Could we do something simpler like add a WaitForEnabled() that checks returns
> when the enable has happened on the file thread? Would be nice to not have to
do
> callback complications in the tests.

Thanks, done.

[commit-bot: I haz the power, 2013-12-25 09:14:46]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/60001

[commit-bot: I haz the power, 2013-12-25 09:31:00]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[haraken, 2013-12-25 09:34:59]

sky, phajdan: Could you take a look at the change to chrome/base/tracing.cc as
an OWNER?

[Paweł Hajdan Jr., 2014-01-02 12:27:23]

LGTM with nits.

https://codereview.chromium.org/105893004/diff/60001/chrome/test/base/tracing.cc
File chrome/test/base/tracing.cc (right):

https://codereview.chromium.org/105893004/diff/60001/chrome/test/base/tracing...
chrome/test/base/tracing.cc:49: base::Unretained(this))))
nit: This should have braces {} because condition spans several lines.

https://codereview.chromium.org/105893004/diff/60001/chrome/test/base/tracing...
chrome/test/base/tracing.cc:52: category_patterns,
content::TracingController::DEFAULT_OPTIONS,
nit: Please indent this +4 and add braces {}.

[commit-bot: I haz the power, 2014-01-06 14:40:43]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/60001

[commit-bot: I haz the power, 2014-01-06 14:40:45]

Failed to apply patch for content/browser/tracing/tracing_controller_impl.cc:
While running patch -p1 --forward --force --no-backup-if-mismatch;
  patching file content/browser/tracing/tracing_controller_impl.cc
  Hunk #2 FAILED at 178.
  Hunk #4 succeeded at 263 (offset 1 line).
  Hunk #5 FAILED at 278.
  Hunk #6 succeeded at 305 with fuzz 1 (offset 1 line).
  Hunk #7 succeeded at 330 (offset 1 line).
  2 out of 7 hunks FAILED -- saving rejects to file
content/browser/tracing/tracing_controller_impl.cc.rej

Patch:       content/browser/tracing/tracing_controller_impl.cc
Index: content/browser/tracing/tracing_controller_impl.cc
diff --git a/content/browser/tracing/tracing_controller_impl.cc
b/content/browser/tracing/tracing_controller_impl.cc
index
ead4cf24359b0ecc59d17b93a2aebcdb5cd5e291..1b670b03b60abe0c4820ffb8dee3b4978c7d1b86
100644
--- a/content/browser/tracing/tracing_controller_impl.cc
+++ b/content/browser/tracing/tracing_controller_impl.cc
@@ -150,6 +150,26 @@ bool TracingControllerImpl::GetCategories(
   return true;
 }
 
+void TracingControllerImpl::SetEnabledOnFileThread(
+    const std::string& category_filter,
+    int trace_options,
+    const base::Closure& callback) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
+
+  TraceLog::GetInstance()->SetEnabled(
+      base::debug::CategoryFilter(category_filter),
+      static_cast<TraceLog::Options>(trace_options));
+  BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, callback);
+}
+
+void TracingControllerImpl::SetDisabledOnFileThread(
+    const base::Closure& callback) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
+
+  TraceLog::GetInstance()->SetDisabled();
+  BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, callback);
+}
+
 bool TracingControllerImpl::EnableRecording(
     const std::string& category_filter,
     TracingController::Options options,
@@ -158,33 +178,47 @@ bool TracingControllerImpl::EnableRecording(
 
   if (!can_enable_recording())
     return false;
+  is_recording_ = true;
 
 #if defined(OS_ANDROID)
   if (pending_get_categories_done_callback_.is_null())
     TraceLog::GetInstance()->AddClockSyncMetadataEvent();
 #endif
 
-  TraceLog::Options trace_options = (options & RECORD_CONTINUOUSLY) ?
+  int trace_options = (options & RECORD_CONTINUOUSLY) ?
       TraceLog::RECORD_CONTINUOUSLY : TraceLog::RECORD_UNTIL_FULL;
   if (options & ENABLE_SAMPLING) {
-    trace_options = static_cast<TraceLog::Options>(
-        trace_options | TraceLog::ENABLE_SAMPLING);
+    trace_options |=  TraceLog::ENABLE_SAMPLING;
   }
   // TODO(haraken): How to handle ENABLE_SYSTRACE?
 
-  TraceLog::GetInstance()->SetEnabled(
-      base::debug::CategoryFilter(category_filter), trace_options);
-  is_recording_ = true;
+  base::Closure on_enable_recording_done_callback =
+      base::Bind(&TracingControllerImpl::OnEnableRecordingDone,
+                 base::Unretained(this),
+                 category_filter, trace_options, callback);
+  BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE,
+      base::Bind(&TracingControllerImpl::SetEnabledOnFileThread,
+                 base::Unretained(this),
+                 category_filter, trace_options,
+                 on_enable_recording_done_callback));
+  return true;
+}
+
+void TracingControllerImpl::OnEnableRecordingDone(
+    const std::string& category_filter,
+    int trace_options,
+    const EnableRecordingDoneCallback& callback) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   // Notify all child processes.
   for (TraceMessageFilterMap::iterator it = trace_message_filters_.begin();
       it != trace_message_filters_.end(); ++it) {
-    it->get()->SendBeginTracing(category_filter, trace_options);
+    it->get()->SendBeginTracing(category_filter,
+                                static_cast<TraceLog::Options>(trace_options));
   }
 
   if (!callback.is_null())
     callback.Run();
-  return true;
 }
 
 bool TracingControllerImpl::DisableRecording(
@@ -195,11 +229,25 @@ bool TracingControllerImpl::DisableRecording(
   if (!can_disable_recording())
     return false;
 
-  pending_disable_recording_done_callback_ = callback;
-
   // Disable local trace early to avoid traces during end-tracing process from
   // interfering with the process.
-  TraceLog::GetInstance()->SetDisabled();
+  base::Closure on_disable_recording_done_callback =
+      base::Bind(&TracingControllerImpl::OnDisableRecordingDone,
+                 base::Unretained(this),
+                 result_file_path, callback);
+  BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE,
+      base::Bind(&TracingControllerImpl::SetDisabledOnFileThread,
+                 base::Unretained(this),
+                 on_disable_recording_done_callback));
+  return true;
+}
+
+void TracingControllerImpl::OnDisableRecordingDone(
+    const base::FilePath& result_file_path,
+    const TracingFileResultCallback& callback) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+
+  pending_disable_recording_done_callback_ = callback;
 
 #if defined(OS_ANDROID)
   if (pending_get_categories_done_callback_.is_null())
@@ -228,7 +276,6 @@ bool TracingControllerImpl::DisableRecording(
       it != trace_message_filters_.end(); ++it) {
     it->get()->SendEndTracing();
   }
-  return true;
 }
 
 bool TracingControllerImpl::EnableMonitoring(
@@ -245,24 +292,37 @@ bool TracingControllerImpl::EnableMonitoring(
   TraceLog::GetInstance()->AddClockSyncMetadataEvent();
 #endif
 
-  int monitoring_tracing_options = 0;
+  int trace_options = 0;
   if (options & ENABLE_SAMPLING)
-    monitoring_tracing_options |= base::debug::TraceLog::MONITOR_SAMPLING;
+    trace_options |= TraceLog::MONITOR_SAMPLING;
 
-  TraceLog::GetInstance()->SetEnabled(
-      base::debug::CategoryFilter(category_filter),
-      static_cast<TraceLog::Options>(monitoring_tracing_options));
+  base::Closure on_enable_monitoring_done_callback =
+      base::Bind(&TracingControllerImpl::OnEnableMonitoringDone,
+                 base::Unretained(this),
+                 category_filter, trace_options, callback);
+  BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE,
+      base::Bind(&TracingControllerImpl::SetEnabledOnFileThread,
+                 base::Unretained(this),
+                 category_filter, trace_options,
+                 on_enable_monitoring_done_callback));
+  return true;
+}
+
+void TracingControllerImpl::OnEnableMonitoringDone(
+    const std::string& category_filter,
+    int trace_options,
+    const EnableMonitoringDoneCallback& callback) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   // Notify all child processes.
   for (TraceMessageFilterMap::iterator it = trace_message_filters_.begin();
       it != trace_message_filters_.end(); ++it) {
     it->get()->SendEnableMonitoring(category_filter,
-        static_cast<TraceLog::Options>(monitoring_tracing_options));
+        static_cast<TraceLog::Options>(trace_options));
   }
 
   if (!callback.is_null())
     callback.Run();
-  return true;
 }
 
 bool TracingControllerImpl::DisableMonitoring(
@@ -271,9 +331,22 @@ bool TracingControllerImpl::DisableMonitoring(
 
   if (!can_disable_monitoring())
     return false;
-  is_monitoring_ = false;
 
-  TraceLog::GetInstance()->SetDisabled();
+  base::Closure on_disable_monitoring_done_callback =
+      base::Bind(&TracingControllerImpl::OnDisableMonitoringDone,
+                 base::Unretained(this), callback);
+  BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE,
+      base::Bind(&TracingControllerImpl::SetDisabledOnFileThread,
+                 base::Unretained(this),
+                 on_disable_monitoring_done_callback));
+  return true;
+}
+
+void TracingControllerImpl::OnDisableMonitoringDone(
+    const DisableMonitoringDoneCallback& callback) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+
+  is_monitoring_ = false;
 
   // Notify all child processes.
   for (TraceMessageFilterMap::iterator it = trace_message_filters_.begin();
@@ -283,7 +356,6 @@ bool TracingControllerImpl::DisableMonitoring(
 
   if (!callback.is_null())
     callback.Run();
-  return true;
 }
 
 void TracingControllerImpl::GetMonitoringStatus(

[commit-bot: I haz the power, 2014-01-06 14:42:49]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/270001

[commit-bot: I haz the power, 2014-01-06 15:11:47]

Retried try job too often on linux_rel for step(s) base_unittests,
browser_tests, interactive_ui_tests, net_unittests, unit_tests
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=linux_rel&...

[commit-bot: I haz the power, 2014-01-06 15:16:54]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/490001

[commit-bot: I haz the power, 2014-01-06 15:27:34]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/600001

[commit-bot: I haz the power, 2014-01-06 15:31:34]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/haraken@chromium.org/105893004/640001

[sky, 2014-01-06 18:14:24]

https://codereview.chromium.org/105893004/diff/640001/chrome/test/base/tracin...
File chrome/test/base/tracing.cc (right):

https://codereview.chromium.org/105893004/diff/640001/chrome/test/base/tracin...
chrome/test/base/tracing.cc:49: base::Unretained(this)))) {
How do you know unretained is safe here and on 55? Also, don't you need to
cancel the watch?

[commit-bot: I haz the power, 2014-01-06 18:54:40]

Change committed as 243129

[haraken, 2014-01-07 02:04:42]

https://codereview.chromium.org/105893004/diff/640001/chrome/test/base/tracin...
File chrome/test/base/tracing.cc (right):

https://codereview.chromium.org/105893004/diff/640001/chrome/test/base/tracin...
chrome/test/base/tracing.cc:49: base::Unretained(this)))) {
On 2014/01/06 18:14:24, sky wrote:
> How do you know unretained is safe here and on 55?

InProcessTraceController is a Singleton, so I think it's safe to use unretained.
(Previous code is also using unretained.)

> Also, don't you need to cancel the watch?

I don't know, but there has been no code about cancellation.

[sky, 2014-01-07 16:39:34]

LGTM