Added event traces at various points during Chrome and ChromeFrame startup to help measure and track performance.

Bug=51638

Review URL: http://codereview.chromium.org/3152001

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@55671 0039d316-1c4b-4281-b951-d872f2087c98

8 files changed, 135 insertions, 8 deletions

diff --git a/chrome/browser/automation/automation_provider.cc b/chrome/browser/automation/automation_provider.cc
index 2d44ff5..bba2ace 100644
--- a/chrome/browser/automation/automation_provider.cc
+++ b/chrome/browser/automation/automation_provider.cc
@@ -21,6 +21,7 @@
 #include "base/string_util.h"
 #include "base/task.h"
 #include "base/thread.h"
+#include "base/trace_event.h"
 #include "base/string_number_conversions.h"
 #include "base/utf_string_conversions.h"
 #include "base/values.h"
@@ -163,6 +164,8 @@ AutomationProvider::AutomationProvider(Profile* profile)
       profile_(profile),
       reply_message_(NULL),
       popup_menu_waiter_(NULL) {
+  TRACE_EVENT_BEGIN("AutomationProvider::AutomationProvider", 0, "");
+
   browser_tracker_.reset(new AutomationBrowserTracker(this));
   extension_tracker_.reset(new AutomationExtensionTracker(this));
   tab_tracker_.reset(new AutomationTabTracker(this));
@@ -175,6 +178,8 @@ AutomationProvider::AutomationProvider(Profile* profile)
   extension_test_result_observer_.reset(
       new ExtensionTestResultNotificationObserver(this));
   g_browser_process->AddRefModule();
+
+  TRACE_EVENT_END("AutomationProvider::AutomationProvider", 0, "");
 }
 
 AutomationProvider::~AutomationProvider() {
@@ -195,6 +200,8 @@ AutomationProvider::~AutomationProvider() {
 }
 
 void AutomationProvider::ConnectToChannel(const std::string& channel_id) {
+  TRACE_EVENT_BEGIN("AutomationProvider::ConnectToChannel", 0, "");
+
   automation_resource_message_filter_ = new AutomationResourceMessageFilter;
   channel_.reset(
       new IPC::SyncChannel(channel_id, IPC::Channel::MODE_CLIENT, this,
@@ -209,6 +216,8 @@ void AutomationProvider::ConnectToChannel(const std::string& channel_id) {
 
   // Send a hello message with our current automation protocol version.
   channel_->Send(new AutomationMsg_Hello(0, version_string.c_str()));
+
+  TRACE_EVENT_END("AutomationProvider::ConnectToChannel", 0, "");
 }
 
 void AutomationProvider::SetExpectedTabCount(size_t expected_tabs) {
diff --git a/chrome/browser/automation/automation_provider_win.cc b/chrome/browser/automation/automation_provider_win.cc
index 81cdcf2..0bb238b 100644
--- a/chrome/browser/automation/automation_provider_win.cc
+++ b/chrome/browser/automation/automation_provider_win.cc
@@ -6,6 +6,7 @@
 
 #include "base/json/json_reader.h"
 #include "base/keyboard_codes.h"
+#include "base/trace_event.h"
 #include "chrome/browser/automation/automation_browser_tracker.h"
 #include "chrome/browser/automation/automation_extension_function.h"
 #include "chrome/browser/automation/automation_tab_tracker.h"
@@ -301,6 +302,8 @@ void AutomationProvider::CreateExternalTab(
     const IPC::ExternalTabSettings& settings,
     gfx::NativeWindow* tab_container_window, gfx::NativeWindow* tab_window,
     int* tab_handle) {
+  TRACE_EVENT_BEGIN("AutomationProvider::CreateExternalTab", 0, "");
+
   *tab_handle = 0;
   *tab_container_window = NULL;
   *tab_window = NULL;
@@ -325,6 +328,8 @@ void AutomationProvider::CreateExternalTab(
   } else {
     external_tab_container->Uninitialize();
   }
+
+  TRACE_EVENT_END("AutomationProvider::CreateExternalTab", 0, "");
 }
 
 bool AutomationProvider::AddExternalTab(ExternalTabContainer* external_tab) {
@@ -433,6 +438,8 @@ void AutomationProvider::ConnectExternalTab(
     gfx::NativeWindow* tab_container_window,
     gfx::NativeWindow* tab_window,
     int* tab_handle) {
+  TRACE_EVENT_BEGIN("AutomationProvider::ConnectExternalTab", 0, "");
+
   *tab_handle = 0;
   *tab_container_window = NULL;
   *tab_window = NULL;
@@ -455,6 +462,8 @@ void AutomationProvider::ConnectExternalTab(
   } else {
     external_tab_container->Uninitialize();
   }
+
+  TRACE_EVENT_END("AutomationProvider::ConnectExternalTab", 0, "");
 }
 
 void AutomationProvider::TerminateSession(int handle, bool* success) {
diff --git a/chrome/browser/browser_main.cc b/chrome/browser/browser_main.cc
index 5f8fa20..6b29674 100644
--- a/chrome/browser/browser_main.cc
+++ b/chrome/browser/browser_main.cc
@@ -26,6 +26,7 @@
 #include "base/string_util.h"
 #include "base/sys_string_conversions.h"
 #include "base/time.h"
+#include "base/trace_event.h"
 #include "base/utf_string_conversions.h"
 #include "base/values.h"
 #include "build/build_config.h"
@@ -443,6 +444,8 @@ void HandleTestParameters(const CommandLine& command_line) {
 }
 
 void RunUIMessageLoop(BrowserProcess* browser_process) {
+  TRACE_EVENT_BEGIN("BrowserMain:MESSAGE_LOOP", 0, "");
+
 #if defined(TOOLKIT_VIEWS)
   views::AcceleratorHandler accelerator_handler;
   MessageLoopForUI::current()->Run(&accelerator_handler);
@@ -451,6 +454,8 @@ void RunUIMessageLoop(BrowserProcess* browser_process) {
 #elif defined(OS_POSIX)
   MessageLoopForUI::current()->Run();
 #endif
+
+  TRACE_EVENT_END("BrowserMain:MESSAGE_LOOP", 0, "");
 }
 
 void AddFirstRunNewTabs(BrowserInit* browser_init,
@@ -810,6 +815,7 @@ DLLEXPORT void __cdecl RelaunchChromeBrowserWithNewCommandLineIfNeeded() {
 
 // Main routine for running as the Browser process.
 int BrowserMain(const MainFunctionParams& parameters) {
+  TRACE_EVENT_BEGIN("BrowserMain", 0, "");
   scoped_ptr<BrowserMainParts>
       parts(BrowserMainParts::CreateBrowserMainParts(parameters));
 
@@ -1442,5 +1448,6 @@ int BrowserMain(const MainFunctionParams& parameters) {
   ignore_result(browser_process.release());
   browser_shutdown::Shutdown();
 
+  TRACE_EVENT_END("BrowserMain", 0, 0);
   return result_code;
 }
diff --git a/chrome/browser/external_tab_container_win.cc b/chrome/browser/external_tab_container_win.cc
index 4f65e6b..59da688 100644
--- a/chrome/browser/external_tab_container_win.cc
+++ b/chrome/browser/external_tab_container_win.cc
@@ -8,6 +8,7 @@
 
 #include "base/i18n/rtl.h"
 #include "base/logging.h"
+#include "base/trace_event.h"
 #include "base/win_util.h"
 #include "chrome/app/chrome_dll_resource.h"
 #include "chrome/browser/automation/automation_provider.h"
@@ -618,6 +619,8 @@ void ExternalTabContainer::Observe(NotificationType type,
         const LoadNotificationDetails* load =
             Details<LoadNotificationDetails>(details).ptr();
         if (load != NULL && PageTransition::IsMainFrame(load->origin())) {
+          TRACE_EVENT_END("ExternalTabContainer::Navigate", 0,
+                          load->url().spec());
           automation_->Send(new AutomationMsg_TabLoaded(0, tab_handle_,
                                                         load->url()));
         }
@@ -866,6 +869,8 @@ void ExternalTabContainer::Navigate(const GURL& url, const GURL& referrer) {
     return;
   }
 
+  TRACE_EVENT_BEGIN("ExternalTabContainer::Navigate", 0, url.spec());
+
   tab_contents_->controller().LoadURL(url, referrer,
                                       PageTransition::START_PAGE);
 }
diff --git a/chrome/common/sandbox_policy.cc b/chrome/common/sandbox_policy.cc
index 2f649c5..5fcb98e 100644
--- a/chrome/common/sandbox_policy.cc
+++ b/chrome/common/sandbox_policy.cc
@@ -14,6 +14,7 @@
 #include "base/path_service.h"
 #include "base/process_util.h"
 #include "base/string_util.h"
+#include "base/trace_event.h"
 #include "base/win_util.h"
 #include "chrome/common/child_process_info.h"
 #include "chrome/common/chrome_constants.h"
@@ -445,6 +446,8 @@ base::ProcessHandle StartProcessWithAccess(CommandLine* cmd_line,
     return 0;
   }
 
+  TRACE_EVENT_BEGIN("StartProcessWithAccess", 0, type_str);
+
   bool in_sandbox =
       (type != ChildProcessInfo::NACL_BROKER_PROCESS) &&
       !browser_command_line.HasSwitch(switches::kNoSandbox) &&
@@ -522,12 +525,16 @@ base::ProcessHandle StartProcessWithAccess(CommandLine* cmd_line,
     return 0;
   }
 
+  TRACE_EVENT_BEGIN("StartProcessWithAccess::LAUNCHPROCESS", 0, 0);
+
   result = g_broker_services->SpawnTarget(
       cmd_line->program().c_str(),
       cmd_line->command_line_string().c_str(),
       policy, &target);
   policy->Release();
 
+  TRACE_EVENT_END("StartProcessWithAccess::LAUNCHPROCESS", 0, 0);
+
   if (sandbox::SBOX_ALL_OK != result)
     return 0;
 
diff --git a/chrome/renderer/render_thread.cc b/chrome/renderer/render_thread.cc
index 7ab9ae8..b49d99e 100644
--- a/chrome/renderer/render_thread.cc
+++ b/chrome/renderer/render_thread.cc
@@ -19,6 +19,7 @@
 #include "base/string_util.h"
 #include "base/task.h"
 #include "base/thread_local.h"
+#include "base/trace_event.h"
 #include "base/utf_string_conversions.h"
 #include "chrome/common/appcache/appcache_dispatcher.h"
 #include "chrome/common/child_process_logging.h"
@@ -221,6 +222,8 @@ RenderThread::RenderThread(const std::string& channel_name)
 }
 
 void RenderThread::Init() {
+  TRACE_EVENT_BEGIN("RenderThread::Init", 0, "");
+
   lazy_tls.Pointer()->Set(this);
 #if defined(OS_WIN)
   // If you are running plugins in this thread you need COM active but in
@@ -276,6 +279,8 @@ void RenderThread::Init() {
   }
 
   GpuVideoServiceHost::get()->OnRendererThreadInit(MessageLoop::current());
+
+  TRACE_EVENT_END("RenderThread::Init", 0, "");
 }
 
 RenderThread::~RenderThread() {
diff --git a/chrome/renderer/renderer_main.cc b/chrome/renderer/renderer_main.cc
index 5339708..dae703a 100644
--- a/chrome/renderer/renderer_main.cc
+++ b/chrome/renderer/renderer_main.cc
@@ -19,6 +19,7 @@
 #include "base/scoped_nsautorelease_pool.h"
 #include "base/stats_counters.h"
 #include "base/string_util.h"
+#include "base/trace_event.h"
 #include "chrome/common/chrome_constants.h"
 #include "chrome/common/chrome_counters.h"
 #include "chrome/common/chrome_switches.h"
@@ -176,6 +177,8 @@ static void HandleRendererErrorTestParameters(const CommandLine& command_line) {
 
 // mainline routine for running as the Renderer process
 int RendererMain(const MainFunctionParams& parameters) {
+  TRACE_EVENT_BEGIN("RendererMain", 0, "");
+
   const CommandLine& parsed_command_line = parameters.command_line_;
   base::ScopedNSAutoreleasePool* pool = parameters.autorelease_pool_;
 
@@ -287,9 +290,12 @@ int RendererMain(const MainFunctionParams& parameters) {
     if (run_loop) {
       if (pool)
         pool->Recycle();
+      TRACE_EVENT_BEGIN("RendererMain.START_MSG_LOOP", 0, 0);
       MessageLoop::current()->Run();
+      TRACE_EVENT_END("RendererMain.START_MSG_LOOP", 0, 0);
     }
   }
   platform.PlatformUninitialize();
+  TRACE_EVENT_END("RendererMain", 0, "");
   return 0;
 }
diff --git a/chrome_frame/test/perf/chrome_frame_perftest.cc b/chrome_frame/test/perf/chrome_frame_perftest.cc
index f9e1b7f..6ab23e4 100644
--- a/chrome_frame/test/perf/chrome_frame_perftest.cc
+++ b/chrome_frame/test/perf/chrome_frame_perftest.cc
@@ -1195,7 +1195,8 @@ class EtwPerfSession {
 
   void Start() {
     // To ensure there is no session leftover from crashes, previous runs, etc.
-    // EtwTraceController::Stop(L"cf_perf", NULL);
+    EtwTraceProperties ignore;
+    EtwTraceController::Stop(L"cf_perf", &ignore);
     ASSERT_TRUE(file_util::CreateTemporaryFile(&etl_log_file_));
     ASSERT_HRESULT_SUCCEEDED(controller_.StartFileSession(L"cf_perf",
         etl_log_file_.value().c_str(), false));
@@ -1205,8 +1206,11 @@ class EtwPerfSession {
         ~(base::CAPTURE_STACK_TRACE)));
   }
 
+  HRESULT Stop() {
+    return controller_.Stop(NULL);
+  }
+
   void AnalyzeOutput(TracedEvents* delegate) {
-    EXPECT_HRESULT_SUCCEEDED(controller_.Stop(NULL));
     EtwConsumer consumer;
     consumer.set_delegate(delegate);
     consumer.OpenFileSession(etl_log_file_.value().c_str());
@@ -1307,7 +1311,7 @@ bool RunSingleTestOutOfProc(const std::string& test_name) {
   if (!base::LaunchApp(cmd_line, false, false, &process_handle))
     return false;
 
-  int test_terminate_timeout_ms = 30 * 1000;
+  int test_terminate_timeout_ms = 60 * 1000;
   int exit_code = 0;
   if (!base::WaitForExitCodeWithTimeout(process_handle, &exit_code,
     test_terminate_timeout_ms)) {
@@ -1325,7 +1329,13 @@ bool RunSingleTestOutOfProc(const std::string& test_name) {
 
 TEST(TestAsPerfTest, MetaTag_createproxy) {
   const int kNumCycles = 10;
-  MonitorTracePair monitor[kNumCycles];
+  MonitorTracePair create_proxy_monitor[kNumCycles];
+  MonitorTracePair browser_main_start_monitor[kNumCycles];
+  MonitorTracePair browser_main_loop_monitor[kNumCycles];
+  MonitorTracePair automation_provider_start_monitor[kNumCycles];
+  MonitorTracePair automation_provider_connect_monitor[kNumCycles];
+  MonitorTracePair automation_provider_createtab_monitor[kNumCycles];
+  MonitorTracePair external_tab_navigate_monitor[kNumCycles];
 
   for (int i = 0; i < kNumCycles; ++i) {
     EtwPerfSession perf_session;
@@ -1334,17 +1344,86 @@ TEST(TestAsPerfTest, MetaTag_createproxy) {
         "ChromeFrameTestWithWebServer.FullTabModeIE_MetaTag"));
     // Since we cannot have array of objects with a non-default constructor,
     // dedicated method is used to initialize watched event.
-    monitor[i].set_interesting_event("chromeframe.createproxy");
-    perf_session.AnalyzeOutput(&monitor[i]);
+    create_proxy_monitor[i].set_interesting_event("chromeframe.createproxy");
+    browser_main_start_monitor[i].set_interesting_event("BrowserMain");
+    browser_main_loop_monitor[i].set_interesting_event(
+        "BrowserMain:MESSAGE_LOOP");
+    automation_provider_start_monitor[i].set_interesting_event(
+        "AutomationProvider::AutomationProvider");
+    automation_provider_connect_monitor[i].set_interesting_event(
+        "AutomationProvider::ConnectToChannel");
+    external_tab_navigate_monitor[i].set_interesting_event(
+        "ExternalTabContainer::Navigate");
+
+    ASSERT_HRESULT_SUCCEEDED(perf_session.Stop());
+
+    perf_session.AnalyzeOutput(&create_proxy_monitor[i]);
+    perf_session.AnalyzeOutput(&browser_main_start_monitor[i]);
+    perf_session.AnalyzeOutput(&browser_main_loop_monitor[i]);
+    perf_session.AnalyzeOutput(&automation_provider_start_monitor[i]);
+    perf_session.AnalyzeOutput(&automation_provider_connect_monitor[i]);
+    perf_session.AnalyzeOutput(&external_tab_navigate_monitor[i]);
   }
 
   // Print results
   std::string times;
   for (int i = 0; i < kNumCycles; ++i) {
-    ASSERT_TRUE(monitor[i].is_valid());
-    StringAppendF(&times, "%.2f,", monitor[i].duration().InMillisecondsF());
+    ASSERT_TRUE(create_proxy_monitor[i].is_valid());
+    StringAppendF(&times, "%.2f,",
+                  create_proxy_monitor[i].duration().InMillisecondsF());
   }
 
   bool important = false;
   PrintResultList("createproxy", "", "t", times, "ms", important);
+
+  times.clear();
+
+  for (int i = 0; i < kNumCycles; ++i) {
+    ASSERT_TRUE(browser_main_start_monitor[i].is_valid());
+    StringAppendF(&times, "%.2f,",
+                  browser_main_start_monitor[i].duration().InMillisecondsF());
+  }
+
+  PrintResultList("browserstart", "", "t", times, "ms", important);
+  times.clear();
+
+  for (int i = 0; i < kNumCycles; ++i) {
+    ASSERT_TRUE(browser_main_loop_monitor[i].is_valid());
+    StringAppendF(&times, "%.2f,",
+                  browser_main_loop_monitor[i].duration().InMillisecondsF());
+  }
+
+  PrintResultList("browserloop", "", "t", times, "ms", important);
+  times.clear();
+
+  for (int i = 0; i < kNumCycles; ++i) {
+    ASSERT_TRUE(automation_provider_start_monitor[i].is_valid());
+    StringAppendF(
+        &times, "%.2f,",
+        automation_provider_start_monitor[i].duration().InMillisecondsF());
+  }
+
+  PrintResultList("automationproviderstart", "", "t", times, "ms", important);
+  times.clear();
+
+  for (int i = 0; i < kNumCycles; ++i) {
+    ASSERT_TRUE(automation_provider_connect_monitor[i].is_valid());
+    StringAppendF(
+        &times, "%.2f,",
+        automation_provider_connect_monitor[i].duration().InMillisecondsF());
+  }
+
+  PrintResultList("automationproviderconnect", "", "t", times, "ms",
+                  important);
+  times.clear();
+
+  for (int i = 0; i < kNumCycles; ++i) {
+    ASSERT_TRUE(external_tab_navigate_monitor[i].is_valid());
+    StringAppendF(
+        &times, "%.2f,",
+        external_tab_navigate_monitor[i].duration().InMillisecondsF());
+  }
+
+  PrintResultList("externaltabnavigate", "", "t", times, "ms", important);
+  times.clear();
 }