| OLD | NEW |
| 1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. | 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 | 2 // Use of this source code is governed by a BSD-style license that can be |
| 3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
| 4 | 4 |
| 5 #include "chrome/browser/metrics/metrics_log.h" | 5 #include "chrome/browser/metrics/metrics_log.h" |
| 6 | 6 |
| 7 #include <string> | 7 #include <string> |
| 8 | 8 |
| 9 #include "base/base64.h" | 9 #include "base/base64.h" |
| 10 #include "base/basictypes.h" | 10 #include "base/basictypes.h" |
| 11 #include "base/command_line.h" | 11 #include "base/command_line.h" |
| 12 #include "base/port.h" | 12 #include "base/port.h" |
| 13 #include "base/prefs/pref_service.h" | 13 #include "base/prefs/pref_service.h" |
| 14 #include "base/prefs/testing_pref_service.h" | 14 #include "base/prefs/testing_pref_service.h" |
| 15 #include "base/strings/string_number_conversions.h" | 15 #include "base/strings/string_number_conversions.h" |
| 16 #include "base/strings/string_util.h" | 16 #include "base/strings/string_util.h" |
| 17 #include "base/strings/stringprintf.h" | 17 #include "base/strings/stringprintf.h" |
| 18 #include "base/threading/sequenced_worker_pool.h" | 18 #include "base/threading/sequenced_worker_pool.h" |
| 19 #include "base/time/time.h" | 19 #include "base/time/time.h" |
| 20 #include "base/tracked_objects.h" | |
| 21 #include "chrome/browser/google/google_util.h" | 20 #include "chrome/browser/google/google_util.h" |
| 22 #include "chrome/browser/metrics/metrics_service.h" | 21 #include "chrome/browser/metrics/metrics_service.h" |
| 23 #include "chrome/browser/prefs/browser_prefs.h" | 22 #include "chrome/browser/prefs/browser_prefs.h" |
| 24 #include "chrome/common/chrome_version_info.h" | 23 #include "chrome/common/chrome_version_info.h" |
| 25 #include "chrome/common/pref_names.h" | 24 #include "chrome/common/pref_names.h" |
| 26 #include "components/metrics/metrics_hashes.h" | 25 #include "components/metrics/metrics_hashes.h" |
| 27 #include "components/metrics/metrics_provider.h" | 26 #include "components/metrics/metrics_provider.h" |
| 28 #include "components/metrics/proto/profiler_event.pb.h" | 27 #include "components/metrics/proto/profiler_event.pb.h" |
| 29 #include "components/metrics/proto/system_profile.pb.h" | 28 #include "components/metrics/proto/system_profile.pb.h" |
| 30 #include "components/metrics/test_metrics_service_client.h" | 29 #include "components/metrics/test_metrics_service_client.h" |
| 31 #include "components/variations/active_field_trials.h" | 30 #include "components/variations/active_field_trials.h" |
| 32 #include "content/public/browser/browser_thread.h" | 31 #include "content/public/browser/browser_thread.h" |
| 33 #include "content/public/common/process_type.h" | |
| 34 #include "content/public/test/test_browser_thread_bundle.h" | 32 #include "content/public/test/test_browser_thread_bundle.h" |
| 35 #include "content/public/test/test_utils.h" | 33 #include "content/public/test/test_utils.h" |
| 36 #include "testing/gtest/include/gtest/gtest.h" | 34 #include "testing/gtest/include/gtest/gtest.h" |
| 37 #include "url/gurl.h" | 35 #include "url/gurl.h" |
| 38 | 36 |
| 39 #if defined(OS_CHROMEOS) | 37 #if defined(OS_CHROMEOS) |
| 40 #include "chromeos/login/login_state.h" | 38 #include "chromeos/login/login_state.h" |
| 41 #endif // defined(OS_CHROMEOS) | 39 #endif // defined(OS_CHROMEOS) |
| 42 | 40 |
| 43 using base::TimeDelta; | 41 using base::TimeDelta; |
| 44 using metrics::ProfilerEventProto; | |
| 45 using tracked_objects::ProcessDataSnapshot; | |
| 46 using tracked_objects::TaskSnapshot; | |
| 47 | 42 |
| 48 namespace { | 43 namespace { |
| 49 | 44 |
| 50 const char kClientId[] = "bogus client ID"; | 45 const char kClientId[] = "bogus client ID"; |
| 51 const int64 kInstallDate = 1373051956; | 46 const int64 kInstallDate = 1373051956; |
| 52 const int64 kInstallDateExpected = 1373050800; // Computed from kInstallDate. | 47 const int64 kInstallDateExpected = 1373050800; // Computed from kInstallDate. |
| 53 const int64 kEnabledDate = 1373001211; | 48 const int64 kEnabledDate = 1373001211; |
| 54 const int64 kEnabledDateExpected = 1373000400; // Computed from kEnabledDate. | 49 const int64 kEnabledDateExpected = 1373000400; // Computed from kEnabledDate. |
| 55 const int kSessionId = 127; | 50 const int kSessionId = 127; |
| 56 const variations::ActiveGroupId kFieldTrialIds[] = { | 51 const variations::ActiveGroupId kFieldTrialIds[] = { |
| (...skipping 243 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 300 EXPECT_TRUE(stability.has_launch_count()); | 295 EXPECT_TRUE(stability.has_launch_count()); |
| 301 EXPECT_TRUE(stability.has_crash_count()); | 296 EXPECT_TRUE(stability.has_crash_count()); |
| 302 // Initial log metrics: | 297 // Initial log metrics: |
| 303 EXPECT_FALSE(stability.has_incomplete_shutdown_count()); | 298 EXPECT_FALSE(stability.has_incomplete_shutdown_count()); |
| 304 EXPECT_FALSE(stability.has_breakpad_registration_success_count()); | 299 EXPECT_FALSE(stability.has_breakpad_registration_success_count()); |
| 305 EXPECT_FALSE(stability.has_breakpad_registration_failure_count()); | 300 EXPECT_FALSE(stability.has_breakpad_registration_failure_count()); |
| 306 EXPECT_FALSE(stability.has_debugger_present_count()); | 301 EXPECT_FALSE(stability.has_debugger_present_count()); |
| 307 EXPECT_FALSE(stability.has_debugger_not_present_count()); | 302 EXPECT_FALSE(stability.has_debugger_not_present_count()); |
| 308 } | 303 } |
| 309 | 304 |
| 310 // Test that we properly write profiler data to the log. | |
| 311 TEST_F(MetricsLogTest, RecordProfilerData) { | |
| 312 // WARNING: If you broke the below check, you've modified how | |
| 313 // metrics::HashMetricName works. Please also modify all server-side code that | |
| 314 // relies on the existing way of hashing. | |
| 315 EXPECT_EQ(GG_UINT64_C(1518842999910132863), | |
| 316 metrics::HashMetricName("birth_thread*")); | |
| 317 | |
| 318 metrics::TestMetricsServiceClient client; | |
| 319 TestMetricsLog log( | |
| 320 kClientId, kSessionId, MetricsLog::ONGOING_LOG, &client, &prefs_); | |
| 321 EXPECT_EQ(0, log.uma_proto().profiler_event_size()); | |
| 322 | |
| 323 { | |
| 324 ProcessDataSnapshot process_data; | |
| 325 process_data.process_id = 177; | |
| 326 process_data.tasks.push_back(TaskSnapshot()); | |
| 327 process_data.tasks.back().birth.location.file_name = "a/b/file.h"; | |
| 328 process_data.tasks.back().birth.location.function_name = "function"; | |
| 329 process_data.tasks.back().birth.location.line_number = 1337; | |
| 330 process_data.tasks.back().birth.thread_name = "birth_thread"; | |
| 331 process_data.tasks.back().death_data.count = 37; | |
| 332 process_data.tasks.back().death_data.run_duration_sum = 31; | |
| 333 process_data.tasks.back().death_data.run_duration_max = 17; | |
| 334 process_data.tasks.back().death_data.run_duration_sample = 13; | |
| 335 process_data.tasks.back().death_data.queue_duration_sum = 8; | |
| 336 process_data.tasks.back().death_data.queue_duration_max = 5; | |
| 337 process_data.tasks.back().death_data.queue_duration_sample = 3; | |
| 338 process_data.tasks.back().death_thread_name = "Still_Alive"; | |
| 339 process_data.tasks.push_back(TaskSnapshot()); | |
| 340 process_data.tasks.back().birth.location.file_name = "c\\d\\file2"; | |
| 341 process_data.tasks.back().birth.location.function_name = "function2"; | |
| 342 process_data.tasks.back().birth.location.line_number = 1773; | |
| 343 process_data.tasks.back().birth.thread_name = "birth_thread2"; | |
| 344 process_data.tasks.back().death_data.count = 19; | |
| 345 process_data.tasks.back().death_data.run_duration_sum = 23; | |
| 346 process_data.tasks.back().death_data.run_duration_max = 11; | |
| 347 process_data.tasks.back().death_data.run_duration_sample = 7; | |
| 348 process_data.tasks.back().death_data.queue_duration_sum = 0; | |
| 349 process_data.tasks.back().death_data.queue_duration_max = 0; | |
| 350 process_data.tasks.back().death_data.queue_duration_sample = 0; | |
| 351 process_data.tasks.back().death_thread_name = "death_thread"; | |
| 352 | |
| 353 log.RecordProfilerData(process_data, content::PROCESS_TYPE_BROWSER); | |
| 354 ASSERT_EQ(1, log.uma_proto().profiler_event_size()); | |
| 355 EXPECT_EQ(ProfilerEventProto::STARTUP_PROFILE, | |
| 356 log.uma_proto().profiler_event(0).profile_type()); | |
| 357 EXPECT_EQ(ProfilerEventProto::WALL_CLOCK_TIME, | |
| 358 log.uma_proto().profiler_event(0).time_source()); | |
| 359 | |
| 360 ASSERT_EQ(2, log.uma_proto().profiler_event(0).tracked_object_size()); | |
| 361 | |
| 362 const ProfilerEventProto::TrackedObject* tracked_object = | |
| 363 &log.uma_proto().profiler_event(0).tracked_object(0); | |
| 364 EXPECT_EQ(metrics::HashMetricName("file.h"), | |
| 365 tracked_object->source_file_name_hash()); | |
| 366 EXPECT_EQ(metrics::HashMetricName("function"), | |
| 367 tracked_object->source_function_name_hash()); | |
| 368 EXPECT_EQ(1337, tracked_object->source_line_number()); | |
| 369 EXPECT_EQ(metrics::HashMetricName("birth_thread"), | |
| 370 tracked_object->birth_thread_name_hash()); | |
| 371 EXPECT_EQ(37, tracked_object->exec_count()); | |
| 372 EXPECT_EQ(31, tracked_object->exec_time_total()); | |
| 373 EXPECT_EQ(13, tracked_object->exec_time_sampled()); | |
| 374 EXPECT_EQ(8, tracked_object->queue_time_total()); | |
| 375 EXPECT_EQ(3, tracked_object->queue_time_sampled()); | |
| 376 EXPECT_EQ(metrics::HashMetricName("Still_Alive"), | |
| 377 tracked_object->exec_thread_name_hash()); | |
| 378 EXPECT_EQ(177U, tracked_object->process_id()); | |
| 379 EXPECT_EQ(ProfilerEventProto::TrackedObject::BROWSER, | |
| 380 tracked_object->process_type()); | |
| 381 | |
| 382 tracked_object = &log.uma_proto().profiler_event(0).tracked_object(1); | |
| 383 EXPECT_EQ(metrics::HashMetricName("file2"), | |
| 384 tracked_object->source_file_name_hash()); | |
| 385 EXPECT_EQ(metrics::HashMetricName("function2"), | |
| 386 tracked_object->source_function_name_hash()); | |
| 387 EXPECT_EQ(1773, tracked_object->source_line_number()); | |
| 388 EXPECT_EQ(metrics::HashMetricName("birth_thread*"), | |
| 389 tracked_object->birth_thread_name_hash()); | |
| 390 EXPECT_EQ(19, tracked_object->exec_count()); | |
| 391 EXPECT_EQ(23, tracked_object->exec_time_total()); | |
| 392 EXPECT_EQ(7, tracked_object->exec_time_sampled()); | |
| 393 EXPECT_EQ(0, tracked_object->queue_time_total()); | |
| 394 EXPECT_EQ(0, tracked_object->queue_time_sampled()); | |
| 395 EXPECT_EQ(metrics::HashMetricName("death_thread"), | |
| 396 tracked_object->exec_thread_name_hash()); | |
| 397 EXPECT_EQ(177U, tracked_object->process_id()); | |
| 398 EXPECT_EQ(ProfilerEventProto::TrackedObject::BROWSER, | |
| 399 tracked_object->process_type()); | |
| 400 } | |
| 401 | |
| 402 { | |
| 403 ProcessDataSnapshot process_data; | |
| 404 process_data.process_id = 1177; | |
| 405 process_data.tasks.push_back(TaskSnapshot()); | |
| 406 process_data.tasks.back().birth.location.file_name = "file3"; | |
| 407 process_data.tasks.back().birth.location.function_name = "function3"; | |
| 408 process_data.tasks.back().birth.location.line_number = 7331; | |
| 409 process_data.tasks.back().birth.thread_name = "birth_thread3"; | |
| 410 process_data.tasks.back().death_data.count = 137; | |
| 411 process_data.tasks.back().death_data.run_duration_sum = 131; | |
| 412 process_data.tasks.back().death_data.run_duration_max = 117; | |
| 413 process_data.tasks.back().death_data.run_duration_sample = 113; | |
| 414 process_data.tasks.back().death_data.queue_duration_sum = 108; | |
| 415 process_data.tasks.back().death_data.queue_duration_max = 105; | |
| 416 process_data.tasks.back().death_data.queue_duration_sample = 103; | |
| 417 process_data.tasks.back().death_thread_name = "death_thread3"; | |
| 418 process_data.tasks.push_back(TaskSnapshot()); | |
| 419 process_data.tasks.back().birth.location.file_name = ""; | |
| 420 process_data.tasks.back().birth.location.function_name = ""; | |
| 421 process_data.tasks.back().birth.location.line_number = 7332; | |
| 422 process_data.tasks.back().birth.thread_name = ""; | |
| 423 process_data.tasks.back().death_data.count = 138; | |
| 424 process_data.tasks.back().death_data.run_duration_sum = 132; | |
| 425 process_data.tasks.back().death_data.run_duration_max = 118; | |
| 426 process_data.tasks.back().death_data.run_duration_sample = 114; | |
| 427 process_data.tasks.back().death_data.queue_duration_sum = 109; | |
| 428 process_data.tasks.back().death_data.queue_duration_max = 106; | |
| 429 process_data.tasks.back().death_data.queue_duration_sample = 104; | |
| 430 process_data.tasks.back().death_thread_name = ""; | |
| 431 | |
| 432 log.RecordProfilerData(process_data, content::PROCESS_TYPE_RENDERER); | |
| 433 ASSERT_EQ(1, log.uma_proto().profiler_event_size()); | |
| 434 EXPECT_EQ(ProfilerEventProto::STARTUP_PROFILE, | |
| 435 log.uma_proto().profiler_event(0).profile_type()); | |
| 436 EXPECT_EQ(ProfilerEventProto::WALL_CLOCK_TIME, | |
| 437 log.uma_proto().profiler_event(0).time_source()); | |
| 438 ASSERT_EQ(4, log.uma_proto().profiler_event(0).tracked_object_size()); | |
| 439 | |
| 440 const ProfilerEventProto::TrackedObject* tracked_object = | |
| 441 &log.uma_proto().profiler_event(0).tracked_object(2); | |
| 442 EXPECT_EQ(metrics::HashMetricName("file3"), | |
| 443 tracked_object->source_file_name_hash()); | |
| 444 EXPECT_EQ(metrics::HashMetricName("function3"), | |
| 445 tracked_object->source_function_name_hash()); | |
| 446 EXPECT_EQ(7331, tracked_object->source_line_number()); | |
| 447 EXPECT_EQ(metrics::HashMetricName("birth_thread*"), | |
| 448 tracked_object->birth_thread_name_hash()); | |
| 449 EXPECT_EQ(137, tracked_object->exec_count()); | |
| 450 EXPECT_EQ(131, tracked_object->exec_time_total()); | |
| 451 EXPECT_EQ(113, tracked_object->exec_time_sampled()); | |
| 452 EXPECT_EQ(108, tracked_object->queue_time_total()); | |
| 453 EXPECT_EQ(103, tracked_object->queue_time_sampled()); | |
| 454 EXPECT_EQ(metrics::HashMetricName("death_thread*"), | |
| 455 tracked_object->exec_thread_name_hash()); | |
| 456 EXPECT_EQ(1177U, tracked_object->process_id()); | |
| 457 EXPECT_EQ(ProfilerEventProto::TrackedObject::RENDERER, | |
| 458 tracked_object->process_type()); | |
| 459 | |
| 460 tracked_object = &log.uma_proto().profiler_event(0).tracked_object(3); | |
| 461 EXPECT_EQ(metrics::HashMetricName(""), | |
| 462 tracked_object->source_file_name_hash()); | |
| 463 EXPECT_EQ(metrics::HashMetricName(""), | |
| 464 tracked_object->source_function_name_hash()); | |
| 465 EXPECT_EQ(7332, tracked_object->source_line_number()); | |
| 466 EXPECT_EQ(metrics::HashMetricName(""), | |
| 467 tracked_object->birth_thread_name_hash()); | |
| 468 EXPECT_EQ(138, tracked_object->exec_count()); | |
| 469 EXPECT_EQ(132, tracked_object->exec_time_total()); | |
| 470 EXPECT_EQ(114, tracked_object->exec_time_sampled()); | |
| 471 EXPECT_EQ(109, tracked_object->queue_time_total()); | |
| 472 EXPECT_EQ(104, tracked_object->queue_time_sampled()); | |
| 473 EXPECT_EQ(metrics::HashMetricName(""), | |
| 474 tracked_object->exec_thread_name_hash()); | |
| 475 EXPECT_EQ(ProfilerEventProto::TrackedObject::RENDERER, | |
| 476 tracked_object->process_type()); | |
| 477 } | |
| 478 } | |
| 479 | |
| 480 TEST_F(MetricsLogTest, ChromeChannelWrittenToProtobuf) { | 305 TEST_F(MetricsLogTest, ChromeChannelWrittenToProtobuf) { |
| 481 metrics::TestMetricsServiceClient client; | 306 metrics::TestMetricsServiceClient client; |
| 482 TestMetricsLog log( | 307 TestMetricsLog log( |
| 483 "user@test.com", kSessionId, MetricsLog::ONGOING_LOG, &client, &prefs_); | 308 "user@test.com", kSessionId, MetricsLog::ONGOING_LOG, &client, &prefs_); |
| 484 EXPECT_TRUE(log.uma_proto().system_profile().has_channel()); | 309 EXPECT_TRUE(log.uma_proto().system_profile().has_channel()); |
| 485 } | 310 } |
| OLD | NEW |