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 (unless |same_version_startup_count| is 0 which indicates it's
+// unknown). 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;
 
+  std::string same_version_startup_count_suffix;
+  if (same_version_startup_count != 0) {
+    // 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;
+    same_version_startup_count_suffix.push_back('.');
+    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 kHardFaultCountHistogram[] =
+      "Startup.BrowserMessageLoopStartHardFaultCount";
+  UMA_HISTOGRAM_CUSTOM_COUNTS(kHardFaultCountHistogram, 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.
+  if (!same_version_startup_count_suffix.empty()) {
+    base::Histogram::FactoryGet(
+        kHardFaultCountHistogram + same_version_startup_count_suffix, 1, 40000,
+        50, base::HistogramBase::kUmaTargetedHistogramFlag)
+        ->Add(hard_fault_count);
   }
 
   // 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);

[fdoray, 2016/01/26 12:13:21]

The comment above the definition of UMA_HISTOGRAM_ENUMERATION says 
"The samples should always be strictly less than |boundary_value|". That
suggests that STARTUP_TEMPERATURE_MAX should not be equal to
LUKEWARM_STARTUP_TEMPERATURE. I haven't looked at the code to see if the comment
is right.

[gab, 2016/01/26 17:59:18]

Ah, I missed that comment and only looked at the code which leads to a
base::LinearHistogram::FactoryGet() with |maximum| set to |boundary_value|, no
where does that class say that maximum is an exclusive boundary.

@jwd: what's the right thing to do here? I guess _COUNT is correct, not _MAX?

[gab, 2016/01/26 18:04:20]

Looking at this closer, the reason I thought this was the case is that the macro
passes |boundary_value + 1| for |bucket_count|, hence I assumed it meant
|boundary_value| was a valid value (though perhaps |bucket_count| includes the
implicit 0?? that'd be a very confusing API if the 0 was implicit but you had to
explicitly count it in your |bucket_count|...)

[jwd, 2016/01/26 18:47:18]

fdoray is correct, the boundary value should be strictly greater than the sample
values. The reason is if you ever want to add extra enum buckets. When you have
a sample of |boundary_value| it's put in a bucket of range [boundary_value,
max_int], which will be problematic when combining with data containing extra
buckets.

So strictly speaking, you can do what you're doing, but you probably shouldn't.

[gab, 2016/01/26 20:10:22]

Aaaah got it, makes sense, thanks!

(maybe the comment in histogram_macros.h could be clearer? or one on
LinearHistogram that states that the max will be in such a special overflow
bucket)

[jwd, 2016/01/26 21:45:37]

Clearer in what sense? The comment on UMA_HISTOGRAM_ENUMERATION seems
unambiguous, and points to the comment on LOCAL_HISTOGRAM_ENUMERATION for a bit
more information. I agree that the the comments on the FactoryGet methods are a
bit unclear, but there's fairly heavy documentation at the top of histograms.h
on how to use these methods.

[gab, 2016/01/26 22:11:32]

I guess I'm bad at reading comment and prefer to follow code and was expecting
comments on LinearHistogram's factory methods directly.

But here's a suggestion for an addition to the LOCAL_HISTOGRAM_ENUMERATION
comment:

"this prevents you from running into problems down the line if you add
additional buckets to the histogram as the overflow bucket will be beyond your
current max instead of including it"

I guess no big deal now that I understand the reason, just trying to make sure
no else loses time on this -- while also not wasting more time on it myself :-).

Also, I'd actually read histogram.h's header comment, but couldn't find the word
"enum" in it nor does it mention that the max value will be in a bucket [max,
MAX_INT] and as such is bad for enums.

Anyways, up to you guys if you want to do something about it, I'm just trying to
explain where my misunderstanding came from in this specific case..

+  // As well as its suffixed twin.
+  // Factory properties copied from UMA_HISTOGRAM_ENUMERATION macro.
+  if (!same_version_startup_count_suffix.empty()) {
+    base::LinearHistogram::FactoryGet(
+        kStartupTemperatureHistogram + same_version_startup_count_suffix, 1,
+        STARTUP_TEMPERATURE_MAX, STARTUP_TEMPERATURE_MAX + 1,
+        base::HistogramBase::kUmaTargetedHistogramFlag)
+        ->Add(g_startup_temperature);
+  }
 #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) {
+  int same_version_startup_count = 0;
+  if (pref_service)
+    same_version_startup_count = RecordSameVersionStartupCount(pref_service);
+  // Keep RecordHardFaultHistogram() first as much as possible as many other
+  // histograms depend on it setting |g_startup_temperature|.
+  RecordHardFaultHistogram(same_version_startup_count);
   AddStartupEventsForTelemetry();
-  RecordHardFaultHistogram(is_first_run);
+  if (pref_service)
+    RecordTimeSinceLastStartup(pref_service);
   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