diff options
| -rw-r--r-- | chrome/browser/metrics/metrics_log_serializer.cc | 198 | ||||
| -rw-r--r-- | chrome/browser/metrics/metrics_log_serializer.h | 69 | ||||
| -rw-r--r-- | chrome/browser/metrics/metrics_log_serializer_unittest.cc | 192 | ||||
| -rw-r--r-- | chrome/browser/metrics/metrics_service.cc | 399 | ||||
| -rw-r--r-- | chrome/browser/metrics/metrics_service.h | 92 | ||||
| -rw-r--r-- | chrome/browser/metrics/metrics_service_unittest.cc | 173 | ||||
| -rw-r--r-- | chrome/chrome_browser.gypi | 2 | ||||
| -rw-r--r-- | chrome/chrome_common.gypi | 2 | ||||
| -rw-r--r-- | chrome/chrome_tests.gypi | 2 | ||||
| -rw-r--r-- | chrome/common/metrics_helpers.cc | 71 | ||||
| -rw-r--r-- | chrome/common/metrics_helpers.h | 26 | ||||
| -rw-r--r-- | chrome/common/metrics_log_manager.cc | 162 | ||||
| -rw-r--r-- | chrome/common/metrics_log_manager.h | 154 | ||||
| -rw-r--r-- | chrome/common/metrics_log_manager_unittest.cc | 211 | ||||
| -rw-r--r-- | chrome_frame/metrics_service.cc | 60 | ||||
| -rw-r--r-- | chrome_frame/metrics_service.h | 3 |
16 files changed, 1118 insertions, 698 deletions
diff --git a/chrome/browser/metrics/metrics_log_serializer.cc b/chrome/browser/metrics/metrics_log_serializer.cc new file mode 100644 index 0000000..bbddf60 --- /dev/null +++ b/chrome/browser/metrics/metrics_log_serializer.cc @@ -0,0 +1,198 @@ +// Copyright (c) 2011 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_serializer.h" + +#include "base/base64.h" +#include "base/md5.h" +#include "base/metrics/histogram.h" +#include "chrome/browser/browser_process.h" +#include "chrome/browser/prefs/pref_service.h" +#include "chrome/browser/prefs/scoped_user_pref_update.h" +#include "chrome/common/pref_names.h" + +// The number of "initial" logs we're willing to save, and hope to send during +// a future Chrome session. Initial logs contain crash stats, and are pretty +// small. +static const size_t kMaxInitialLogsPersisted = 20; + +// The number of ongoing logs we're willing to save persistently, and hope to +// send during a this or future sessions. Note that each log may be pretty +// large, as presumably the related "initial" log wasn't sent (probably nothing +// was, as the user was probably off-line). As a result, the log probably kept +// accumulating while the "initial" log was stalled, and couldn't be sent. As a +// result, we don't want to save too many of these mega-logs. +// A "standard shutdown" will create a small log, including just the data that +// was not yet been transmitted, and that is normal (to have exactly one +// ongoing_log_ at startup). +static const size_t kMaxOngoingLogsPersisted = 8; + +// We append (2) more elements to persisted lists: the size of the list and a +// checksum of the elements. +static const size_t kChecksumEntryCount = 2; + +namespace { +// TODO(ziadh): This is here temporarily for a side experiment. Remove later +// on. +enum LogStoreStatus { + STORE_SUCCESS, // Successfully presisted log. + ENCODE_FAIL, // Failed to encode log. + COMPRESS_FAIL, // Failed to compress log. + END_STORE_STATUS // Number of bins to use to create the histogram. +}; + +MetricsLogSerializer::LogReadStatus MakeRecallStatusHistogram( + MetricsLogSerializer::LogReadStatus status) { + UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogRecall", status, + MetricsLogSerializer::END_RECALL_STATUS); + return status; +} + +// TODO(ziadh): Remove this when done with experiment. +void MakeStoreStatusHistogram(LogStoreStatus status) { + UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogStore2", status, + END_STORE_STATUS); +} +} // namespace + + +MetricsLogSerializer::MetricsLogSerializer() {} + +MetricsLogSerializer::~MetricsLogSerializer() {} + +void MetricsLogSerializer::SerializeLogs(const std::vector<std::string>& logs, + MetricsLogManager::LogType log_type) { + PrefService* local_state = g_browser_process->local_state(); + DCHECK(local_state); + const char* pref = NULL; + size_t max_store_count = 0; + switch (log_type) { + case MetricsLogManager::INITIAL_LOG: + pref = prefs::kMetricsInitialLogs; + max_store_count = kMaxInitialLogsPersisted; + break; + case MetricsLogManager::ONGOING_LOG: + pref = prefs::kMetricsOngoingLogs; + max_store_count = kMaxOngoingLogsPersisted; + break; + default: + NOTREACHED(); + return; + }; + ListPrefUpdate update(local_state, pref); + ListValue* pref_list = update.Get(); + WriteLogsToPrefList(logs, max_store_count, pref_list); +} + +void MetricsLogSerializer::DeserializeLogs(MetricsLogManager::LogType log_type, + std::vector<std::string>* logs) { + DCHECK(logs); + PrefService* local_state = g_browser_process->local_state(); + DCHECK(local_state); + + const char* pref = (log_type == MetricsLogManager::INITIAL_LOG) ? + prefs::kMetricsInitialLogs : prefs::kMetricsOngoingLogs; + const ListValue* unsent_logs = local_state->GetList(pref); + ReadLogsFromPrefList(*unsent_logs, logs); +} + +// static +void MetricsLogSerializer::WriteLogsToPrefList( + const std::vector<std::string>& local_list, + const size_t kMaxLocalListSize, + ListValue* list) { + list->Clear(); + size_t start = 0; + if (local_list.size() > kMaxLocalListSize) + start = local_list.size() - kMaxLocalListSize; + DCHECK(start <= local_list.size()); + if (local_list.size() <= start) + return; + + // Store size at the beginning of the list. + list->Append(Value::CreateIntegerValue(local_list.size() - start)); + + base::MD5Context ctx; + base::MD5Init(&ctx); + std::string encoded_log; + for (std::vector<std::string>::const_iterator it = local_list.begin() + start; + it != local_list.end(); ++it) { + // We encode the compressed log as Value::CreateStringValue() expects to + // take a valid UTF8 string. + if (!base::Base64Encode(*it, &encoded_log)) { + MakeStoreStatusHistogram(ENCODE_FAIL); + list->Clear(); + return; + } + base::MD5Update(&ctx, encoded_log); + list->Append(Value::CreateStringValue(encoded_log)); + } + + // Append hash to the end of the list. + base::MD5Digest digest; + base::MD5Final(&digest, &ctx); + list->Append(Value::CreateStringValue(base::MD5DigestToBase16(digest))); + DCHECK(list->GetSize() >= 3); // Minimum of 3 elements (size, data, hash). + MakeStoreStatusHistogram(STORE_SUCCESS); +} + +// static +MetricsLogSerializer::LogReadStatus MetricsLogSerializer::ReadLogsFromPrefList( + const ListValue& list, + std::vector<std::string>* local_list) { + DCHECK(local_list->empty()); + if (list.GetSize() == 0) + return MakeRecallStatusHistogram(LIST_EMPTY); + if (list.GetSize() < 3) + return MakeRecallStatusHistogram(LIST_SIZE_TOO_SMALL); + + // The size is stored at the beginning of the list. + int size; + bool valid = (*list.begin())->GetAsInteger(&size); + if (!valid) + return MakeRecallStatusHistogram(LIST_SIZE_MISSING); + + // Account for checksum and size included in the list. + if (static_cast<unsigned int>(size) != + list.GetSize() - kChecksumEntryCount) { + return MakeRecallStatusHistogram(LIST_SIZE_CORRUPTION); + } + + base::MD5Context ctx; + base::MD5Init(&ctx); + std::string encoded_log; + std::string decoded_log; + for (ListValue::const_iterator it = list.begin() + 1; + it != list.end() - 1; ++it) { // Last element is the checksum. + valid = (*it)->GetAsString(&encoded_log); + if (!valid) { + local_list->clear(); + return MakeRecallStatusHistogram(LOG_STRING_CORRUPTION); + } + + base::MD5Update(&ctx, encoded_log); + + if (!base::Base64Decode(encoded_log, &decoded_log)) { + local_list->clear(); + return MakeRecallStatusHistogram(DECODE_FAIL); + } + local_list->push_back(decoded_log); + } + + // Verify checksum. + base::MD5Digest digest; + base::MD5Final(&digest, &ctx); + std::string recovered_md5; + // We store the hash at the end of the list. + valid = (*(list.end() - 1))->GetAsString(&recovered_md5); + if (!valid) { + local_list->clear(); + return MakeRecallStatusHistogram(CHECKSUM_STRING_CORRUPTION); + } + if (recovered_md5 != base::MD5DigestToBase16(digest)) { + local_list->clear(); + return MakeRecallStatusHistogram(CHECKSUM_CORRUPTION); + } + return MakeRecallStatusHistogram(RECALL_SUCCESS); +} diff --git a/chrome/browser/metrics/metrics_log_serializer.h b/chrome/browser/metrics/metrics_log_serializer.h new file mode 100644 index 0000000..d698164 --- /dev/null +++ b/chrome/browser/metrics/metrics_log_serializer.h @@ -0,0 +1,69 @@ +// Copyright (c) 2011 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. + +#ifndef CHROME_BROWSER_METRICS_METRICS_LOG_SERIALIZER_H_ +#define CHROME_BROWSER_METRICS_METRICS_LOG_SERIALIZER_H_ +#pragma once + +#include "base/basictypes.h" +#include "base/gtest_prod_util.h" +#include "chrome/common/metrics_log_manager.h" + +namespace base { +class ListValue; +} + +// Serializer for persisting metrics logs to prefs. +class MetricsLogSerializer : public MetricsLogManager::LogSerializer { + public: + // Used to produce a historgram that keeps track of the status of recalling + // persisted per logs. + enum LogReadStatus { + RECALL_SUCCESS, // We were able to correctly recall a persisted log. + LIST_EMPTY, // Attempting to recall from an empty list. + LIST_SIZE_MISSING, // Failed to recover list size using GetAsInteger(). + LIST_SIZE_TOO_SMALL, // Too few elements in the list (less than 3). + LIST_SIZE_CORRUPTION, // List size is not as expected. + LOG_STRING_CORRUPTION, // Failed to recover log string using GetAsString(). + CHECKSUM_CORRUPTION, // Failed to verify checksum. + CHECKSUM_STRING_CORRUPTION, // Failed to recover checksum string using + // GetAsString(). + DECODE_FAIL, // Failed to decode log. + END_RECALL_STATUS // Number of bins to use to create the histogram. + }; + + MetricsLogSerializer(); + virtual ~MetricsLogSerializer(); + + // Implementation of MetricsLogManager::LogSerializer + virtual void SerializeLogs(const std::vector<std::string>& logs, + MetricsLogManager::LogType log_type); + virtual void DeserializeLogs(MetricsLogManager::LogType log_type, + std::vector<std::string>* logs); + + private: + // Encodes the textual log data from |local_list| and writes it to the given + // pref list, along with list size and checksum. + static void WriteLogsToPrefList(const std::vector<std::string>& local_list, + const size_t kMaxLocalListSize, + base::ListValue* list); + + // Decodes and verifies the textual log data from |list|, populating + // |local_list| and returning a status code. + static LogReadStatus ReadLogsFromPrefList( + const base::ListValue& list, + std::vector<std::string>* local_list); + + FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, EmptyLogList); + FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, SingleElementLogList); + FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, OverLimitLogList); + FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, SmallRecoveredListSize); + FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, RemoveSizeFromLogList); + FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, CorruptSizeOfLogList); + FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, CorruptChecksumOfLogList); + + DISALLOW_COPY_AND_ASSIGN(MetricsLogSerializer); +}; + +#endif // CHROME_BROWSER_METRICS_METRICS_LOG_SERIALIZER_H_ diff --git a/chrome/browser/metrics/metrics_log_serializer_unittest.cc b/chrome/browser/metrics/metrics_log_serializer_unittest.cc new file mode 100644 index 0000000..59c257b --- /dev/null +++ b/chrome/browser/metrics/metrics_log_serializer_unittest.cc @@ -0,0 +1,192 @@ +// Copyright (c) 2011 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 "base/base64.h" +#include "base/md5.h" +#include "base/values.h" +#include "chrome/browser/metrics/metrics_log_serializer.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace { + class MetricsLogSerializerTest : public ::testing::Test { + }; +} + +static const size_t kMaxLocalListSize = 3; + +// Store and retrieve empty list. +TEST(MetricsLogSerializerTest, EmptyLogList) { + ListValue list; + std::vector<std::string> local_list; + + MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + &list); + EXPECT_EQ(0U, list.GetSize()); + + local_list.clear(); // ReadLogsFromPrefList() expects empty |local_list|. + EXPECT_EQ(MetricsLogSerializer::LIST_EMPTY, + MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ(0U, local_list.size()); +} + +// Store and retrieve a single log value. +TEST(MetricsLogSerializerTest, SingleElementLogList) { + ListValue list; + std::vector<std::string> local_list; + + local_list.push_back("Hello world!"); + EXPECT_EQ(1U, local_list.size()); + + MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + &list); + + // |list| will now contain the following: + // [1, Base64Encode("Hello world!"), MD5("Hello world!")]. + EXPECT_EQ(3U, list.GetSize()); + + // Examine each element. + ListValue::const_iterator it = list.begin(); + int size = 0; + (*it)->GetAsInteger(&size); + EXPECT_EQ(1, size); + + ++it; + std::string str; + (*it)->GetAsString(&str); // Base64 encoded "Hello world!" string. + std::string encoded; + base::Base64Encode("Hello world!", &encoded); + EXPECT_TRUE(encoded == str); + + ++it; + (*it)->GetAsString(&str); // MD5 for encoded "Hello world!" string. + EXPECT_TRUE(base::MD5String(encoded) == str); + + ++it; + EXPECT_TRUE(it == list.end()); // Reached end of list. + + local_list.clear(); + EXPECT_EQ(MetricsLogSerializer::RECALL_SUCCESS, + MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ(1U, local_list.size()); +} + +// Store elements greater than the limit. +TEST(MetricsLogSerializerTest, OverLimitLogList) { + ListValue list; + std::vector<std::string> local_list; + + local_list.push_back("one"); + local_list.push_back("two"); + local_list.push_back("three"); + local_list.push_back("four"); + EXPECT_EQ(4U, local_list.size()); + + std::string expected_first; + base::Base64Encode(local_list[local_list.size() - kMaxLocalListSize], + &expected_first); + std::string expected_last; + base::Base64Encode(local_list[local_list.size() - 1], + &expected_last); + + MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + &list); + EXPECT_EQ(kMaxLocalListSize + 2, list.GetSize()); + + std::string actual_first; + EXPECT_TRUE((*(list.begin() + 1))->GetAsString(&actual_first)); + EXPECT_TRUE(expected_first == actual_first); + + std::string actual_last; + EXPECT_TRUE((*(list.end() - 2))->GetAsString(&actual_last)); + EXPECT_TRUE(expected_last == actual_last); + + local_list.clear(); + EXPECT_EQ(MetricsLogSerializer::RECALL_SUCCESS, + MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ(kMaxLocalListSize, local_list.size()); +} + +// Induce LIST_SIZE_TOO_SMALL corruption +TEST(MetricsLogSerializerTest, SmallRecoveredListSize) { + ListValue list; + std::vector<std::string> local_list; + + local_list.push_back("Hello world!"); + EXPECT_EQ(1U, local_list.size()); + MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + &list); + EXPECT_EQ(3U, list.GetSize()); + + // Remove last element. + list.Remove(list.GetSize() - 1, NULL); + EXPECT_EQ(2U, list.GetSize()); + + local_list.clear(); + EXPECT_EQ(MetricsLogSerializer::LIST_SIZE_TOO_SMALL, + MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); +} + +// Remove size from the stored list. +TEST(MetricsLogSerializerTest, RemoveSizeFromLogList) { + ListValue list; + std::vector<std::string> local_list; + + local_list.push_back("one"); + local_list.push_back("two"); + EXPECT_EQ(2U, local_list.size()); + MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + &list); + EXPECT_EQ(4U, list.GetSize()); + + list.Remove(0, NULL); // Delete size (1st element). + EXPECT_EQ(3U, list.GetSize()); + + local_list.clear(); + EXPECT_EQ(MetricsLogSerializer::LIST_SIZE_MISSING, + MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); +} + +// Corrupt size of stored list. +TEST(MetricsLogSerializerTest, CorruptSizeOfLogList) { + ListValue list; + std::vector<std::string> local_list; + + local_list.push_back("Hello world!"); + EXPECT_EQ(1U, local_list.size()); + MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + &list); + EXPECT_EQ(3U, list.GetSize()); + + // Change list size from 1 to 2. + EXPECT_TRUE(list.Set(0, Value::CreateIntegerValue(2))); + EXPECT_EQ(3U, list.GetSize()); + + local_list.clear(); + EXPECT_EQ(MetricsLogSerializer::LIST_SIZE_CORRUPTION, + MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); +} + +// Corrupt checksum of stored list. +TEST(MetricsLogSerializerTest, CorruptChecksumOfLogList) { + ListValue list; + std::vector<std::string> local_list; + + local_list.clear(); + local_list.push_back("Hello world!"); + EXPECT_EQ(1U, local_list.size()); + MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + &list); + EXPECT_EQ(3U, list.GetSize()); + + // Fetch checksum (last element) and change it. + std::string checksum; + EXPECT_TRUE((*(list.end() - 1))->GetAsString(&checksum)); + checksum[0] = (checksum[0] == 'a') ? 'b' : 'a'; + EXPECT_TRUE(list.Set(2, Value::CreateStringValue(checksum))); + EXPECT_EQ(3U, list.GetSize()); + + local_list.clear(); + EXPECT_EQ(MetricsLogSerializer::CHECKSUM_CORRUPTION, + MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); +} diff --git a/chrome/browser/metrics/metrics_service.cc b/chrome/browser/metrics/metrics_service.cc index 4efdc8c..2072626 100644 --- a/chrome/browser/metrics/metrics_service.cc +++ b/chrome/browser/metrics/metrics_service.cc @@ -49,10 +49,7 @@ // // When the browser shuts down, there will typically be a fragment of an ongoing // log that has not yet been transmitted. At shutdown time, that fragment -// is closed (including snapshotting histograms), and converted to text. Note -// that memory stats are not gathered during shutdown, as gathering *might* be -// too time consuming. The textual representation of the fragment of the -// ongoing log is then stored persistently as a string in the PrefServices, for +// is closed (including snapshotting histograms), and persisted, for // potential transmission during a future run of the product. // // There are two slightly abnormal shutdown conditions. There is a @@ -82,7 +79,6 @@ // INIT_TASK_SCHEDULED, // Waiting for deferred init tasks to complete. // INIT_TASK_DONE, // Waiting for timer to send initial log. // INITIAL_LOG_READY, // Initial log generated, and waiting for reply. -// SEND_OLD_INITIAL_LOGS, // Sending unsent logs from previous session. // SENDING_OLD_LOGS, // Sending unsent logs from previous session. // SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue. // @@ -109,17 +105,12 @@ // prepared for transmission. It is also the case that any previously unsent // logs have been loaded into instance variables for possible transmission. // -// SEND_OLD_INITIAL_LOGS, // Sending unsent logs from previous session. -// This state indicates that the initial log for this session has been -// successfully sent and it is now time to send any "initial logs" that were -// saved from previous sessions. Most commonly, there are none, but all old -// logs that were "initial logs" must be sent before this state is exited. -// // SENDING_OLD_LOGS, // Sending unsent logs from previous session. -// This state indicates that there are no more unsent initial logs, and now any -// ongoing logs from previous sessions should be transmitted. All such logs -// will be transmitted before exiting this state, and proceeding with ongoing -// logs from the current session (see next state). +// This state indicates that the initial log for this session has been +// successfully sent and it is now time to send any logs that were +// saved from previous sessions. All such logs will be transmitted before +// exiting this state, and proceeding with ongoing logs from the current session +// (see next state). // // SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue. // Current logs are being accumulated. Typically every 20 minutes a log is @@ -131,19 +122,16 @@ // and remain in the latter until shutdown. // // The one unusual case is when the user asks that we stop logging. When that -// happens, any pending (transmission in progress) log is pushed into the list -// of old unsent logs (the appropriate list, depending on whether it is an -// initial log, or an ongoing log). An addition, any log that is currently -// accumulating is also finalized, and pushed into the unsent log list. With -// those pushes performed, we regress back to the SEND_OLD_INITIAL_LOGS state in -// case the user enables log recording again during this session. This way -// anything we have "pushed back" will be sent automatically if/when we progress -// back to SENDING_CURRENT_LOG state. +// happens, any staged (transmission in progress) log is persisted, and any log +// log that is currently accumulating is also finalized and persisted. We then +// regress back to the SEND_OLD_LOGS state in case the user enables log +// recording again during this session. This way anything we have persisted +// will be sent automatically if/when we progress back to SENDING_CURRENT_LOG +// state. // -// Also note that whenever the member variables containing unsent logs are -// modified (i.e., when we send an old log), we mirror the list of logs into -// the PrefServices. This ensures that IF we crash, we won't start up and -// retransmit our old logs again. +// Also note that whenever we successfully send an old log, we mirror the list +// of logs into the PrefService. This ensures that IF we crash, we won't start +// up and retransmit our old logs again. // // Due to race conditions, it is always possible that a log file could be sent // twice. For example, if a log file is sent, but not yet acknowledged by @@ -156,14 +144,12 @@ #include "chrome/browser/metrics/metrics_service.h" -#include "base/base64.h" #include "base/bind.h" #include "base/callback.h" #include "base/command_line.h" #include "base/md5.h" #include "base/metrics/histogram.h" #include "base/string_number_conversions.h" -#include "base/string_util.h" // For WriteInto(). #include "base/threading/platform_thread.h" #include "base/threading/thread.h" #include "base/utf_string_conversions.h" @@ -173,6 +159,7 @@ #include "chrome/browser/memory_details.h" #include "chrome/browser/metrics/histogram_synchronizer.h" #include "chrome/browser/metrics/metrics_log.h" +#include "chrome/browser/metrics/metrics_log_serializer.h" #include "chrome/browser/metrics/metrics_reporting_scheduler.h" #include "chrome/browser/net/network_stats.h" #include "chrome/browser/prefs/pref_service.h" @@ -184,6 +171,7 @@ #include "chrome/common/chrome_notification_types.h" #include "chrome/common/chrome_switches.h" #include "chrome/common/guid.h" +#include "chrome/common/metrics_log_manager.h" #include "chrome/common/pref_names.h" #include "chrome/common/render_messages.h" #include "content/browser/load_notification_details.h" @@ -205,21 +193,6 @@ #include "chrome/browser/chromeos/system/statistics_provider.h" #endif -namespace { -MetricsService::LogRecallStatus MakeRecallStatusHistogram( - MetricsService::LogRecallStatus status) { - UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogRecall", status, - MetricsService::END_RECALL_STATUS); - return status; -} - -// TODO(ziadh): Remove this when done with experiment. -void MakeStoreStatusHistogram(MetricsService::LogStoreStatus status) { - UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogStore2", status, - MetricsService::END_STORE_STATUS); -} -} // namespace - using base::Time; // Check to see that we're being called on only one thread. @@ -247,26 +220,6 @@ static const int kUploadLogAvoidRetransmitSize = 50000; // Interval, in seconds, between state saves. static const int kSaveStateInterval = 5 * 60; // five minutes -// The number of "initial" logs we're willing to save, and hope to send during -// a future Chrome session. Initial logs contain crash stats, and are pretty -// small. -static const size_t kMaxInitialLogsPersisted = 20; - -// The number of ongoing logs we're willing to save persistently, and hope to -// send during a this or future sessions. Note that each log may be pretty -// large, as presumably the related "initial" log wasn't sent (probably nothing -// was, as the user was probably off-line). As a result, the log probably kept -// accumulating while the "initial" log was stalled (pending_), and couldn't be -// sent. As a result, we don't want to save too many of these mega-logs. -// A "standard shutdown" will create a small log, including just the data that -// was not yet been transmitted, and that is normal (to have exactly one -// ongoing_log_ at startup). -static const size_t kMaxOngoingLogsPersisted = 8; - -// We append (2) more elements to persisted lists: the size of the list and a -// checksum of the elements. -static const size_t kChecksumEntryCount = 2; - // static MetricsService::ShutdownCleanliness MetricsService::clean_shutdown_status_ = MetricsService::CLEANLY_SHUTDOWN; @@ -419,6 +372,8 @@ MetricsService::MetricsService() base::Closure callback = base::Bind(&MetricsService::StartScheduledUpload, base::Unretained(this)); scheduler_.reset(new MetricsReportingScheduler(callback)); + log_manager_.set_log_serializer(new MetricsLogSerializer()); + log_manager_.set_max_ongoing_log_store_size(kUploadLogAvoidRetransmitSize); } MetricsService::~MetricsService() { @@ -472,10 +427,10 @@ void MetricsService::SetRecording(bool enabled) { SetUpNotifications(®istrar_, this); } else { registrar_.RemoveAll(); - PushPendingLogsToUnsentLists(); - DCHECK(!pending_log()); - if (state_ > INITIAL_LOG_READY && unsent_logs()) - state_ = SEND_OLD_INITIAL_LOGS; + PushPendingLogsToPersistentStorage(); + DCHECK(!log_manager_.has_staged_log()); + if (state_ > INITIAL_LOG_READY && log_manager_.has_unsent_logs()) + state_ = SENDING_OLD_LOGS; } recording_active_ = enabled; } @@ -536,7 +491,7 @@ void MetricsService::SetUpNotifications(NotificationRegistrar* registrar, void MetricsService::Observe(int type, const NotificationSource& source, const NotificationDetails& details) { - DCHECK(current_log_); + DCHECK(log_manager_.current_log()); DCHECK(IsSingleThreaded()); if (!CanLogNotification(type, source, details)) @@ -544,7 +499,8 @@ void MetricsService::Observe(int type, switch (type) { case content::NOTIFICATION_USER_ACTION: - current_log_->RecordUserAction(*Details<const char*>(details).ptr()); + log_manager_.current_log()->RecordUserAction( + *Details<const char*>(details).ptr()); break; case chrome::NOTIFICATION_BROWSER_OPENED: @@ -596,7 +552,7 @@ void MetricsService::Observe(int type, break; case chrome::NOTIFICATION_OMNIBOX_OPENED_URL: { - MetricsLog* current_log = current_log_->AsMetricsLog(); + MetricsLog* current_log = log_manager_.current_log()->AsMetricsLog(); DCHECK(current_log); current_log->RecordOmniboxOpenedURL( *Details<AutocompleteLog>(details).ptr()); @@ -616,8 +572,9 @@ void MetricsService::Observe(int type, HandleIdleSinceLastTransmission(false); - if (current_log_) - DVLOG(1) << "METRICS: NUMBER OF EVENTS = " << current_log_->num_events(); + if (log_manager_.current_log()) + DVLOG(1) << "METRICS: NUMBER OF EVENTS = " + << log_manager_.current_log()->num_events(); } void MetricsService::HandleIdleSinceLastTransmission(bool in_idle) { @@ -830,10 +787,10 @@ void MetricsService::SaveLocalState() { // Recording control methods void MetricsService::StartRecording() { - if (current_log_) + if (log_manager_.current_log()) return; - current_log_ = new MetricsLog(client_id_, session_id_); + log_manager_.BeginLoggingWithLog(new MetricsLog(client_id_, session_id_)); if (state_ == INITIALIZED) { // We only need to schedule that run once. state_ = INIT_TASK_SCHEDULED; @@ -851,71 +808,54 @@ void MetricsService::StartRecording() { } void MetricsService::StopRecording() { - if (!current_log_) + if (!log_manager_.current_log()) return; // TODO(jar): Integrate bounds on log recording more consistently, so that we // can stop recording logs that are too big much sooner. - if (current_log_->num_events() >= kEventLimit) { + if (log_manager_.current_log()->num_events() > kEventLimit) { UMA_HISTOGRAM_COUNTS("UMA.Discarded Log Events", - current_log_->num_events()); - current_log_->CloseLog(); - delete current_log_; - current_log_ = NULL; + log_manager_.current_log()->num_events()); + log_manager_.DiscardCurrentLog(); StartRecording(); // Start trivial log to hold our histograms. } - current_log_->set_hardware_class(hardware_class_); // Adds to ongoing logs. + // Adds to ongoing logs. + log_manager_.current_log()->set_hardware_class(hardware_class_); // Put incremental data (histogram deltas, and realtime stats deltas) at the // end of all log transmissions (initial log handles this separately). // RecordIncrementalStabilityElements only exists on the derived // MetricsLog class. - MetricsLog* current_log = current_log_->AsMetricsLog(); + MetricsLog* current_log = log_manager_.current_log()->AsMetricsLog(); DCHECK(current_log); current_log->RecordIncrementalStabilityElements(); RecordCurrentHistograms(); - current_log_->CloseLog(); - pending_log_ = current_log_; - current_log_ = NULL; + log_manager_.StageCurrentLogForUpload(); } -void MetricsService::PushPendingLogsToUnsentLists() { +void MetricsService::PushPendingLogsToPersistentStorage() { if (state_ < INITIAL_LOG_READY) return; // We didn't and still don't have time to get plugin list etc. - if (pending_log()) { - PreparePendingLogText(); + if (log_manager_.has_staged_log()) { if (state_ == INITIAL_LOG_READY) { // We may race here, and send second copy of initial log later. - unsent_initial_logs_.push_back(compressed_log_); - state_ = SEND_OLD_INITIAL_LOGS; + log_manager_.StoreStagedLogAsUnsent(MetricsLogManager::INITIAL_LOG); + state_ = SENDING_OLD_LOGS; } else { // TODO(jar): Verify correctness in other states, including sending unsent // initial logs. - PushPendingLogTextToUnsentOngoingLogs(); + log_manager_.StoreStagedLogAsUnsent(MetricsLogManager::ONGOING_LOG); } - DiscardPendingLog(); } - DCHECK(!pending_log()); + DCHECK(!log_manager_.has_staged_log()); StopRecording(); - PreparePendingLogText(); - PushPendingLogTextToUnsentOngoingLogs(); - DiscardPendingLog(); + log_manager_.StoreStagedLogAsUnsent(MetricsLogManager::ONGOING_LOG); StoreUnsentLogs(); } -void MetricsService::PushPendingLogTextToUnsentOngoingLogs() { - if (compressed_log_.length() > - static_cast<size_t>(kUploadLogAvoidRetransmitSize)) { - UMA_HISTOGRAM_COUNTS("UMA.Large Accumulated Log Not Persisted", - static_cast<int>(compressed_log_.length())); - return; - } - unsent_ongoing_logs_.push_back(compressed_log_); -} - //------------------------------------------------------------------------------ // Transmission of logs methods @@ -998,20 +938,20 @@ void MetricsService::OnHistogramSynchronizationDone() { return; } - MakePendingLog(); + MakeStagedLog(); - // MakePendingLog should have put something in the pending log, if it didn't, - // we skip this upload and hope things work out next time. - if (!pending_log()) { + // MakeStagedLog should have prepared log text; if it didn't, skip this + // upload and hope things work out next time. + if (log_manager_.staged_log_text().empty()) { scheduler_->UploadCancelled(); return; } - PrepareFetchWithPendingLog(); + PrepareFetchWithStagedLog(); if (!current_fetch_.get()) { // Compression failed, and log discarded :-/. - DiscardPendingLog(); + log_manager_.DiscardStagedLog(); scheduler_->UploadCancelled(); // TODO(jar): If compression failed, we should have created a tiny log and // compressed that, so that we can signal that we're losing logs. @@ -1027,8 +967,8 @@ void MetricsService::OnHistogramSynchronizationDone() { } -void MetricsService::MakePendingLog() { - if (pending_log()) +void MetricsService::MakeStagedLog() { + if (log_manager_.has_staged_log()) return; switch (state_) { @@ -1043,23 +983,13 @@ void MetricsService::MakePendingLog() { // from us. PrepareInitialLog(); DCHECK(state_ == INIT_TASK_DONE); - RecallUnsentLogs(); + log_manager_.LoadPersistedUnsentLogs(); state_ = INITIAL_LOG_READY; break; - case SEND_OLD_INITIAL_LOGS: - if (!unsent_initial_logs_.empty()) { - compressed_log_ = unsent_initial_logs_.back(); - unsent_initial_logs_.pop_back(); - break; - } - state_ = SENDING_OLD_LOGS; - // Fall through. - case SENDING_OLD_LOGS: - if (!unsent_ongoing_logs_.empty()) { - compressed_log_ = unsent_ongoing_logs_.back(); - unsent_ongoing_logs_.pop_back(); + if (log_manager_.has_unsent_logs()) { + log_manager_.StageNextStoredLogForUpload(); break; } state_ = SENDING_CURRENT_LOGS; @@ -1075,7 +1005,7 @@ void MetricsService::MakePendingLog() { return; } - DCHECK(pending_log()); + DCHECK(log_manager_.has_staged_log()); } void MetricsService::PrepareInitialLog() { @@ -1085,187 +1015,35 @@ void MetricsService::PrepareInitialLog() { log->set_hardware_class(hardware_class_); // Adds to initial log. log->RecordEnvironment(plugins_, profile_dictionary_.get()); - // Histograms only get written to current_log_, so setup for the write. - MetricsLogBase* save_log = current_log_; - current_log_ = log; - RecordCurrentHistograms(); // Into current_log_... which is really log. - current_log_ = save_log; - - log->CloseLog(); - DCHECK(!pending_log()); - pending_log_ = log; -} - -// static -MetricsService::LogRecallStatus MetricsService::RecallUnsentLogsHelper( - const ListValue& list, - std::vector<std::string>* local_list) { - DCHECK(local_list->empty()); - if (list.GetSize() == 0) - return MakeRecallStatusHistogram(LIST_EMPTY); - if (list.GetSize() < 3) - return MakeRecallStatusHistogram(LIST_SIZE_TOO_SMALL); - - // The size is stored at the beginning of the list. - int size; - bool valid = (*list.begin())->GetAsInteger(&size); - if (!valid) - return MakeRecallStatusHistogram(LIST_SIZE_MISSING); - - // Account for checksum and size included in the list. - if (static_cast<unsigned int>(size) != - list.GetSize() - kChecksumEntryCount) - return MakeRecallStatusHistogram(LIST_SIZE_CORRUPTION); - - base::MD5Context ctx; - base::MD5Init(&ctx); - std::string encoded_log; - std::string decoded_log; - for (ListValue::const_iterator it = list.begin() + 1; - it != list.end() - 1; ++it) { // Last element is the checksum. - valid = (*it)->GetAsString(&encoded_log); - if (!valid) { - local_list->clear(); - return MakeRecallStatusHistogram(LOG_STRING_CORRUPTION); - } - - base::MD5Update(&ctx, encoded_log); - - if (!base::Base64Decode(encoded_log, &decoded_log)) { - local_list->clear(); - return MakeRecallStatusHistogram(DECODE_FAIL); - } - local_list->push_back(decoded_log); - } - - // Verify checksum. - base::MD5Digest digest; - base::MD5Final(&digest, &ctx); - std::string recovered_md5; - // We store the hash at the end of the list. - valid = (*(list.end() - 1))->GetAsString(&recovered_md5); - if (!valid) { - local_list->clear(); - return MakeRecallStatusHistogram(CHECKSUM_STRING_CORRUPTION); - } - if (recovered_md5 != base::MD5DigestToBase16(digest)) { - local_list->clear(); - return MakeRecallStatusHistogram(CHECKSUM_CORRUPTION); - } - return MakeRecallStatusHistogram(RECALL_SUCCESS); -} -void MetricsService::RecallUnsentLogs() { - PrefService* local_state = g_browser_process->local_state(); - DCHECK(local_state); - - const ListValue* unsent_initial_logs = local_state->GetList( - prefs::kMetricsInitialLogs); - RecallUnsentLogsHelper(*unsent_initial_logs, &unsent_initial_logs_); - - const ListValue* unsent_ongoing_logs = local_state->GetList( - prefs::kMetricsOngoingLogs); - RecallUnsentLogsHelper(*unsent_ongoing_logs, &unsent_ongoing_logs_); -} - -// static -void MetricsService::StoreUnsentLogsHelper( - const std::vector<std::string>& local_list, - const size_t kMaxLocalListSize, - ListValue* list) { - list->Clear(); - size_t start = 0; - if (local_list.size() > kMaxLocalListSize) - start = local_list.size() - kMaxLocalListSize; - DCHECK(start <= local_list.size()); - if (local_list.size() == start) - return; - - // Store size at the beginning of the list. - list->Append(Value::CreateIntegerValue(local_list.size() - start)); - - base::MD5Context ctx; - base::MD5Init(&ctx); - std::string encoded_log; - for (std::vector<std::string>::const_iterator it = local_list.begin() + start; - it != local_list.end(); ++it) { - // We encode the compressed log as Value::CreateStringValue() expects to - // take a valid UTF8 string. - if (!base::Base64Encode(*it, &encoded_log)) { - MakeStoreStatusHistogram(ENCODE_FAIL); - list->Clear(); - return; - } - base::MD5Update(&ctx, encoded_log); - list->Append(Value::CreateStringValue(encoded_log)); - } + // Histograms only get written to the current log, so make the new log current + // before writing them. + log_manager_.PauseCurrentLog(); + log_manager_.BeginLoggingWithLog(log); + RecordCurrentHistograms(); - // Append hash to the end of the list. - base::MD5Digest digest; - base::MD5Final(&digest, &ctx); - list->Append(Value::CreateStringValue(base::MD5DigestToBase16(digest))); - DCHECK(list->GetSize() >= 3); // Minimum of 3 elements (size, data, hash). - MakeStoreStatusHistogram(STORE_SUCCESS); + DCHECK(!log_manager_.has_staged_log()); + log_manager_.StageCurrentLogForUpload(); + log_manager_.ResumePausedLog(); } void MetricsService::StoreUnsentLogs() { if (state_ < INITIAL_LOG_READY) return; // We never Recalled the prior unsent logs. - PrefService* local_state = g_browser_process->local_state(); - DCHECK(local_state); - - { - ListPrefUpdate update(local_state, prefs::kMetricsInitialLogs); - ListValue* unsent_initial_logs = update.Get(); - StoreUnsentLogsHelper(unsent_initial_logs_, kMaxInitialLogsPersisted, - unsent_initial_logs); - } - - { - ListPrefUpdate update(local_state, prefs::kMetricsOngoingLogs); - ListValue* unsent_ongoing_logs = update.Get(); - StoreUnsentLogsHelper(unsent_ongoing_logs_, kMaxOngoingLogsPersisted, - unsent_ongoing_logs); - } -} - -void MetricsService::PreparePendingLogText() { - DCHECK(pending_log()); - if (!compressed_log_.empty()) - return; - int text_size = pending_log_->GetEncodedLogSize(); - - std::string pending_log_text; - // Leave room for the NULL terminator. - pending_log_->GetEncodedLog(WriteInto(&pending_log_text, text_size + 1), - text_size); - - if (Bzip2Compress(pending_log_text, &compressed_log_)) { - // Allow security conscious users to see all metrics logs that we send. - VLOG(1) << "COMPRESSED FOLLOWING METRICS LOG: " << pending_log_text; - } else { - LOG(DFATAL) << "Failed to compress log for transmission."; - // We can't discard the logs as other caller functions expect that - // |compressed_log_| not be empty. We can detect this failure at the server - // after we transmit. - compressed_log_ = "Unable to compress!"; - MakeStoreStatusHistogram(COMPRESS_FAIL); - return; - } + log_manager_.PersistUnsentLogs(); } -void MetricsService::PrepareFetchWithPendingLog() { - DCHECK(pending_log()); +void MetricsService::PrepareFetchWithStagedLog() { + DCHECK(!log_manager_.staged_log_text().empty()); DCHECK(!current_fetch_.get()); - PreparePendingLogText(); - DCHECK(!compressed_log_.empty()); current_fetch_.reset(new URLFetcher(GURL(WideToUTF16(server_url_)), URLFetcher::POST, this)); current_fetch_->set_request_context( g_browser_process->system_request_context()); - current_fetch_->set_upload_data(kMetricsType, compressed_log_); + current_fetch_->set_upload_data(kMetricsType, + log_manager_.staged_log_text()); } static const char* StatusToString(const net::URLRequestStatus& status) { @@ -1312,10 +1090,11 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source, bool discard_log = false; if (!upload_succeeded && - (compressed_log_.length() > + (log_manager_.staged_log_text().length() > static_cast<size_t>(kUploadLogAvoidRetransmitSize))) { - UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded", - static_cast<int>(compressed_log_.length())); + UMA_HISTOGRAM_COUNTS( + "UMA.Large Rejected Log was Discarded", + static_cast<int>(log_manager_.staged_log_text().length())); discard_log = true; } else if (response_code == 400) { // Bad syntax. Retransmission won't work. @@ -1331,10 +1110,9 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source, VLOG(1) << "METRICS RESPONSE DATA: " << data; switch (state_) { case INITIAL_LOG_READY: - state_ = SEND_OLD_INITIAL_LOGS; + state_ = SENDING_OLD_LOGS; break; - case SEND_OLD_INITIAL_LOGS: case SENDING_OLD_LOGS: // Store the updated list to disk now that the removed log is uploaded. StoreUnsentLogs(); @@ -1348,14 +1126,14 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source, break; } - DiscardPendingLog(); + log_manager_.DiscardStagedLog(); // Since we sent a log, make sure our in-memory state is recorded to disk. PrefService* local_state = g_browser_process->local_state(); DCHECK(local_state); if (local_state) local_state->ScheduleSavePersistentPrefs(); - if (unsent_logs()) + if (log_manager_.has_unsent_logs()) DCHECK(state_ < SENDING_CURRENT_LOGS); } @@ -1363,7 +1141,8 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source, // don't consider that a sign that the server is in trouble. bool server_is_healthy = upload_succeeded || response_code == 400; - scheduler_->UploadFinished(server_is_healthy, unsent_logs()); + scheduler_->UploadFinished(server_is_healthy, + log_manager_.has_unsent_logs()); // Collect network stats if UMA upload succeeded. if (server_is_healthy && io_thread_) @@ -1373,11 +1152,11 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source, void MetricsService::LogBadResponseCode() { VLOG(1) << "Verify your metrics logs are formatted correctly. Verify server " "is active at " << server_url_; - if (!pending_log()) { + if (!log_manager_.has_staged_log()) { VLOG(1) << "METRICS: Recorder shutdown during log transmission."; } else { VLOG(1) << "METRICS: transmission retry being scheduled for " - << compressed_log_; + << log_manager_.staged_log_text(); } } @@ -1417,7 +1196,7 @@ void MetricsService::LogWindowChange(int type, } // TODO(brettw) we should have some kind of ID for the parent. - current_log_->RecordWindowEvent(window_type, controller_id, 0); + log_manager_.current_log()->RecordWindowEvent(window_type, controller_id, 0); } void MetricsService::LogLoadComplete(int type, @@ -1433,11 +1212,11 @@ void MetricsService::LogLoadComplete(int type, const Details<LoadNotificationDetails> load_details(details); int controller_id = window_map_[details.map_key()]; - current_log_->RecordLoadEvent(controller_id, - load_details->url(), - load_details->origin(), - load_details->session_index(), - load_details->load_time()); + log_manager_.current_log()->RecordLoadEvent(controller_id, + load_details->url(), + load_details->origin(), + load_details->session_index(), + load_details->load_time()); } void MetricsService::IncrementPrefValue(const char* path) { diff --git a/chrome/browser/metrics/metrics_service.h b/chrome/browser/metrics/metrics_service.h index b3e38f2..dc781e4 100644 --- a/chrome/browser/metrics/metrics_service.h +++ b/chrome/browser/metrics/metrics_service.h @@ -37,7 +37,6 @@ class TemplateURLService; namespace base { class DictionaryValue; -class ListValue; class MessageLoopProxy; } @@ -54,31 +53,6 @@ class MetricsService : public NotificationObserver, public URLFetcher::Delegate, public MetricsServiceBase { public: - // Used to produce a historgram that keeps track of the status of recalling - // persisted per logs. - enum LogRecallStatus { - RECALL_SUCCESS, // We were able to correctly recall a persisted log. - LIST_EMPTY, // Attempting to recall from an empty list. - LIST_SIZE_MISSING, // Failed to recover list size using GetAsInteger(). - LIST_SIZE_TOO_SMALL, // Too few elements in the list (less than 3). - LIST_SIZE_CORRUPTION, // List size is not as expected. - LOG_STRING_CORRUPTION, // Failed to recover log string using GetAsString(). - CHECKSUM_CORRUPTION, // Failed to verify checksum. - CHECKSUM_STRING_CORRUPTION, // Failed to recover checksum string using - // GetAsString(). - DECODE_FAIL, // Failed to decode log. - END_RECALL_STATUS // Number of bins to use to create the histogram. - }; - - // TODO(ziadh): This is here temporarily for a side experiment. Remove later - // on. - enum LogStoreStatus { - STORE_SUCCESS, // Successfully presisted log. - ENCODE_FAIL, // Failed to encode log. - COMPRESS_FAIL, // Failed to compress log. - END_STORE_STATUS // Number of bins to use to create the histogram. - }; - MetricsService(); virtual ~MetricsService(); @@ -156,7 +130,6 @@ class MetricsService : public NotificationObserver, INIT_TASK_SCHEDULED, // Waiting for deferred init tasks to complete. INIT_TASK_DONE, // Waiting for timer to send initial log. INITIAL_LOG_READY, // Initial log generated, and waiting for reply. - SEND_OLD_INITIAL_LOGS, // Sending unsent logs from previous session. SENDING_OLD_LOGS, // Sending unsent logs from previous session. SENDING_CURRENT_LOGS, // Sending standard current logs as they acrue. }; @@ -221,17 +194,12 @@ class MetricsService : public NotificationObserver, void StartRecording(); // Called to stop recording user experience metrics. - // Adds any last information to current_log_ and then moves it to pending_log_ - // for upload. + // Adds any last information to current_log_ and then stages it for upload. void StopRecording(); - // Deletes pending_log_ and current_log_, and pushes their text into the - // appropriate unsent_log vectors. Called when Chrome shuts down. - void PushPendingLogsToUnsentLists(); - - // Save the pending_log_text_ persistently in a pref for transmission when we - // next run. Note that IF this text is "too large," we just dicard it. - void PushPendingLogTextToUnsentOngoingLogs(); + // Pushes the text of the current and staged logs into persistent storage. + // Called when Chrome shuts down. + void PushPendingLogsToPersistentStorage(); // Ensures that scheduler is running, assuming the current settings are such // that metrics should be reported. If not, this is a no-op. @@ -247,34 +215,17 @@ class MetricsService : public NotificationObserver, void OnHistogramSynchronizationDone(); // Takes whatever log should be uploaded next (according to the state_) - // and makes it the pending log. If pending_log_ is not NULL, - // MakePendingLog does nothing and returns. - void MakePendingLog(); - - // Check to see if there are any unsent logs from previous sessions. - bool unsent_logs() const { - return !unsent_initial_logs_.empty() || !unsent_ongoing_logs_.empty(); - } + // and makes it the staged log. If there is already a staged log, this is a + // no-op. + void MakeStagedLog(); + // Record stats, client ID, Session ID, etc. in a special "first" log. void PrepareInitialLog(); - // Pull copies of unsent logs from prefs into instance variables. - void RecallUnsentLogs(); - // Decode and verify written pref log data. - static MetricsService::LogRecallStatus RecallUnsentLogsHelper( - const base::ListValue& list, - std::vector<std::string>* local_list); - // Encode and write list size and checksum for perf log data. - static void StoreUnsentLogsHelper(const std::vector<std::string>& local_list, - const size_t kMaxLocalListSize, - base::ListValue* list); - // Convert |pending_log_| to XML in |compressed_log_|, and compress it for - // transmission. - void PreparePendingLogText(); - - // Convert pending_log_ to XML, compress it, and prepare to pass to server. - // Upon return, current_fetch_ should be reset with its upload data set to - // a compressed copy of the pending log. - void PrepareFetchWithPendingLog(); + + // Prepared the staged log to be passed to the server. Upon return, + // current_fetch_ should be reset with its upload data set to a compressed + // copy of the staged log. + void PrepareFetchWithStagedLog(); // Implementation of URLFetcher::Delegate. Called after transmission // completes (either successfully or with failure). @@ -403,16 +354,6 @@ class MetricsService : public NotificationObserver, // A number that identifies the how many times the app has been launched. int session_id_; - // When logs were not sent during a previous session they are queued to be - // sent instead of currently accumulating logs. We give preference to sending - // our inital log first, then unsent intial logs, then unsent ongoing logs. - // Unsent logs are gathered at shutdown, and save in a persistent pref, one - // log in each string in the following arrays. - // Note that the vector has the oldest logs listed first (early in the - // vector), and we'll discard old logs if we have gathered too many logs. - std::vector<std::string> unsent_initial_logs_; - std::vector<std::string> unsent_ongoing_logs_; - // Maps NavigationControllers (corresponding to tabs) or Browser // (corresponding to Windows) to a unique integer that we will use to identify // it. |next_window_id_| is used to track which IDs we have used so far. @@ -448,13 +389,6 @@ class MetricsService : public NotificationObserver, // exited-cleanly bit in the prefs. static ShutdownCleanliness clean_shutdown_status_; - FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, EmptyLogList); - FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, SingleElementLogList); - FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, OverLimitLogList); - FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, SmallRecoveredListSize); - FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, RemoveSizeFromLogList); - FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, CorruptSizeOfLogList); - FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, CorruptChecksumOfLogList); FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, ClientIdGeneratesAllZeroes); FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, ClientIdGeneratesCorrectly); FRIEND_TEST_ALL_PREFIXES(MetricsServiceTest, ClientIdCorrectlyFormatted); diff --git a/chrome/browser/metrics/metrics_service_unittest.cc b/chrome/browser/metrics/metrics_service_unittest.cc index 2ddb2f8..01263de 100644 --- a/chrome/browser/metrics/metrics_service_unittest.cc +++ b/chrome/browser/metrics/metrics_service_unittest.cc @@ -5,19 +5,14 @@ #include "chrome/browser/metrics/metrics_service.h" #include <string> -#include <vector> #include "base/base64.h" -#include "base/md5.h" -#include "base/values.h" #include "testing/gtest/include/gtest/gtest.h" class MetricsServiceTest : public ::testing::Test { }; -static const size_t kMaxLocalListSize = 3; - // Ensure the ClientId is formatted as expected. TEST(MetricsServiceTest, ClientIdCorrectlyFormatted) { std::string clientid = MetricsService::GenerateClientID(); @@ -33,171 +28,3 @@ TEST(MetricsServiceTest, ClientIdCorrectlyFormatted) { } } -// Store and retrieve empty list. -TEST(MetricsServiceTest, EmptyLogList) { - ListValue list; - std::vector<std::string> local_list; - - MetricsService::StoreUnsentLogsHelper(local_list, kMaxLocalListSize, &list); - EXPECT_EQ(0U, list.GetSize()); - - local_list.clear(); // RecallUnsentLogsHelper() expects empty |local_list|. - EXPECT_EQ(MetricsService::LIST_EMPTY, - MetricsService::RecallUnsentLogsHelper(list, &local_list)); - EXPECT_EQ(0U, local_list.size()); -} - -// Store and retrieve a single log value. -TEST(MetricsServiceTest, SingleElementLogList) { - ListValue list; - std::vector<std::string> local_list; - - local_list.push_back("Hello world!"); - EXPECT_EQ(1U, local_list.size()); - - MetricsService::StoreUnsentLogsHelper(local_list, kMaxLocalListSize, &list); - - // |list| will now contain the following: - // [1, Base64Encode("Hello world!"), MD5("Hello world!")]. - EXPECT_EQ(3U, list.GetSize()); - - // Examine each element. - ListValue::const_iterator it = list.begin(); - int size = 0; - (*it)->GetAsInteger(&size); - EXPECT_EQ(1, size); - - ++it; - std::string str; - (*it)->GetAsString(&str); // Base64 encoded "Hello world!" string. - std::string encoded; - base::Base64Encode("Hello world!", &encoded); - EXPECT_TRUE(encoded == str); - - ++it; - (*it)->GetAsString(&str); // MD5 for encoded "Hello world!" string. - EXPECT_TRUE(base::MD5String(encoded) == str); - - ++it; - EXPECT_TRUE(it == list.end()); // Reached end of list. - - local_list.clear(); - EXPECT_EQ(MetricsService::RECALL_SUCCESS, - MetricsService::RecallUnsentLogsHelper(list, &local_list)); - EXPECT_EQ(1U, local_list.size()); -} - -// Store elements greater than the limit. -TEST(MetricsServiceTest, OverLimitLogList) { - ListValue list; - std::vector<std::string> local_list; - - local_list.push_back("one"); - local_list.push_back("two"); - local_list.push_back("three"); - local_list.push_back("four"); - EXPECT_EQ(4U, local_list.size()); - - std::string expected_first; - base::Base64Encode(local_list[local_list.size() - kMaxLocalListSize], - &expected_first); - std::string expected_last; - base::Base64Encode(local_list[local_list.size() - 1], - &expected_last); - - MetricsService::StoreUnsentLogsHelper(local_list, kMaxLocalListSize, &list); - EXPECT_EQ(kMaxLocalListSize + 2, list.GetSize()); - - std::string actual_first; - EXPECT_TRUE((*(list.begin() + 1))->GetAsString(&actual_first)); - EXPECT_TRUE(expected_first == actual_first); - - std::string actual_last; - EXPECT_TRUE((*(list.end() - 2))->GetAsString(&actual_last)); - EXPECT_TRUE(expected_last == actual_last); - - local_list.clear(); - EXPECT_EQ(MetricsService::RECALL_SUCCESS, - MetricsService::RecallUnsentLogsHelper(list, &local_list)); - EXPECT_EQ(kMaxLocalListSize, local_list.size()); -} - -// Induce LIST_SIZE_TOO_SMALL corruption -TEST(MetricsServiceTest, SmallRecoveredListSize) { - ListValue list; - std::vector<std::string> local_list; - - local_list.push_back("Hello world!"); - EXPECT_EQ(1U, local_list.size()); - MetricsService::StoreUnsentLogsHelper(local_list, kMaxLocalListSize, &list); - EXPECT_EQ(3U, list.GetSize()); - - // Remove last element. - list.Remove(list.GetSize() - 1, NULL); - EXPECT_EQ(2U, list.GetSize()); - - local_list.clear(); - EXPECT_EQ(MetricsService::LIST_SIZE_TOO_SMALL, - MetricsService::RecallUnsentLogsHelper(list, &local_list)); -} - -// Remove size from the stored list. -TEST(MetricsServiceTest, RemoveSizeFromLogList) { - ListValue list; - std::vector<std::string> local_list; - - local_list.push_back("one"); - local_list.push_back("two"); - EXPECT_EQ(2U, local_list.size()); - MetricsService::StoreUnsentLogsHelper(local_list, kMaxLocalListSize, &list); - EXPECT_EQ(4U, list.GetSize()); - - list.Remove(0, NULL); // Delete size (1st element). - EXPECT_EQ(3U, list.GetSize()); - - local_list.clear(); - EXPECT_EQ(MetricsService::LIST_SIZE_MISSING, - MetricsService::RecallUnsentLogsHelper(list, &local_list)); -} - -// Corrupt size of stored list. -TEST(MetricsServiceTest, CorruptSizeOfLogList) { - ListValue list; - std::vector<std::string> local_list; - - local_list.push_back("Hello world!"); - EXPECT_EQ(1U, local_list.size()); - MetricsService::StoreUnsentLogsHelper(local_list, kMaxLocalListSize, &list); - EXPECT_EQ(3U, list.GetSize()); - - // Change list size from 1 to 2. - EXPECT_TRUE(list.Set(0, Value::CreateIntegerValue(2))); - EXPECT_EQ(3U, list.GetSize()); - - local_list.clear(); - EXPECT_EQ(MetricsService::LIST_SIZE_CORRUPTION, - MetricsService::RecallUnsentLogsHelper(list, &local_list)); -} - -// Corrupt checksum of stored list. -TEST(MetricsServiceTest, CorruptChecksumOfLogList) { - ListValue list; - std::vector<std::string> local_list; - - local_list.clear(); - local_list.push_back("Hello world!"); - EXPECT_EQ(1U, local_list.size()); - MetricsService::StoreUnsentLogsHelper(local_list, kMaxLocalListSize, &list); - EXPECT_EQ(3U, list.GetSize()); - - // Fetch checksum (last element) and change it. - std::string checksum; - EXPECT_TRUE((*(list.end() - 1))->GetAsString(&checksum)); - checksum[0] = (checksum[0] == 'a') ? 'b' : 'a'; - EXPECT_TRUE(list.Set(2, Value::CreateStringValue(checksum))); - EXPECT_EQ(3U, list.GetSize()); - - local_list.clear(); - EXPECT_EQ(MetricsService::CHECKSUM_CORRUPTION, - MetricsService::RecallUnsentLogsHelper(list, &local_list)); -} diff --git a/chrome/chrome_browser.gypi b/chrome/chrome_browser.gypi index 4b58b51..cc3b1a3 100644 --- a/chrome/chrome_browser.gypi +++ b/chrome/chrome_browser.gypi @@ -1493,6 +1493,8 @@ 'browser/metrics/metric_event_duration_details.h', 'browser/metrics/metrics_log.cc', 'browser/metrics/metrics_log.h', + 'browser/metrics/metrics_log_serializer.cc', + 'browser/metrics/metrics_log_serializer.h', 'browser/metrics/metrics_reporting_scheduler.cc', 'browser/metrics/metrics_reporting_scheduler.h', 'browser/metrics/metrics_response.cc', diff --git a/chrome/chrome_common.gypi b/chrome/chrome_common.gypi index d3d8496..0f15ea6 100644 --- a/chrome/chrome_common.gypi +++ b/chrome/chrome_common.gypi @@ -172,6 +172,8 @@ 'common/mac/objc_zombie.mm', 'common/metrics_helpers.cc', 'common/metrics_helpers.h', + 'common/metrics_log_manager.cc', + 'common/metrics_log_manager.h', 'common/multi_process_lock.h', 'common/multi_process_lock_linux.cc', 'common/multi_process_lock_mac.cc', diff --git a/chrome/chrome_tests.gypi b/chrome/chrome_tests.gypi index b89b478..4b859e1 100644 --- a/chrome/chrome_tests.gypi +++ b/chrome/chrome_tests.gypi @@ -1323,6 +1323,7 @@ 'browser/media/media_internals_unittest.cc', 'browser/metrics/display_utils_unittest.cc', 'browser/metrics/metrics_log_unittest.cc', + 'browser/metrics/metrics_log_serializer_unittest.cc', 'browser/metrics/metrics_response_unittest.cc', 'browser/metrics/metrics_service_unittest.cc', 'browser/metrics/thread_watcher_unittest.cc', @@ -1791,6 +1792,7 @@ 'common/json_schema_validator_unittest_base.cc', 'common/json_schema_validator_unittest_base.h', 'common/json_value_serializer_unittest.cc', + 'common/metrics_log_manager_unittest.cc', 'common/multi_process_lock_unittest.cc', 'common/mac/objc_method_swizzle_unittest.mm', 'common/mac/objc_zombie_unittest.mm', diff --git a/chrome/common/metrics_helpers.cc b/chrome/common/metrics_helpers.cc index 028d0b3..e5e32cd 100644 --- a/chrome/common/metrics_helpers.cc +++ b/chrome/common/metrics_helpers.cc @@ -4,12 +4,6 @@ #include "chrome/common/metrics_helpers.h" -#if defined(USE_SYSTEM_LIBBZ2) -#include <bzlib.h> -#else -#include "third_party/bzip2/bzlib.h" -#endif - #include "base/base64.h" #include "base/basictypes.h" #include "base/file_util.h" @@ -21,6 +15,7 @@ #include "base/time.h" #include "base/utf_string_conversions.h" #include "chrome/common/logging_chrome.h" +#include "chrome/common/metrics_log_manager.h" #include "googleurl/src/gurl.h" #include "libxml/xmlwriter.h" @@ -416,79 +411,21 @@ void MetricsLogBase::RecordHistogramDelta( // MetricsServiceBase -MetricsServiceBase::MetricsServiceBase() - : pending_log_(NULL), - compressed_log_(), - current_log_(NULL) { +MetricsServiceBase::MetricsServiceBase() { } MetricsServiceBase::~MetricsServiceBase() { - if (pending_log_) { - delete pending_log_; - pending_log_ = NULL; - } - if (current_log_) { - delete current_log_; - current_log_ = NULL; - } -} - -// This implementation is based on the Firefox MetricsService implementation. -bool MetricsServiceBase::Bzip2Compress(const std::string& input, - std::string* output) { - bz_stream stream = {0}; - // As long as our input is smaller than the bzip2 block size, we should get - // the best compression. For example, if your input was 250k, using a block - // size of 300k or 500k should result in the same compression ratio. Since - // our data should be under 100k, using the minimum block size of 100k should - // allocate less temporary memory, but result in the same compression ratio. - int result = BZ2_bzCompressInit(&stream, - 1, // 100k (min) block size - 0, // quiet - 0); // default "work factor" - if (result != BZ_OK) { // out of memory? - return false; - } - - output->clear(); - - stream.next_in = const_cast<char*>(input.data()); - stream.avail_in = static_cast<int>(input.size()); - // NOTE: we don't need a BZ_RUN phase since our input buffer contains - // the entire input - do { - output->resize(output->size() + 1024); - stream.next_out = &((*output)[stream.total_out_lo32]); - stream.avail_out = static_cast<int>(output->size()) - stream.total_out_lo32; - result = BZ2_bzCompress(&stream, BZ_FINISH); - } while (result == BZ_FINISH_OK); - if (result != BZ_STREAM_END) // unknown failure? - return false; - result = BZ2_bzCompressEnd(&stream); - DCHECK(result == BZ_OK); - - output->resize(stream.total_out_lo32); - - return true; -} - -void MetricsServiceBase::DiscardPendingLog() { - if (pending_log_) { // Shutdown might have deleted it! - delete pending_log_; - pending_log_ = NULL; - } - compressed_log_.clear(); } void MetricsServiceBase::RecordCurrentHistograms() { - DCHECK(current_log_); + DCHECK(log_manager_.current_log()); TransmitAllHistograms(base::Histogram::kNoFlags, true); } void MetricsServiceBase::TransmitHistogramDelta( const base::Histogram& histogram, const base::Histogram::SampleSet& snapshot) { - current_log_->RecordHistogramDelta(histogram, snapshot); + log_manager_.current_log()->RecordHistogramDelta(histogram, snapshot); } void MetricsServiceBase::InconsistencyDetected(int problem) { diff --git a/chrome/common/metrics_helpers.h b/chrome/common/metrics_helpers.h index 68777dc..373d551 100644 --- a/chrome/common/metrics_helpers.h +++ b/chrome/common/metrics_helpers.h @@ -16,6 +16,7 @@ #include "base/memory/scoped_ptr.h" #include "base/metrics/histogram.h" #include "base/time.h" +#include "chrome/common/metrics_log_manager.h" #include "content/common/page_transition_types.h" class GURL; @@ -232,33 +233,12 @@ class MetricsServiceBase : public HistogramSender { MetricsServiceBase(); virtual ~MetricsServiceBase(); - // Check to see if there is a log that needs to be, or is being, transmitted. - bool pending_log() const { - return pending_log_ || !compressed_log_.empty(); - } - - // Compress the report log in |input| using bzip2, store the result in - // |output|. - bool Bzip2Compress(const std::string& input, std::string* output); - - // Discard |pending_log_|, and clear |compressed_log_|. Called after - // processing of this log is complete. - void DiscardPendingLog(); - // Record complete list of histograms into the current log. // Called when we close a log. void RecordCurrentHistograms(); - // A log that we are currently transmiting, or about to try to transmit. - MetricsLogBase* pending_log_; - - // An alternate form of |pending_log_|. We persistently save this version - // into prefs if we can't transmit it. As a result, sometimes all we have is - // the compressed text version. - std::string compressed_log_; - - // The log that we are still appending to. - MetricsLogBase* current_log_; + // Manager for the various in-flight logs. + MetricsLogManager log_manager_; private: // HistogramSender interface (override) methods. diff --git a/chrome/common/metrics_log_manager.cc b/chrome/common/metrics_log_manager.cc new file mode 100644 index 0000000..572e62a --- /dev/null +++ b/chrome/common/metrics_log_manager.cc @@ -0,0 +1,162 @@ +// Copyright (c) 2011 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/common/metrics_log_manager.h" + +#if defined(USE_SYSTEM_LIBBZ2) +#include <bzlib.h> +#else +#include "third_party/bzip2/bzlib.h" +#endif + +#include "base/metrics/histogram.h" +#include "base/string_util.h" +#include "chrome/common/metrics_helpers.h" + +MetricsLogManager::MetricsLogManager() : max_ongoing_log_store_size_(0) {} + +MetricsLogManager::~MetricsLogManager() {} + +void MetricsLogManager::BeginLoggingWithLog(MetricsLogBase* log) { + DCHECK(!current_log_.get()); + current_log_.reset(log); +} + +void MetricsLogManager::StageCurrentLogForUpload() { + DCHECK(current_log_.get()); + current_log_->CloseLog(); + staged_log_.reset(current_log_.release()); + CompressStagedLog(); +} + +bool MetricsLogManager::has_staged_log() const { + return staged_log_.get() || !compressed_staged_log_text_.empty(); +} + +void MetricsLogManager::DiscardStagedLog() { + staged_log_.reset(); + compressed_staged_log_text_.clear(); +} + +void MetricsLogManager::DiscardCurrentLog() { + current_log_->CloseLog(); + current_log_.reset(); +} + +void MetricsLogManager::PauseCurrentLog() { + DCHECK(!paused_log_.get()); + paused_log_.reset(current_log_.release()); +} + +void MetricsLogManager::ResumePausedLog() { + DCHECK(!current_log_.get()); + current_log_.reset(paused_log_.release()); +} + +void MetricsLogManager::StoreStagedLogAsUnsent(LogType log_type) { + DCHECK(staged_log_.get()); + // If compressing the log failed, there's nothing to store. + if (compressed_staged_log_text_.empty()) + return; + + if (log_type == INITIAL_LOG) { + unsent_initial_logs_.push_back(compressed_staged_log_text_); + } else { + // If it's too large, just note that and discard it. + if (max_ongoing_log_store_size_ && + compressed_staged_log_text_.length() > max_ongoing_log_store_size_) { + UMA_HISTOGRAM_COUNTS( + "UMA.Large Accumulated Log Not Persisted", + static_cast<int>(compressed_staged_log_text_.length())); + } else { + unsent_ongoing_logs_.push_back(compressed_staged_log_text_); + } + } + DiscardStagedLog(); +} + +void MetricsLogManager::StageNextStoredLogForUpload() { + // Prioritize initial logs for uploading. + std::vector<std::string>* source_list = unsent_initial_logs_.empty() ? + &unsent_ongoing_logs_ : &unsent_initial_logs_; + DCHECK(!source_list->empty()); + DCHECK(compressed_staged_log_text_.empty()); + compressed_staged_log_text_ = source_list->back(); + source_list->pop_back(); +} + +void MetricsLogManager::PersistUnsentLogs() { + DCHECK(log_serializer_.get()); + if (!log_serializer_.get()) + return; + log_serializer_->SerializeLogs(unsent_initial_logs_, INITIAL_LOG); + log_serializer_->SerializeLogs(unsent_ongoing_logs_, ONGOING_LOG); +} + +void MetricsLogManager::LoadPersistedUnsentLogs() { + DCHECK(log_serializer_.get()); + if (!log_serializer_.get()) + return; + log_serializer_->DeserializeLogs(INITIAL_LOG, &unsent_initial_logs_); + log_serializer_->DeserializeLogs(ONGOING_LOG, &unsent_ongoing_logs_); +} + +void MetricsLogManager::CompressStagedLog() { + int text_size = staged_log_->GetEncodedLogSize(); + std::string staged_log_text; + // Leave room for the NULL terminator. + staged_log_->GetEncodedLog(WriteInto(&staged_log_text, text_size + 1), + text_size); + + bool success = Bzip2Compress(staged_log_text, &compressed_staged_log_text_); + if (success) { + // Allow security-conscious users to see all metrics logs that we send. + VLOG(1) << "METRICS LOG: " << staged_log_text; + } else { + LOG(DFATAL) << "Failed to compress log for transmission."; + } +} + +// static +// This implementation is based on the Firefox MetricsService implementation. +bool MetricsLogManager::Bzip2Compress(const std::string& input, + std::string* output) { + bz_stream stream = {0}; + // As long as our input is smaller than the bzip2 block size, we should get + // the best compression. For example, if your input was 250k, using a block + // size of 300k or 500k should result in the same compression ratio. Since + // our data should be under 100k, using the minimum block size of 100k should + // allocate less temporary memory, but result in the same compression ratio. + int result = BZ2_bzCompressInit(&stream, + 1, // 100k (min) block size + 0, // quiet + 0); // default "work factor" + if (result != BZ_OK) { // out of memory? + return false; + } + + output->clear(); + + stream.next_in = const_cast<char*>(input.data()); + stream.avail_in = static_cast<int>(input.size()); + // NOTE: we don't need a BZ_RUN phase since our input buffer contains + // the entire input + do { + output->resize(output->size() + 1024); + stream.next_out = &((*output)[stream.total_out_lo32]); + stream.avail_out = static_cast<int>(output->size()) - stream.total_out_lo32; + result = BZ2_bzCompress(&stream, BZ_FINISH); + } while (result == BZ_FINISH_OK); + if (result != BZ_STREAM_END) { // unknown failure? + output->clear(); + // TODO(jar): See if it would be better to do a CHECK() here. + return false; + } + result = BZ2_bzCompressEnd(&stream); + DCHECK(result == BZ_OK); + + output->resize(stream.total_out_lo32); + + return true; +} diff --git a/chrome/common/metrics_log_manager.h b/chrome/common/metrics_log_manager.h new file mode 100644 index 0000000..c843d6e --- /dev/null +++ b/chrome/common/metrics_log_manager.h @@ -0,0 +1,154 @@ +// Copyright (c) 2011 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. + +#ifndef CHROME_COMMON_METRICS_LOG_MANAGER_H_ +#define CHROME_COMMON_METRICS_LOG_MANAGER_H_ +#pragma once + +#include "base/basictypes.h" +#include "base/memory/scoped_ptr.h" + +#include <string> +#include <vector> + +class MetricsLogBase; + +// Manages all the log objects used by a MetricsService implementation. Keeps +// track of both an in progress log and a log that is staged for uploading as +// text, as well as saving logs to, and loading logs from, persistent storage. +class MetricsLogManager { + public: + MetricsLogManager(); + ~MetricsLogManager(); + + // Takes ownership of |log|, and makes it the current_log. + // This should only be called if there is not a current log. + void BeginLoggingWithLog(MetricsLogBase* log); + + // Returns the in-progress log. + MetricsLogBase* current_log() { return current_log_.get(); } + + // Closes |current_log| and stages it for upload, leaving |current_log| NULL. + void StageCurrentLogForUpload(); + + // Returns true if there is a log that needs to be, or is being, uploaded. + // Note that this returns true even if compressing the log text failed. + bool has_staged_log() const; + + // The compressed text of the staged log. Empty if there is no staged log, + // or if compression of the staged log failed. + const std::string& staged_log_text() { return compressed_staged_log_text_; } + + // Discards the staged log. + void DiscardStagedLog(); + + // Closes and discards |current_log|. + void DiscardCurrentLog(); + + // Sets current_log to NULL, but saves the current log for future use with + // ResumePausedLog(). Only one log may be paused at a time. + // TODO(stuartmorgan): Pause/resume support is really a workaround for a + // design issue in initial log writing; that should be fixed, and pause/resume + // removed. + void PauseCurrentLog(); + + // Restores the previously paused log (if any) to current_log. + // This should only be called if there is not a current log. + void ResumePausedLog(); + + // Returns true if there are any logs left over from previous sessions that + // need to be uploaded. + bool has_unsent_logs() const { + return !unsent_initial_logs_.empty() || !unsent_ongoing_logs_.empty(); + } + + enum LogType { + INITIAL_LOG, // The first log of a session. + ONGOING_LOG, // Subsequent logs in a session. + }; + + // Saves the staged log as the given type (or discards it in accordance with + // set_max_ongoing_log_store_size), then clears the staged log. + // This can only be called after StageCurrentLogForUpload. + void StoreStagedLogAsUnsent(LogType log_type); + + // Populates staged_log_text with the next stored log to send. + void StageNextStoredLogForUpload(); + + // Sets the threshold for how large an onging log can be and still be stored. + // Ongoing logs larger than this will be discarded. 0 is interpreted as no + // limit. + void set_max_ongoing_log_store_size(size_t max_size) { + max_ongoing_log_store_size_ = max_size; + } + + // Interface for a utility class to serialize and deserialize logs for + // persistent storage. + class LogSerializer { + public: + virtual ~LogSerializer() {} + + // Serializes |logs| to persistent storage, replacing any previously + // serialized logs of the same type. + virtual void SerializeLogs(const std::vector<std::string>& logs, + LogType log_type) = 0; + + // Populates |logs| with logs of type |log_type| deserialized from + // persistent storage. + virtual void DeserializeLogs(LogType log_type, + std::vector<std::string>* logs) = 0; + }; + + // Sets the serializer to use for persisting and loading logs; takes ownership + // of |serializer|. + void set_log_serializer(LogSerializer* serializer) { + log_serializer_.reset(serializer); + } + + // Saves any unsent logs to persistent storage using the current log + // serializer. Can only be called after set_log_serializer. + void PersistUnsentLogs(); + + // Loads any unsent logs from persistent storage using the current log + // serializer. Can only be called after set_log_serializer. + void LoadPersistedUnsentLogs(); + + private: + // Compresses staged_log_ and stores the result in + // compressed_staged_log_text_. + void CompressStagedLog(); + + // Compresses the text in |input| using bzip2, store the result in |output|. + static bool Bzip2Compress(const std::string& input, std::string* output); + + // The log that we are still appending to. + scoped_ptr<MetricsLogBase> current_log_; + + // A paused, previously-current log. + scoped_ptr<MetricsLogBase> paused_log_; + + // The log that we are currently transmiting, or about to try to transmit. + // Note that when using StageNextStoredLogForUpload, this can be NULL while + // compressed_staged_log_text_ is non-NULL. + scoped_ptr<MetricsLogBase> staged_log_; + + // Helper class to handle serialization/deserialization of logs for persistent + // storage. May be NULL. + scoped_ptr<LogSerializer> log_serializer_; + + // The compressed text of the staged log, ready for upload to the server. + std::string compressed_staged_log_text_; + + // Logs from a previous session that have not yet been sent. + // Note that the vector has the oldest logs listed first (early in the + // vector), and we'll discard old logs if we have gathered too many logs. + std::vector<std::string> unsent_initial_logs_; + std::vector<std::string> unsent_ongoing_logs_; + + size_t max_ongoing_log_store_size_; + + DISALLOW_COPY_AND_ASSIGN(MetricsLogManager); +}; + +#endif // CHROME_COMMON_METRICS_LOG_MANAGER_H_ diff --git a/chrome/common/metrics_log_manager_unittest.cc b/chrome/common/metrics_log_manager_unittest.cc new file mode 100644 index 0000000..a7c894e --- /dev/null +++ b/chrome/common/metrics_log_manager_unittest.cc @@ -0,0 +1,211 @@ +// Copyright (c) 2011 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/common/metrics_helpers.h" +#include "chrome/common/metrics_log_manager.h" +#include "testing/gtest/include/gtest/gtest.h" + +#include <string> +#include <vector> + +namespace { +class MetricsLogManagerTest : public testing::Test { +}; + +// Dummy serializer that just stores logs in memory. +class DummyLogSerializer : public MetricsLogManager::LogSerializer { + public: + virtual void SerializeLogs(const std::vector<std::string>& logs, + MetricsLogManager::LogType log_type) { + persisted_logs_[log_type] = logs; + } + + virtual void DeserializeLogs(MetricsLogManager::LogType log_type, + std::vector<std::string>* logs) { + ASSERT_NE(static_cast<void*>(NULL), logs); + *logs = persisted_logs_[log_type]; + } + + // Returns the number of logs of the given type. + size_t TypeCount(MetricsLogManager::LogType log_type) { + return persisted_logs_[log_type].size(); + } + + // In-memory "persitent storage". + std::vector<std::string> persisted_logs_[2]; +}; +}; // namespace + +TEST(MetricsLogManagerTest, StandardFlow) { + MetricsLogManager log_manager; + + // Make sure a new manager has a clean slate. + EXPECT_EQ(NULL, log_manager.current_log()); + EXPECT_FALSE(log_manager.has_staged_log()); + EXPECT_FALSE(log_manager.has_unsent_logs()); + + // Check that the normal flow works. + MetricsLogBase* initial_log = new MetricsLogBase("id", 0, "version"); + log_manager.BeginLoggingWithLog(initial_log); + EXPECT_EQ(initial_log, log_manager.current_log()); + EXPECT_FALSE(log_manager.has_staged_log()); + + log_manager.StageCurrentLogForUpload(); + EXPECT_EQ(NULL, log_manager.current_log()); + EXPECT_TRUE(log_manager.has_staged_log()); + EXPECT_FALSE(log_manager.staged_log_text().empty()); + + MetricsLogBase* second_log = new MetricsLogBase("id", 0, "version"); + log_manager.BeginLoggingWithLog(second_log); + EXPECT_EQ(second_log, log_manager.current_log()); + EXPECT_TRUE(log_manager.has_staged_log()); + + log_manager.DiscardStagedLog(); + EXPECT_EQ(second_log, log_manager.current_log()); + EXPECT_FALSE(log_manager.has_staged_log()); + EXPECT_TRUE(log_manager.staged_log_text().empty()); + + EXPECT_FALSE(log_manager.has_unsent_logs()); +} + +TEST(MetricsLogManagerTest, AbandonedLog) { + MetricsLogManager log_manager; + + MetricsLogBase* dummy_log = new MetricsLogBase("id", 0, "version"); + log_manager.BeginLoggingWithLog(dummy_log); + EXPECT_EQ(dummy_log, log_manager.current_log()); + + log_manager.DiscardCurrentLog(); + EXPECT_EQ(NULL, log_manager.current_log()); + EXPECT_FALSE(log_manager.has_staged_log()); +} + +TEST(MetricsLogManagerTest, InterjectedLog) { + MetricsLogManager log_manager; + + MetricsLogBase* ongoing_log = new MetricsLogBase("id", 0, "version"); + MetricsLogBase* temp_log = new MetricsLogBase("id", 0, "version"); + + log_manager.BeginLoggingWithLog(ongoing_log); + EXPECT_EQ(ongoing_log, log_manager.current_log()); + + log_manager.PauseCurrentLog(); + EXPECT_EQ(NULL, log_manager.current_log()); + + log_manager.BeginLoggingWithLog(temp_log); + EXPECT_EQ(temp_log, log_manager.current_log()); + log_manager.StageCurrentLogForUpload(); + EXPECT_TRUE(log_manager.has_staged_log()); + log_manager.DiscardStagedLog(); + EXPECT_EQ(NULL, log_manager.current_log()); + EXPECT_FALSE(log_manager.has_staged_log()); + + log_manager.ResumePausedLog(); + EXPECT_EQ(ongoing_log, log_manager.current_log()); + EXPECT_FALSE(log_manager.has_staged_log()); + + EXPECT_FALSE(log_manager.has_unsent_logs()); +} + +TEST(MetricsLogManagerTest, StoreAndLoad) { + std::vector<std::string> initial_logs; + std::vector<std::string> ongoing_logs; + + // Set up some in-progress logging in a scoped log manager simulating the + // leadup to quitting, then persist as would be done on quit. + { + MetricsLogManager log_manager; + DummyLogSerializer* serializer = new DummyLogSerializer; + log_manager.set_log_serializer(serializer); + // Simulate a log having already been unsent from a previous session. + serializer->persisted_logs_[MetricsLogManager::ONGOING_LOG].push_back("a"); + EXPECT_FALSE(log_manager.has_unsent_logs()); + log_manager.LoadPersistedUnsentLogs(); + EXPECT_TRUE(log_manager.has_unsent_logs()); + + MetricsLogBase* log1 = new MetricsLogBase("id", 0, "version"); + MetricsLogBase* log2 = new MetricsLogBase("id", 0, "version"); + log_manager.BeginLoggingWithLog(log1); + log_manager.StageCurrentLogForUpload(); + log_manager.BeginLoggingWithLog(log2); + log_manager.StoreStagedLogAsUnsent(MetricsLogManager::INITIAL_LOG); + log_manager.StageCurrentLogForUpload(); + log_manager.StoreStagedLogAsUnsent(MetricsLogManager::ONGOING_LOG); + + // Nothing should be written out until PersistUnsentLogs is called. + EXPECT_EQ(0U, serializer->TypeCount(MetricsLogManager::INITIAL_LOG)); + EXPECT_EQ(1U, serializer->TypeCount(MetricsLogManager::ONGOING_LOG)); + log_manager.PersistUnsentLogs(); + EXPECT_EQ(1U, serializer->TypeCount(MetricsLogManager::INITIAL_LOG)); + EXPECT_EQ(2U, serializer->TypeCount(MetricsLogManager::ONGOING_LOG)); + + // Save the logs to transfer over to a new serializer (since log_manager + // owns |serializer|, so it's about to go away. + initial_logs = serializer->persisted_logs_[MetricsLogManager::INITIAL_LOG]; + ongoing_logs = serializer->persisted_logs_[MetricsLogManager::ONGOING_LOG]; + } + + // Now simulate the relaunch, ensure that the log manager restores + // everything correctly, and verify that once the are handled they are not + // re-persisted. + { + MetricsLogManager log_manager; + + DummyLogSerializer* serializer = new DummyLogSerializer; + serializer->persisted_logs_[MetricsLogManager::INITIAL_LOG] = initial_logs; + serializer->persisted_logs_[MetricsLogManager::ONGOING_LOG] = ongoing_logs; + + log_manager.set_log_serializer(serializer); + log_manager.LoadPersistedUnsentLogs(); + EXPECT_TRUE(log_manager.has_unsent_logs()); + + log_manager.StageNextStoredLogForUpload(); + log_manager.DiscardStagedLog(); + // The initial log should be sent first; update the persisted storage to + // verify. + log_manager.PersistUnsentLogs(); + EXPECT_EQ(0U, serializer->TypeCount(MetricsLogManager::INITIAL_LOG)); + EXPECT_EQ(2U, serializer->TypeCount(MetricsLogManager::ONGOING_LOG)); + + // Handle the first ongoing log. + log_manager.StageNextStoredLogForUpload(); + log_manager.DiscardStagedLog(); + EXPECT_TRUE(log_manager.has_unsent_logs()); + + // Handle the last log. + log_manager.StageNextStoredLogForUpload(); + log_manager.DiscardStagedLog(); + EXPECT_FALSE(log_manager.has_unsent_logs()); + + // Nothing should have changed "on disk" since PersistUnsentLogs hasn't been + // called again. + EXPECT_EQ(2U, serializer->TypeCount(MetricsLogManager::ONGOING_LOG)); + // Persist, and make sure nothing is left. + log_manager.PersistUnsentLogs(); + EXPECT_EQ(0U, serializer->TypeCount(MetricsLogManager::INITIAL_LOG)); + EXPECT_EQ(0U, serializer->TypeCount(MetricsLogManager::ONGOING_LOG)); + } +} + +TEST(MetricsLogManagerTest, LargeLogDiscarding) { + MetricsLogManager log_manager; + DummyLogSerializer* serializer = new DummyLogSerializer; + log_manager.set_log_serializer(serializer); + // Set the size threshold very low, to verify that it's honored. + log_manager.set_max_ongoing_log_store_size(1); + + MetricsLogBase* log1 = new MetricsLogBase("id", 0, "version"); + MetricsLogBase* log2 = new MetricsLogBase("id", 0, "version"); + log_manager.BeginLoggingWithLog(log1); + log_manager.StageCurrentLogForUpload(); + log_manager.BeginLoggingWithLog(log2); + log_manager.StoreStagedLogAsUnsent(MetricsLogManager::INITIAL_LOG); + log_manager.StageCurrentLogForUpload(); + log_manager.StoreStagedLogAsUnsent(MetricsLogManager::ONGOING_LOG); + + // Only the ongoing log should be written out, due to the threshold. + log_manager.PersistUnsentLogs(); + EXPECT_EQ(1U, serializer->TypeCount(MetricsLogManager::INITIAL_LOG)); + EXPECT_EQ(0U, serializer->TypeCount(MetricsLogManager::ONGOING_LOG)); +} diff --git a/chrome_frame/metrics_service.cc b/chrome_frame/metrics_service.cc index ee7d393..9af220b 100644 --- a/chrome_frame/metrics_service.cc +++ b/chrome_frame/metrics_service.cc @@ -57,6 +57,7 @@ #include "base/utf_string_conversions.h" #include "base/win/scoped_comptr.h" #include "chrome/common/chrome_version_info.h" +#include "chrome/common/metrics_log_manager.h" #include "chrome/installer/util/browser_distribution.h" #include "chrome/installer/util/google_update_settings.h" #include "chrome_frame/bind_status_callback_impl.h" @@ -250,14 +251,6 @@ MetricsService::MetricsService() MetricsService::~MetricsService() { SetRecording(false); - if (pending_log_) { - delete pending_log_; - pending_log_ = NULL; - } - if (current_log_) { - delete current_log_; - current_log_ = NULL; - } } void MetricsService::InitializeMetricsState() { @@ -369,36 +362,36 @@ void MetricsService::SetReporting(bool enable) { void MetricsService::StartRecording() { DCHECK_EQ(thread_, base::PlatformThread::CurrentId()); - if (current_log_) + if (log_manager_.current_log()) return; - current_log_ = new MetricsLogBase(client_id_, session_id_, - GetVersionString()); + log_manager_.BeginLoggingWithLog(new MetricsLogBase(client_id_, session_id_, + GetVersionString())); if (state_ == INITIALIZED) state_ = ACTIVE; } void MetricsService::StopRecording(bool save_log) { DCHECK_EQ(thread_, base::PlatformThread::CurrentId()); - if (!current_log_) + if (!log_manager_.current_log()) return; // Put incremental histogram deltas at the end of all log transmissions. - // Don't bother if we're going to discard current_log_. + // Don't bother if we're going to discard current_log. if (save_log) { CrashMetricsReporter::GetInstance()->RecordCrashMetrics(); RecordCurrentHistograms(); } - if (save_log) { - pending_log_ = current_log_; - } - current_log_ = NULL; + if (save_log) + log_manager_.StageCurrentLogForUpload(); + else + log_manager_.DiscardCurrentLog(); } void MetricsService::MakePendingLog() { DCHECK_EQ(thread_, base::PlatformThread::CurrentId()); - if (pending_log()) + if (log_manager_.has_staged_log()) return; switch (state_) { @@ -416,7 +409,7 @@ void MetricsService::MakePendingLog() { return; } - DCHECK(pending_log()); + DCHECK(log_manager_.has_staged_log()); } bool MetricsService::TransmissionPermitted() const { @@ -425,22 +418,6 @@ bool MetricsService::TransmissionPermitted() const { return user_permits_upload_; } -std::string MetricsService::PrepareLogSubmissionString() { - DCHECK_EQ(thread_, base::PlatformThread::CurrentId()); - - MakePendingLog(); - DCHECK(pending_log()); - if (pending_log_== NULL) { - return std::string(); - } - - pending_log_->CloseLog(); - std::string pending_log_text = pending_log_->GetEncodedLogString(); - DCHECK(!pending_log_text.empty()); - DiscardPendingLog(); - return pending_log_text; -} - bool MetricsService::UploadData() { DCHECK_EQ(thread_, base::PlatformThread::CurrentId()); @@ -453,23 +430,20 @@ bool MetricsService::UploadData() { return false; } - std::string pending_log_text = PrepareLogSubmissionString(); - DCHECK(!pending_log_text.empty()); - - // Allow security conscious users to see all metrics logs that we send. - VLOG(1) << "METRICS LOG: " << pending_log_text; + MakePendingLog(); + DCHECK(log_manager_.has_staged_log()); bool ret = true; - if (!Bzip2Compress(pending_log_text, &compressed_log_)) { + if (log_manager_.staged_log_text().empty()) { NOTREACHED() << "Failed to compress log for transmission."; ret = false; } else { HRESULT hr = ChromeFrameMetricsDataUploader::UploadDataHelper( - compressed_log_); + log_manager_.staged_log_text()); DCHECK(SUCCEEDED(hr)); } - DiscardPendingLog(); + log_manager_.DiscardStagedLog(); currently_uploading = 0; return ret; diff --git a/chrome_frame/metrics_service.h b/chrome_frame/metrics_service.h index 7b5f84f..e29ad85 100644 --- a/chrome_frame/metrics_service.h +++ b/chrome_frame/metrics_service.h @@ -103,9 +103,6 @@ class MetricsService : public MetricsServiceBase { return reporting_active_; } - // Convert pending_log_ to XML in pending_log_text_ for transmission. - std::string PrepareLogSubmissionString(); - // Upload pending data to the server by converting it to XML and compressing // it. Returns true on success. bool UploadData(); |