src/chrome/browser/metrics/metrics_log_unittest.cc

   1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include <string>
   6
   7 #include "base/basictypes.h"
   8 #include "base/command_line.h"
   9 #include "base/message_loop/message_loop.h"
  10 #include "base/metrics/field_trial.h"
  11 #include "base/port.h"
  12 #include "base/prefs/pref_service.h"
  13 #include "base/prefs/testing_pref_service.h"
  14 #include "base/strings/string_number_conversions.h"
  15 #include "base/strings/string_util.h"
  16 #include "base/strings/stringprintf.h"
  17 #include "base/threading/sequenced_worker_pool.h"
  18 #include "base/time/time.h"
  19 #include "base/tracked_objects.h"
  20 #include "chrome/browser/google/google_util.h"
  21 #include "chrome/browser/metrics/metrics_log.h"
  22 #include "chrome/browser/prefs/browser_prefs.h"
  23 #include "chrome/common/chrome_switches.h"
  24 #include "chrome/common/metrics/proto/profiler_event.pb.h"
  25 #include "chrome/common/metrics/proto/system_profile.pb.h"
  26 #include "chrome/common/metrics/variations/variations_util.h"
  27 #include "chrome/common/pref_names.h"
  28 #include "chrome/installer/util/google_update_settings.h"
  29 #include "components/variations/entropy_provider.h"
  30 #include "content/public/browser/browser_thread.h"
  31 #include "content/public/common/process_type.h"
  32 #include "content/public/common/webplugininfo.h"
  33 #include "content/public/test/test_utils.h"
  34 #include "testing/gtest/include/gtest/gtest.h"
  35 #include "ui/gfx/size.h"
  36 #include "url/gurl.h"
  37
  38 #if defined(OS_CHROMEOS)
  39 #include "chrome/browser/chromeos/login/fake_user_manager.h"
  40 #include "chrome/browser/chromeos/login/user_manager.h"
  41 #include "chromeos/dbus/fake_dbus_thread_manager.h"
  42 #endif  // OS_CHROMEOS
  43
  44 using base::TimeDelta;
  45 using metrics::ProfilerEventProto;
  46 using tracked_objects::ProcessDataSnapshot;
  47 using tracked_objects::TaskSnapshot;
  48
  49 namespace {
  50
  51 const char kClientId[] = "bogus client ID";
  52 const int64 kInstallDate = 1373051956;
  53 const int64 kEnabledDate = 1373001211;
  54 const int kSessionId = 127;
  55 const int kScreenWidth = 1024;
  56 const int kScreenHeight = 768;
  57 const int kScreenCount = 3;
  58 const float kScreenScaleFactor = 2;
  59 const char kBrandForTesting[] = "brand_for_testing";
  60 const chrome_variations::ActiveGroupId kFieldTrialIds[] = {
  61   {37, 43},
  62   {13, 47},
  63   {23, 17}
  64 };
  65
  66 class TestMetricsLog : public MetricsLog {
  67  public:
  68   TestMetricsLog(const std::string& client_id, int session_id)
  69       : MetricsLog(client_id, session_id),
  70         brand_for_testing_(kBrandForTesting) {
  71     chrome::RegisterLocalState(prefs_.registry());
  72
  73     prefs_.SetInt64(prefs::kInstallDate, kInstallDate);
  74     prefs_.SetString(prefs::kMetricsClientIDTimestamp,
  75                      base::Int64ToString(kEnabledDate));
  76 #if defined(OS_CHROMEOS)
  77     prefs_.SetInteger(prefs::kStabilityChildProcessCrashCount, 10);
  78     prefs_.SetInteger(prefs::kStabilityOtherUserCrashCount, 11);
  79     prefs_.SetInteger(prefs::kStabilityKernelCrashCount, 12);
  80     prefs_.SetInteger(prefs::kStabilitySystemUncleanShutdownCount, 13);
  81 #endif  // OS_CHROMEOS
  82   }
  83   virtual ~TestMetricsLog() {}
  84
  85   virtual PrefService* GetPrefService() OVERRIDE {
  86     return &prefs_;
  87   }
  88
  89   const metrics::ChromeUserMetricsExtension& uma_proto() const {
  90     return *MetricsLog::uma_proto();
  91   }
  92
  93   const metrics::SystemProfileProto& system_profile() const {
  94     return uma_proto().system_profile();
  95   }
  96
  97  private:
  98   virtual void GetFieldTrialIds(
  99       std::vector<chrome_variations::ActiveGroupId>* field_trial_ids) const
 100       OVERRIDE {
 101     ASSERT_TRUE(field_trial_ids->empty());
 102
 103     for (size_t i = 0; i < arraysize(kFieldTrialIds); ++i) {
 104       field_trial_ids->push_back(kFieldTrialIds[i]);
 105     }
 106   }
 107
 108   virtual gfx::Size GetScreenSize() const OVERRIDE {
 109     return gfx::Size(kScreenWidth, kScreenHeight);
 110   }
 111
 112   virtual float GetScreenDeviceScaleFactor() const OVERRIDE {
 113     return kScreenScaleFactor;
 114   }
 115
 116   virtual int GetScreenCount() const OVERRIDE {
 117     return kScreenCount;
 118   }
 119
 120   TestingPrefServiceSimple prefs_;
 121
 122   google_util::BrandForTesting brand_for_testing_;
 123
 124   DISALLOW_COPY_AND_ASSIGN(TestMetricsLog);
 125 };
 126
 127 }  // namespace
 128
 129 class MetricsLogTest : public testing::Test {
 130  public:
 131   MetricsLogTest() : message_loop_(base::MessageLoop::TYPE_IO) {}
 132
 133  protected:
 134   void TestRecordEnvironment(bool proto_only) {
 135     TestMetricsLog log(kClientId, kSessionId);
 136
 137     std::vector<content::WebPluginInfo> plugins;
 138     GoogleUpdateMetrics google_update_metrics;
 139     if (proto_only)
 140       log.RecordEnvironmentProto(plugins, google_update_metrics);
 141     else
 142       log.RecordEnvironment(plugins, google_update_metrics, base::TimeDelta());
 143
 144     // Computed from original time of 1373051956.
 145     EXPECT_EQ(1373050800, log.system_profile().install_date());
 146
 147     // Computed from original time of 1373001211.
 148     EXPECT_EQ(1373000400, log.system_profile().uma_enabled_date());
 149
 150     const metrics::SystemProfileProto& system_profile = log.system_profile();
 151     ASSERT_EQ(arraysize(kFieldTrialIds),
 152               static_cast<size_t>(system_profile.field_trial_size()));
 153     for (size_t i = 0; i < arraysize(kFieldTrialIds); ++i) {
 154       const metrics::SystemProfileProto::FieldTrial& field_trial =
 155           system_profile.field_trial(i);
 156       EXPECT_EQ(kFieldTrialIds[i].name, field_trial.name_id());
 157       EXPECT_EQ(kFieldTrialIds[i].group, field_trial.group_id());
 158     }
 159
 160     EXPECT_EQ(kBrandForTesting, system_profile.brand_code());
 161
 162     const metrics::SystemProfileProto::Hardware& hardware =
 163         system_profile.hardware();
 164     EXPECT_EQ(kScreenWidth, hardware.primary_screen_width());
 165     EXPECT_EQ(kScreenHeight, hardware.primary_screen_height());
 166     EXPECT_EQ(kScreenScaleFactor, hardware.primary_screen_scale_factor());
 167     EXPECT_EQ(kScreenCount, hardware.screen_count());
 168
 169     EXPECT_TRUE(hardware.has_cpu());
 170     EXPECT_TRUE(hardware.cpu().has_vendor_name());
 171     EXPECT_TRUE(hardware.cpu().has_signature());
 172
 173     // TODO(isherman): Verify other data written into the protobuf as a result
 174     // of this call.
 175   }
 176
 177   virtual void SetUp() OVERRIDE {
 178 #if defined(OS_CHROMEOS)
 179     fake_dbus_thread_manager_ = new chromeos::FakeDBusThreadManager();
 180     chromeos::DBusThreadManager::InitializeForTesting(
 181         fake_dbus_thread_manager_);
 182
 183     // Enable multi-profiles.
 184     CommandLine::ForCurrentProcess()->AppendSwitch(switches::kMultiProfiles);
 185     field_trial_list_.reset(new base::FieldTrialList(
 186         new metrics::SHA1EntropyProvider("42")));
 187     base::FieldTrialList::CreateTrialsFromString(
 188         "ChromeOSUseMultiProfiles/Enable/",
 189         base::FieldTrialList::ACTIVATE_TRIALS);
 190 #endif  // OS_CHROMEOS
 191   }
 192
 193   virtual void TearDown() OVERRIDE {
 194     // Drain the blocking pool from PostTaskAndReply executed by
 195     // MetrticsLog.network_observer_.
 196     content::BrowserThread::GetBlockingPool()->FlushForTesting();
 197     content::RunAllPendingInMessageLoop();
 198
 199 #if defined(OS_CHROMEOS)
 200     chromeos::DBusThreadManager::Shutdown();
 201 #endif  // OS_CHROMEOS
 202   }
 203
 204  private:
 205   // This is necessary because eventually some tests call base::RepeatingTimer
 206   // functions and a message loop is required for that.
 207   base::MessageLoop message_loop_;
 208
 209 #if defined(OS_CHROMEOS)
 210   chromeos::FakeDBusThreadManager* fake_dbus_thread_manager_;
 211   scoped_ptr<base::FieldTrialList> field_trial_list_;
 212 #endif  // OS_CHROMEOS
 213 };
 214
 215 TEST_F(MetricsLogTest, RecordEnvironment) {
 216   // Test that recording the environment works via both of the public methods
 217   // RecordEnvironment() and RecordEnvironmentProto().
 218   TestRecordEnvironment(false);
 219   TestRecordEnvironment(true);
 220 }
 221
 222 // Test that we properly write profiler data to the log.
 223 TEST_F(MetricsLogTest, RecordProfilerData) {
 224   TestMetricsLog log(kClientId, kSessionId);
 225   EXPECT_EQ(0, log.uma_proto().profiler_event_size());
 226
 227   {
 228     ProcessDataSnapshot process_data;
 229     process_data.process_id = 177;
 230     process_data.tasks.push_back(TaskSnapshot());
 231     process_data.tasks.back().birth.location.file_name = "file";
 232     process_data.tasks.back().birth.location.function_name = "function";
 233     process_data.tasks.back().birth.location.line_number = 1337;
 234     process_data.tasks.back().birth.thread_name = "birth_thread";
 235     process_data.tasks.back().death_data.count = 37;
 236     process_data.tasks.back().death_data.run_duration_sum = 31;
 237     process_data.tasks.back().death_data.run_duration_max = 17;
 238     process_data.tasks.back().death_data.run_duration_sample = 13;
 239     process_data.tasks.back().death_data.queue_duration_sum = 8;
 240     process_data.tasks.back().death_data.queue_duration_max = 5;
 241     process_data.tasks.back().death_data.queue_duration_sample = 3;
 242     process_data.tasks.back().death_thread_name = "Still_Alive";
 243     process_data.tasks.push_back(TaskSnapshot());
 244     process_data.tasks.back().birth.location.file_name = "file2";
 245     process_data.tasks.back().birth.location.function_name = "function2";
 246     process_data.tasks.back().birth.location.line_number = 1773;
 247     process_data.tasks.back().birth.thread_name = "birth_thread2";
 248     process_data.tasks.back().death_data.count = 19;
 249     process_data.tasks.back().death_data.run_duration_sum = 23;
 250     process_data.tasks.back().death_data.run_duration_max = 11;
 251     process_data.tasks.back().death_data.run_duration_sample = 7;
 252     process_data.tasks.back().death_data.queue_duration_sum = 0;
 253     process_data.tasks.back().death_data.queue_duration_max = 0;
 254     process_data.tasks.back().death_data.queue_duration_sample = 0;
 255     process_data.tasks.back().death_thread_name = "death_thread";
 256
 257     log.RecordProfilerData(process_data, content::PROCESS_TYPE_BROWSER);
 258     ASSERT_EQ(1, log.uma_proto().profiler_event_size());
 259     EXPECT_EQ(ProfilerEventProto::STARTUP_PROFILE,
 260               log.uma_proto().profiler_event(0).profile_type());
 261     EXPECT_EQ(ProfilerEventProto::WALL_CLOCK_TIME,
 262               log.uma_proto().profiler_event(0).time_source());
 263
 264     ASSERT_EQ(2, log.uma_proto().profiler_event(0).tracked_object_size());
 265
 266     const ProfilerEventProto::TrackedObject* tracked_object =
 267         &log.uma_proto().profiler_event(0).tracked_object(0);
 268     EXPECT_EQ(GG_UINT64_C(10123486280357988687),
 269               tracked_object->source_file_name_hash());
 270     EXPECT_EQ(GG_UINT64_C(13962325592283560029),
 271               tracked_object->source_function_name_hash());
 272     EXPECT_EQ(1337, tracked_object->source_line_number());
 273     EXPECT_EQ(GG_UINT64_C(3400908935414830400),
 274               tracked_object->birth_thread_name_hash());
 275     EXPECT_EQ(37, tracked_object->exec_count());
 276     EXPECT_EQ(31, tracked_object->exec_time_total());
 277     EXPECT_EQ(13, tracked_object->exec_time_sampled());
 278     EXPECT_EQ(8, tracked_object->queue_time_total());
 279     EXPECT_EQ(3, tracked_object->queue_time_sampled());
 280     EXPECT_EQ(GG_UINT64_C(10151977472163283085),
 281               tracked_object->exec_thread_name_hash());
 282     EXPECT_EQ(177U, tracked_object->process_id());
 283     EXPECT_EQ(ProfilerEventProto::TrackedObject::BROWSER,
 284               tracked_object->process_type());
 285
 286     tracked_object = &log.uma_proto().profiler_event(0).tracked_object(1);
 287     EXPECT_EQ(GG_UINT64_C(2025659946535236365),
 288               tracked_object->source_file_name_hash());
 289     EXPECT_EQ(GG_UINT64_C(55232426147951219),
 290               tracked_object->source_function_name_hash());
 291     EXPECT_EQ(1773, tracked_object->source_line_number());
 292     EXPECT_EQ(GG_UINT64_C(15727396632046120663),
 293               tracked_object->birth_thread_name_hash());
 294     EXPECT_EQ(19, tracked_object->exec_count());
 295     EXPECT_EQ(23, tracked_object->exec_time_total());
 296     EXPECT_EQ(7, tracked_object->exec_time_sampled());
 297     EXPECT_EQ(0, tracked_object->queue_time_total());
 298     EXPECT_EQ(0, tracked_object->queue_time_sampled());
 299     EXPECT_EQ(GG_UINT64_C(14275151213201158253),
 300               tracked_object->exec_thread_name_hash());
 301     EXPECT_EQ(177U, tracked_object->process_id());
 302     EXPECT_EQ(ProfilerEventProto::TrackedObject::BROWSER,
 303               tracked_object->process_type());
 304   }
 305
 306   {
 307     ProcessDataSnapshot process_data;
 308     process_data.process_id = 1177;
 309     process_data.tasks.push_back(TaskSnapshot());
 310     process_data.tasks.back().birth.location.file_name = "file3";
 311     process_data.tasks.back().birth.location.function_name = "function3";
 312     process_data.tasks.back().birth.location.line_number = 7331;
 313     process_data.tasks.back().birth.thread_name = "birth_thread3";
 314     process_data.tasks.back().death_data.count = 137;
 315     process_data.tasks.back().death_data.run_duration_sum = 131;
 316     process_data.tasks.back().death_data.run_duration_max = 117;
 317     process_data.tasks.back().death_data.run_duration_sample = 113;
 318     process_data.tasks.back().death_data.queue_duration_sum = 108;
 319     process_data.tasks.back().death_data.queue_duration_max = 105;
 320     process_data.tasks.back().death_data.queue_duration_sample = 103;
 321     process_data.tasks.back().death_thread_name = "death_thread3";
 322
 323     log.RecordProfilerData(process_data, content::PROCESS_TYPE_RENDERER);
 324     ASSERT_EQ(1, log.uma_proto().profiler_event_size());
 325     EXPECT_EQ(ProfilerEventProto::STARTUP_PROFILE,
 326               log.uma_proto().profiler_event(0).profile_type());
 327     EXPECT_EQ(ProfilerEventProto::WALL_CLOCK_TIME,
 328               log.uma_proto().profiler_event(0).time_source());
 329     ASSERT_EQ(3, log.uma_proto().profiler_event(0).tracked_object_size());
 330
 331     const ProfilerEventProto::TrackedObject* tracked_object =
 332         &log.uma_proto().profiler_event(0).tracked_object(2);
 333     EXPECT_EQ(GG_UINT64_C(2686523203278102732),
 334               tracked_object->source_file_name_hash());
 335     EXPECT_EQ(GG_UINT64_C(5081672290546182009),
 336               tracked_object->source_function_name_hash());
 337     EXPECT_EQ(7331, tracked_object->source_line_number());
 338     EXPECT_EQ(GG_UINT64_C(8768512930949373716),
 339               tracked_object->birth_thread_name_hash());
 340     EXPECT_EQ(137, tracked_object->exec_count());
 341     EXPECT_EQ(131, tracked_object->exec_time_total());
 342     EXPECT_EQ(113, tracked_object->exec_time_sampled());
 343     EXPECT_EQ(108, tracked_object->queue_time_total());
 344     EXPECT_EQ(103, tracked_object->queue_time_sampled());
 345     EXPECT_EQ(GG_UINT64_C(7246674144371406371),
 346               tracked_object->exec_thread_name_hash());
 347     EXPECT_EQ(1177U, tracked_object->process_id());
 348     EXPECT_EQ(ProfilerEventProto::TrackedObject::RENDERER,
 349               tracked_object->process_type());
 350   }
 351 }
 352
 353 #if defined(OS_CHROMEOS)
 354 TEST_F(MetricsLogTest, MultiProfileUserCount) {
 355   std::string user1("user1@example.com");
 356   std::string user2("user2@example.com");
 357   std::string user3("user3@example.com");
 358
 359   // |scoped_enabler| takes over the lifetime of |user_manager|.
 360   chromeos::FakeUserManager* user_manager = new chromeos::FakeUserManager();
 361   chromeos::ScopedUserManagerEnabler scoped_enabler(user_manager);
 362   user_manager->AddKioskAppUser(user1);
 363   user_manager->AddKioskAppUser(user2);
 364   user_manager->AddKioskAppUser(user3);
 365
 366   user_manager->LoginUser(user1);
 367   user_manager->LoginUser(user3);
 368
 369   TestMetricsLog log(kClientId, kSessionId);
 370   std::vector<content::WebPluginInfo> plugins;
 371   GoogleUpdateMetrics google_update_metrics;
 372   log.RecordEnvironmentProto(plugins, google_update_metrics);
 373   EXPECT_EQ(2u, log.system_profile().multi_profile_user_count());
 374 }
 375
 376 TEST_F(MetricsLogTest, MultiProfileCountInvalidated) {
 377   std::string user1("user1@example.com");
 378   std::string user2("user2@example.com");
 379   std::string user3("user3@example.com");
 380
 381   // |scoped_enabler| takes over the lifetime of |user_manager|.
 382   chromeos::FakeUserManager* user_manager = new chromeos::FakeUserManager();
 383   chromeos::ScopedUserManagerEnabler scoped_enabler(user_manager);
 384   user_manager->AddKioskAppUser(user1);
 385   user_manager->AddKioskAppUser(user2);
 386   user_manager->AddKioskAppUser(user3);
 387
 388   user_manager->LoginUser(user1);
 389
 390   TestMetricsLog log(kClientId, kSessionId);
 391   EXPECT_EQ(1u, log.system_profile().multi_profile_user_count());
 392
 393   user_manager->LoginUser(user2);
 394   log.RecordEnvironmentProto(std::vector<content::WebPluginInfo>(),
 395                              GoogleUpdateMetrics());
 396   EXPECT_EQ(0u, log.system_profile().multi_profile_user_count());
 397 }
 398 #endif  // OS_CHROMEOS