[UMA] Add performance profile data to UMA uploads.

chrome/browser/metrics/metrics_log.cc

 // Copyright (c) 2012 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 "chrome/browser/metrics/metrics_log.h"
 
 #include <string>
 #include <vector>
 
 #include "base/basictypes.h"
 #include "base/file_util.h"
 #include "base/lazy_instance.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/perftimer.h"
 #include "base/string_number_conversions.h"
 #include "base/string_util.h"
 #include "base/sys_info.h"
 #include "base/third_party/nspr/prtime.h"
 #include "base/time.h"
+#include "base/tracked_objects.h"
 #include "base/utf_string_conversions.h"
 #include "chrome/browser/autocomplete/autocomplete.h"
 #include "chrome/browser/autocomplete/autocomplete_match.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/plugin_prefs.h"
 #include "chrome/browser/prefs/pref_service.h"
 #include "chrome/browser/profiles/profile_manager.h"
 #include "chrome/common/chrome_version_info.h"
 #include "chrome/common/logging_chrome.h"
 #include "chrome/common/metrics/proto/omnibox_event.pb.h"
+#include "chrome/common/metrics/proto/profiler_event.pb.h"
 #include "chrome/common/metrics/proto/system_profile.pb.h"
 #include "chrome/common/pref_names.h"
 #include "content/public/browser/content_browser_client.h"
 #include "content/public/browser/gpu_data_manager.h"
+#include "content/public/common/content_client.h"
 #include "content/public/common/gpu_info.h"
-#include "content/public/common/content_client.h"
 #include "googleurl/src/gurl.h"
 #include "ui/gfx/screen.h"
 #include "webkit/plugins/webplugininfo.h"
 
 #define OPEN_ELEMENT_FOR_SCOPE(name) ScopedElement scoped_element(this, name)
 
 // http://blogs.msdn.com/oldnewthing/archive/2004/10/25/247180.aspx
 #if defined(OS_WIN)
 extern "C" IMAGE_DOS_HEADER __ImageBase;
 #endif
 
 using content::GpuDataManager;
 using metrics::OmniboxEventProto;
+using metrics::ProfilerEventProto;
 using metrics::SystemProfileProto;
+using tracked_objects::ProcessDataSnapshot;
 typedef base::FieldTrial::NameGroupId NameGroupId;
 
 namespace {
 
 // Returns the date at which the current metrics client ID was created as
 // a string containing milliseconds since the epoch, or "0" if none was found.
 std::string GetInstallDate(PrefService* pref) {
   if (!pref) {
     NOTREACHED();
     return "0";
@@ skipping 74 matching lines @@
     case AutocompleteMatch::SEARCH_OTHER_ENGINE:
       return OmniboxEventProto::Suggestion::SEARCH_OTHER_ENGINE;
     case AutocompleteMatch::EXTENSION_APP:
       return OmniboxEventProto::Suggestion::EXTENSION_APP;
     default:
       NOTREACHED();
       return OmniboxEventProto::Suggestion::UNKNOWN_RESULT_TYPE;
   }
 }
 
+ProfilerEventProto::TrackedObject::ProcessType AsProtobufProcessType(
+    content::ProcessType process_type) {
+  switch (process_type) {
+    case content::PROCESS_TYPE_BROWSER:
+      return ProfilerEventProto::TrackedObject::BROWSER;
+    case content::PROCESS_TYPE_RENDERER:
+      return ProfilerEventProto::TrackedObject::RENDERER;
+    case content::PROCESS_TYPE_PLUGIN:
+      return ProfilerEventProto::TrackedObject::PLUGIN;
+    case content::PROCESS_TYPE_WORKER:
+      return ProfilerEventProto::TrackedObject::WORKER;
+    case content::PROCESS_TYPE_NACL_LOADER:
+      return ProfilerEventProto::TrackedObject::NACL_LOADER;
+    case content::PROCESS_TYPE_UTILITY:
+      return ProfilerEventProto::TrackedObject::UTILITY;
+    case content::PROCESS_TYPE_PROFILE_IMPORT:
+      return ProfilerEventProto::TrackedObject::PROFILE_IMPORT;
+    case content::PROCESS_TYPE_ZYGOTE:
+      return ProfilerEventProto::TrackedObject::ZYGOTE;
+    case content::PROCESS_TYPE_SANDBOX_HELPER:
+      return ProfilerEventProto::TrackedObject::SANDBOX_HELPER;
+    case content::PROCESS_TYPE_NACL_BROKER:
+      return ProfilerEventProto::TrackedObject::NACL_BROKER;
+    case content::PROCESS_TYPE_GPU:
+      return ProfilerEventProto::TrackedObject::GPU;
+    case content::PROCESS_TYPE_PPAPI_PLUGIN:
+      return ProfilerEventProto::TrackedObject::PPAPI_PLUGIN;
+    case content::PROCESS_TYPE_PPAPI_BROKER:
+      return ProfilerEventProto::TrackedObject::PPAPI_BROKER;
+    default:
+      NOTREACHED();
+      return ProfilerEventProto::TrackedObject::UNKNOWN;
+  }
+}
+
 // Returns the plugin preferences corresponding for this user, if available.
 // If multiple user profiles are loaded, returns the preferences corresponding
 // to an arbitrary one of the profiles.
 PluginPrefs* GetPluginPrefs() {
   ProfileManager* profile_manager = g_browser_process->profile_manager();
 
   if (!profile_manager) {
     // The profile manager can be NULL when testing.
     return NULL;
   }
@@ skipping 20 matching lines @@
                       SystemProfileProto* system_profile) {
   for (std::vector<NameGroupId>::const_iterator it = field_trial_ids.begin();
        it != field_trial_ids.end(); ++it) {
     SystemProfileProto::FieldTrial* field_trial =
         system_profile->add_field_trial();
     field_trial->set_name_id(it->name);
     field_trial->set_group_id(it->group);
   }
 }
 
+void WriteProfilerData(const ProcessDataSnapshot& profiler_data,
+                       content::ProcessType process_type,
+                       ProfilerEventProto* performance_profile) {
+  for (std::vector<tracked_objects::TaskSnapshot>::const_iterator it =
+           profiler_data.tasks.begin();
+       it != profiler_data.tasks.end(); ++it) {
+    std::string ignored;
+    uint64 birth_thread_name_hash;
+    uint64 exec_thread_name_hash;
+    uint64 source_file_name_hash;
+    uint64 source_function_name_hash;
+    MetricsLogBase::CreateHashes(it->birth.thread_name,

[jar (doing other things), 2012/04/19 03:04:56]

We may end up needing to profile this... to see how long it takes... and if it
is too wasteful.
It sure seems like a shame to calculate the SHA hash of the same thread, time
and again.
At a minimum, we should watch for the task that does this protobuf-ication, and
see if it stands out.

[Ilya Sherman, 2012/04/19 21:26:08]

I think the relevant task is "OnProfilerDataCollected", which on my Debug build
does not show up as a hot spot -- the max run time is 12ms (and that includes
loads of about:profiler as well).  Let's definitely keep an eye on it though.

+                                 &ignored, &birth_thread_name_hash);
+    MetricsLogBase::CreateHashes(it->death_thread_name,
+                                 &ignored, &exec_thread_name_hash);
+    MetricsLogBase::CreateHashes(it->birth.location.function_name,
+                                 &ignored, &source_file_name_hash);
+    MetricsLogBase::CreateHashes(it->birth.location.file_name,
+                                 &ignored, &source_function_name_hash);
+
+    const tracked_objects::DeathDataSnapshot& death_data = it->death_data;
+    ProfilerEventProto::TrackedObject* tracked_object =
+        performance_profile->add_tracked_object();
+    tracked_object->set_birth_thread_name_hash(birth_thread_name_hash);
+    tracked_object->set_exec_thread_name_hash(exec_thread_name_hash);
+    tracked_object->set_source_file_name_hash(source_file_name_hash);
+    tracked_object->set_source_function_name_hash(source_function_name_hash);
+    tracked_object->set_source_line_number(it->birth.location.line_number);
+    tracked_object->set_exec_count(death_data.count);
+    tracked_object->set_exec_time_total(death_data.run_duration_sum);
+    tracked_object->set_exec_time_sampled(death_data.run_duration_sample);
+    tracked_object->set_queue_time_total(death_data.queue_duration_sum);
+    tracked_object->set_queue_time_sampled(death_data.queue_duration_sample);
+    tracked_object->set_process_type(AsProtobufProcessType(process_type));
+    tracked_object->set_process_id(profiler_data.process_id);
+  }
+}
+
 }  // namespace
 
 static base::LazyInstance<std::string>::Leaky
   g_version_extension = LAZY_INSTANCE_INITIALIZER;
 
 MetricsLog::MetricsLog(const std::string& client_id, int session_id)
     : MetricsLogBase(client_id, session_id, MetricsLog::GetVersionString()) {}
 
 MetricsLog::~MetricsLog() {}
 
@@ skipping 503 matching lines @@
   hardware->set_screen_count(GetScreenCount());
 
   bool write_as_xml = false;
   WritePluginList(plugin_list, write_as_xml);
 
   std::vector<NameGroupId> field_trial_ids;
   GetFieldTrialIds(&field_trial_ids);
   WriteFieldTrials(field_trial_ids, system_profile);
 }
 
+void MetricsLog::RecordProfilerData(
+    const tracked_objects::ProcessDataSnapshot& process_data,
+    content::ProcessType process_type) {
+  DCHECK(!locked());
+
+  ProfilerEventProto* profile;
+  if (!uma_proto()->profiler_event_size()) {
+    // For the first process's data, add a new field to the protocol buffer.
+    profile = uma_proto()->add_profiler_event();
+    profile->set_profile_type(ProfilerEventProto::STARTUP_PROFILE);
+    profile->set_time_source(ProfilerEventProto::WALL_CLOCK_TIME);

[jar (doing other things), 2012/04/19 03:04:56]

We need to validate this as being the source.  I think we need to augment the
code that changes the time source, so that it sets an inspectable value... which
we can use here to establish the "true" source.
As currently coded, if a person plays with the TCMalloc time source... they'll
corrupt our stats.

[Ilya Sherman, 2012/04/19 21:26:08]

Done.

+  } else {
+    // For the remaining calls, re-use the existing field.
+    profile = uma_proto()->mutable_profiler_event(0);
+  }
+
+  WriteProfilerData(process_data, process_type, profile);
+}
+
 void MetricsLog::WriteAllProfilesMetrics(
     const DictionaryValue& all_profiles_metrics) {
   const std::string profile_prefix(prefs::kProfilePrefix);
   for (DictionaryValue::key_iterator i = all_profiles_metrics.begin_keys();
        i != all_profiles_metrics.end_keys(); ++i) {
     const std::string& key_name = *i;
     if (key_name.compare(0, profile_prefix.size(), profile_prefix) == 0) {
       DictionaryValue* profile;
       if (all_profiles_metrics.GetDictionaryWithoutPathExpansion(key_name,
                                                                  &profile))
@@ skipping 114 matching lines @@
        i != log.result.end(); ++i) {
     OmniboxEventProto::Suggestion* suggestion = omnibox_event->add_suggestion();
     suggestion->set_provider(AsOmniboxEventProviderType(i->provider));
     suggestion->set_result_type(AsOmniboxEventResultType(i->type));
     suggestion->set_relevance(i->relevance);
     suggestion->set_is_starred(i->starred);
   }
 
   ++num_events_;
 }