Add SameVersionStartupCounts suffix to startup HardFault and Temperature histograms.

components/startup_metric_utils/browser/startup_metric_utils.cc

 // Copyright 2013 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 "components/startup_metric_utils/browser/startup_metric_utils.h"
 
 #include <stddef.h>
 
 #include "base/containers/hash_tables.h"
 #include "base/environment.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
+#include "base/metrics/histogram.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/prefs/pref_registry_simple.h"
 #include "base/prefs/pref_service.h"
 #include "base/process/process_info.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/sys_info.h"
 #include "base/threading/platform_thread.h"
 #include "base/trace_event/trace_event.h"
 #include "build/build_config.h"
 #include "components/startup_metric_utils/browser/pref_names.h"
@@ skipping 107 matching lines @@
         type(basename ".ColdStartup", kValue);                                \
         break;                                                                \
       case WARM_STARTUP_TEMPERATURE:                                          \
         type(basename ".WarmStartup", kValue);                                \
         break;                                                                \
       case LUKEWARM_STARTUP_TEMPERATURE:                                      \
         type(basename ".LukewarmStartup", kValue);                            \
         break;                                                                \
       case UNDETERMINED_STARTUP_TEMPERATURE:                                  \
         break;                                                                \
-      case STARTUP_TEMPERATURE_COUNT:                                         \
-        NOTREACHED();                                                         \
-        break;                                                                \
     }                                                                         \
   }
 
 #define UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(                     \
     type, basename, begin_ticks, end_ticks)                                   \
   {                                                                           \
     UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(type, basename,                    \
                                            end_ticks - begin_ticks)           \
     TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP1(                                  \
         "startup", basename, 0, begin_ticks.ToInternalValue(), "Temperature", \
@@ skipping 21 matching lines @@
       GetSystemUptimeOnProcessLaunch();
   if (system_uptime_on_process_launch.is_zero())
     return;
 
   UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(UMA_HISTOGRAM_LONG_TIMES_100,
                                          "Startup.SystemUptime",
                                          GetSystemUptimeOnProcessLaunch());
 }
 
 // On Windows, records the number of hard-faults that have occurred in the
-// current chrome.exe process since it was started. This is a nop on other
-// platforms.
-void RecordHardFaultHistogram(bool is_first_run) {
+// current chrome.exe process since it was started. A version of the histograms
+// recorded in this method suffixed by |same_version_startup_count| will also be
+// recorded. This is a nop on other platforms.
+void RecordHardFaultHistogram(int same_version_startup_count) {
 #if defined(OS_WIN)
   uint32_t hard_fault_count = 0;
 
-  // Don't log a histogram value if unable to get the hard fault count.
+  // Don't record histograms if unable to get the hard fault count.
   if (!GetHardFaultCountForCurrentProcess(&hard_fault_count))
     return;
 
+  // Histograms below will be suffixed by |same_version_startup_count| up to
+  // |kMaxSameVersionCountRecorded|, higher counts will be grouped in the
+  // ".Over" suffix. Make sure to reflect changes to
+  // kMaxSameVersionCountRecorded in the "SameVersionStartupCounts" histogram
+  // suffix.
+  const int kMaxSameVersionCountRecorded = 9;
+  std::string same_version_startup_count_suffix = ".";
+  DCHECK_GE(same_version_startup_count, 1);
+  if (same_version_startup_count <= kMaxSameVersionCountRecorded) {
+    same_version_startup_count_suffix.append(
+        base::IntToString(same_version_startup_count));
+  } else {
+    same_version_startup_count_suffix.append("Over");
+  }
+
   // Hard fault counts are expected to be in the thousands range,
   // corresponding to faulting in ~10s of MBs of code ~10s of KBs at a time.
   // (Observed to vary from 1000 to 10000 on various test machines and
   // platforms.)
-  if (is_first_run) {
-    UMA_HISTOGRAM_CUSTOM_COUNTS(
-        "Startup.BrowserMessageLoopStartHardFaultCount.FirstRun",
-        hard_fault_count,
-        0, 40000, 50);
-  } else {
-    UMA_HISTOGRAM_CUSTOM_COUNTS(
-        "Startup.BrowserMessageLoopStartHardFaultCount",
-        hard_fault_count,
-        0, 40000, 50);
-  }
+  const char kHardFaulCountHistogram[] =

[fdoray, 2016/01/25 18:48:00]

kHardFaultCount
         ^

[gab, 2016/01/25 21:32:26]

Done.

+      "Startup.BrowserMessageLoopStartHardFaultCount";
+  UMA_HISTOGRAM_CUSTOM_COUNTS(kHardFaulCountHistogram, hard_fault_count, 1,
+                              40000, 50);
+  // Also record the hard fault count histogram suffixed by the number of
+  // startups this specific version has been through.
+  // Factory properties copied from UMA_HISTOGRAM_CUSTOM_COUNTS macro.
+  base::Histogram::FactoryGet(
+      kHardFaulCountHistogram + same_version_startup_count_suffix, 1, 40000, 50,
+      base::HistogramBase::kUmaTargetedHistogramFlag)
+      ->Add(hard_fault_count);

[fdoray, 2016/01/25 18:48:00]

Why can't you use the UMA_HISTOGRAM_CUSTOM_COUNTS macro here?

[gab, 2016/01/25 21:32:26]

Because the name is dynamic and the macros end up taking a static pointer to a
single histogram which doesn't work for dynamic names :
https://code.google.com/p/chromium/codesearch#chromium/src/base/metrics/histo...

Using the FactoryGet() is common for dynamically generated histogram names (i.e.
to use the macro we'd need an explicit switch with 10 static names).

 
   // Determine the startup type based on the number of observed hard faults.
   DCHECK_EQ(UNDETERMINED_STARTUP_TEMPERATURE, g_startup_temperature);
   if (hard_fault_count < WARM_START_HARD_FAULT_COUNT_THRESHOLD) {
     g_startup_temperature = WARM_STARTUP_TEMPERATURE;
   } else if (hard_fault_count >= COLD_START_HARD_FAULT_COUNT_THRESHOLD) {
     g_startup_temperature = COLD_STARTUP_TEMPERATURE;
   } else {
     g_startup_temperature = LUKEWARM_STARTUP_TEMPERATURE;
   }
 
   // Record the startup 'temperature'.
-  UMA_HISTOGRAM_ENUMERATION(
-      "Startup.Temperature", g_startup_temperature, STARTUP_TEMPERATURE_COUNT);
+  const char kStartupTemperatureHistogram[] = "Startup.Temperature";
+  UMA_HISTOGRAM_ENUMERATION(kStartupTemperatureHistogram, g_startup_temperature,
+                            STARTUP_TEMPERATURE_MAX);
+  // As well as its suffixed twin.
+  // Factory properties copied from UMA_HISTOGRAM_ENUMERATION macro.
+  base::LinearHistogram::FactoryGet(
+      kStartupTemperatureHistogram + same_version_startup_count_suffix, 1,
+      STARTUP_TEMPERATURE_MAX, STARTUP_TEMPERATURE_MAX + 1,
+      base::HistogramBase::kUmaTargetedHistogramFlag)
+      ->Add(g_startup_temperature);

[fdoray, 2016/01/25 18:48:00]

Why can't you use the UMA_HISTOGRAM_ENUMERATION macro here?

[gab, 2016/01/25 21:32:26]

Same.

 #endif  // defined(OS_WIN)
 }
 
 // Converts a base::Time value to a base::TimeTicks value. The conversion isn't
 // exact, but by capturing Time::Now() as early as possible, the likelihood of a
 // clock change between it and process start is as low as possible. There is
 // also the time taken to synchronously resolve base::Time::Now() and
 // base::TimeTicks::Now() at play, but in practice it is pretty much instant
 // compared to multi-seconds startup timings.
 base::TimeTicks StartupTimeToTimeTicks(const base::Time& time) {
@@ skipping 103 matching lines @@
       g_browser_main_entry_point_ticks.Get().ToInternalValue());
 
   if (!g_process_creation_ticks.Get().is_null())
   {
     TRACE_EVENT_INSTANT_WITH_TIMESTAMP0(
         "startup", "Startup.BrowserProcessCreation", 0,
         g_process_creation_ticks.Get().ToInternalValue());
   }
 }
 
+// Logs the Startup.TimeSinceLastStartup histogram. Obtains the timestamp of the
+// last startup from |pref_service| and overwrites it with the timestamp of the
+// current startup. If the startup temperature has been set by
+// RecordBrowserMainMessageLoopStart, the time since last startup is also logged
+// to an histogram suffixed with the startup temperature.
+void RecordTimeSinceLastStartup(PrefService* pref_service) {
+#if defined(OS_MACOSX) || defined(OS_WIN) || defined(OS_LINUX)
+  DCHECK(pref_service);
+
+  // Get the timestamp of the current startup.
+  const base::Time process_start_time =
+      base::CurrentProcessInfo::CreationTime();
+
+  // Get the timestamp of the last startup from |pref_service|.
+  const int64_t last_startup_timestamp_internal =
+      pref_service->GetInt64(prefs::kLastStartupTimestamp);
+  if (last_startup_timestamp_internal != 0) {
+    // Log the Startup.TimeSinceLastStartup histogram.
+    const base::Time last_startup_timestamp =
+        base::Time::FromInternalValue(last_startup_timestamp_internal);
+    const base::TimeDelta time_since_last_startup =
+        process_start_time - last_startup_timestamp;
+    const int minutes_since_last_startup = time_since_last_startup.InMinutes();
+
+    // Ignore negative values, which can be caused by system clock changes.
+    if (minutes_since_last_startup >= 0) {
+      UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(
+          UMA_HISTOGRAM_TIME_IN_MINUTES_MONTH_RANGE,
+          "Startup.TimeSinceLastStartup", minutes_since_last_startup);
+    }
+  }
+
+  // Write the timestamp of the current startup in |pref_service|.
+  pref_service->SetInt64(prefs::kLastStartupTimestamp,
+                         process_start_time.ToInternalValue());
+#endif  // defined(OS_MACOSX) || defined(OS_WIN) || defined(OS_LINUX)
+}
+
+// Logs the Startup.SameVersionStartupCount histogram. Relies on |pref_service|
+// to know information about the previous startups and store information for
+// future ones. Returns the number of startups with the same version count that
+// was logged.
+int RecordSameVersionStartupCount(PrefService* pref_service) {
+  DCHECK(pref_service);
+
+  const std::string current_version = version_info::GetVersionNumber();
+
+  int startups_with_current_version = 0;
+  if (current_version == pref_service->GetString(prefs::kLastStartupVersion)) {
+    startups_with_current_version =
+        pref_service->GetInteger(prefs::kSameVersionStartupCount);
+    ++startups_with_current_version;
+    pref_service->SetInteger(prefs::kSameVersionStartupCount,
+                             startups_with_current_version);
+  } else {
+    startups_with_current_version = 1;
+    pref_service->SetString(prefs::kLastStartupVersion, current_version);
+    pref_service->SetInteger(prefs::kSameVersionStartupCount, 1);
+  }
+
+  UMA_HISTOGRAM_COUNTS_100("Startup.SameVersionStartupCount",
+                           startups_with_current_version);
+  return startups_with_current_version;
+}
+
 }  // namespace
 
 #if defined(OS_WIN)
 bool GetHardFaultCountForCurrentProcess(uint32_t* hard_fault_count) {
   DCHECK(hard_fault_count);
 
   if (base::win::GetVersion() < base::win::VERSION_WIN7)
     return false;
 
   // Get the function pointer.
@@ skipping 81 matching lines @@
 }
 
 void RecordExeMainEntryPointTime(const base::Time& time) {
   const std::string exe_load_ticks =
       base::Int64ToString(StartupTimeToTimeTicks(time).ToInternalValue());
   scoped_ptr<base::Environment> env(base::Environment::Create());
   env->SetVar(kChromeMainTicksEnvVar, exe_load_ticks);
 }
 
 void RecordBrowserMainMessageLoopStart(const base::TimeTicks& ticks,
-                                       bool is_first_run) {
+                                       bool is_first_run,
+                                       PrefService* pref_service) {
   AddStartupEventsForTelemetry();
-  RecordHardFaultHistogram(is_first_run);
+  RecordTimeSinceLastStartup(pref_service);

[fdoray, 2016/01/25 18:48:00]

RecordTimeSinceLastStartup needs to be called after RecordHardFaultHistogram
becauses it uses the startup temperature.

[gab, 2016/01/25 21:32:26]

Good catch :-) -- next on my list is to make that NOTREACHED() to catch those
once I've addressed those that are already wrong..!

+  int same_version_startup_count = RecordSameVersionStartupCount(pref_service);
+  RecordHardFaultHistogram(same_version_startup_count);
   RecordSystemUptimeHistogram();
   RecordMainEntryTimeHistogram();
 
   const base::TimeTicks& process_creation_ticks =
       g_process_creation_ticks.Get();
   if (!is_first_run && !process_creation_ticks.is_null()) {
     UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
         UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserMessageLoopStartTime",
         process_creation_ticks, ticks);
   }
@@ skipping 38 matching lines @@
 
       // Process create to chrome.dll:main(). Reported as a histogram only as
       // the other two events above are sufficient for tracing purposes.
       UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(
           UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ProcessCreateToDllMain",
           g_browser_main_entry_point_ticks.Get() - process_creation_ticks);
     }
   }
 }
 
-void RecordTimeSinceLastStartup(PrefService* pref_service) {
-#if defined(OS_MACOSX) || defined(OS_WIN) || defined(OS_LINUX)
-  DCHECK(pref_service);
-
-  // Get the timestamp of the current startup.
-  const base::Time process_start_time =
-      base::CurrentProcessInfo::CreationTime();
-
-  // Get the timestamp of the last startup from |pref_service|.
-  const int64_t last_startup_timestamp_internal =
-      pref_service->GetInt64(prefs::kLastStartupTimestamp);
-  if (last_startup_timestamp_internal != 0) {
-    // Log the Startup.TimeSinceLastStartup histogram.
-    const base::Time last_startup_timestamp =
-        base::Time::FromInternalValue(last_startup_timestamp_internal);
-    const base::TimeDelta time_since_last_startup =
-        process_start_time - last_startup_timestamp;
-    const int minutes_since_last_startup = time_since_last_startup.InMinutes();
-
-    // Ignore negative values, which can be caused by system clock changes.
-    if (minutes_since_last_startup >= 0) {
-      UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(
-          UMA_HISTOGRAM_TIME_IN_MINUTES_MONTH_RANGE,
-          "Startup.TimeSinceLastStartup", minutes_since_last_startup);
-    }
-  }
-
-  // Write the timestamp of the current startup in |pref_service|.
-  pref_service->SetInt64(prefs::kLastStartupTimestamp,
-                         process_start_time.ToInternalValue());
-#endif  // defined(OS_MACOSX) || defined(OS_WIN) || defined(OS_LINUX)
-}
-
-void RecordStartupCount(PrefService* pref_service) {
-  DCHECK(pref_service);
-
-  const std::string current_version = version_info::GetVersionNumber();
-
-  int startups_with_current_version = 0;
-  if (current_version == pref_service->GetString(prefs::kLastStartupVersion)) {
-    startups_with_current_version =
-        pref_service->GetInteger(prefs::kSameVersionStartupCount);
-    ++startups_with_current_version;
-    pref_service->SetInteger(prefs::kSameVersionStartupCount,
-                             startups_with_current_version);
-  } else {
-    startups_with_current_version = 1;
-    pref_service->SetString(prefs::kLastStartupVersion, current_version);
-    pref_service->SetInteger(prefs::kSameVersionStartupCount, 1);
-  }
-
-  UMA_HISTOGRAM_COUNTS_100("Startup.SameVersionStartupCount",
-                           startups_with_current_version);
-}
-
 void RecordBrowserWindowDisplay(const base::TimeTicks& ticks) {
   static bool is_first_call = true;
   if (!is_first_call || ticks.is_null())
     return;
   is_first_call = false;
   if (WasNonBrowserUIDisplayed() || g_process_creation_ticks.Get().is_null())
     return;
 
   UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES, "Startup.BrowserWindowDisplay",
@@ skipping 79 matching lines @@
 
 base::TimeTicks MainEntryPointTicks() {
   return g_browser_main_entry_point_ticks.Get();
 }
 
 StartupTemperature GetStartupTemperature() {
   return g_startup_temperature;
 }
 
 }  // namespace startup_metric_utils