diff options
-rw-r--r-- | chrome/browser/metrics/metrics_log.cc | 400 | ||||
-rw-r--r-- | chrome/browser/metrics/metrics_log.h | 15 | ||||
-rw-r--r-- | chrome/browser/metrics/metrics_log_serializer.cc | 143 | ||||
-rw-r--r-- | chrome/browser/metrics/metrics_log_serializer.h | 32 | ||||
-rw-r--r-- | chrome/browser/metrics/metrics_log_serializer_unittest.cc | 118 | ||||
-rw-r--r-- | chrome/browser/metrics/metrics_log_unittest.cc | 188 | ||||
-rw-r--r-- | chrome/browser/metrics/metrics_service.cc | 190 | ||||
-rw-r--r-- | chrome/browser/metrics/metrics_service.h | 16 | ||||
-rw-r--r-- | chrome/chrome_tests.gypi | 1 | ||||
-rw-r--r-- | chrome/common/metrics/metrics_log_base.cc | 201 | ||||
-rw-r--r-- | chrome/common/metrics/metrics_log_base.h | 45 | ||||
-rw-r--r-- | chrome/common/metrics/metrics_log_base_unittest.cc | 195 | ||||
-rw-r--r-- | chrome/common/metrics/metrics_log_manager.cc | 63 | ||||
-rw-r--r-- | chrome/common/metrics/metrics_log_manager.h | 53 | ||||
-rw-r--r-- | chrome/common/metrics/metrics_log_manager_unittest.cc | 24 | ||||
-rw-r--r-- | chrome/common/pref_names.cc | 12 | ||||
-rw-r--r-- | chrome/common/pref_names.h | 6 | ||||
-rw-r--r-- | chrome_frame/metrics_service.cc | 4 |
18 files changed, 1164 insertions, 542 deletions
diff --git a/chrome/browser/metrics/metrics_log.cc b/chrome/browser/metrics/metrics_log.cc index 7170b03..1f10db6 100644 --- a/chrome/browser/metrics/metrics_log.cc +++ b/chrome/browser/metrics/metrics_log.cc @@ -12,6 +12,7 @@ #include "base/lazy_instance.h" #include "base/memory/scoped_ptr.h" #include "base/perftimer.h" +#include "base/string_number_conversions.h" #include "base/string_util.h" #include "base/sys_info.h" #include "base/third_party/nspr/prtime.h" @@ -20,14 +21,19 @@ #include "chrome/browser/autocomplete/autocomplete.h" #include "chrome/browser/autocomplete/autocomplete_match.h" #include "chrome/browser/browser_process.h" +#include "chrome/browser/gpu_performance_stats.h" #include "chrome/browser/plugin_prefs.h" #include "chrome/browser/prefs/pref_service.h" #include "chrome/browser/profiles/profile_manager.h" #include "chrome/common/chrome_version_info.h" #include "chrome/common/logging_chrome.h" +#include "chrome/common/metrics/proto/omnibox_event.pb.h" +#include "chrome/common/metrics/proto/system_profile.pb.h" #include "chrome/common/pref_names.h" +#include "content/public/browser/content_browser_client.h" #include "content/public/browser/gpu_data_manager.h" #include "content/public/common/gpu_info.h" +#include "content/public/common/content_client.h" #include "googleurl/src/gurl.h" #include "ui/gfx/screen.h" #include "webkit/plugins/webplugininfo.h" @@ -40,6 +46,8 @@ extern "C" IMAGE_DOS_HEADER __ImageBase; #endif using content::GpuDataManager; +using metrics::OmniboxEventProto; +using metrics::SystemProfileProto; namespace { @@ -55,11 +63,96 @@ std::string GetInstallDate() { } } +OmniboxEventProto::InputType AsOmniboxEventInputType( + AutocompleteInput::Type type) { + switch (type) { + case AutocompleteInput::INVALID: + return OmniboxEventProto::INVALID; + case AutocompleteInput::UNKNOWN: + return OmniboxEventProto::UNKNOWN; + case AutocompleteInput::REQUESTED_URL: + return OmniboxEventProto::REQUESTED_URL; + case AutocompleteInput::URL: + return OmniboxEventProto::URL; + case AutocompleteInput::QUERY: + return OmniboxEventProto::QUERY; + case AutocompleteInput::FORCED_QUERY: + return OmniboxEventProto::FORCED_QUERY; + default: + NOTREACHED(); + return OmniboxEventProto::INVALID; + } +} + +OmniboxEventProto::Suggestion::ProviderType AsOmniboxEventProviderType( + const AutocompleteProvider* provider) { + if (!provider) + return OmniboxEventProto::Suggestion::UNKNOWN_PROVIDER; + + const std::string& name = provider->name(); + if (name == "HistoryURL") + return OmniboxEventProto::Suggestion::URL; + if (name == "HistoryContents") + return OmniboxEventProto::Suggestion::HISTORY_CONTENTS; + if (name == "HistoryQuickProvider") + return OmniboxEventProto::Suggestion::HISTORY_QUICK; + if (name == "Search") + return OmniboxEventProto::Suggestion::SEARCH; + if (name == "Keyword") + return OmniboxEventProto::Suggestion::KEYWORD; + if (name == "Builtin") + return OmniboxEventProto::Suggestion::BUILTIN; + if (name == "ShortcutsProvider") + return OmniboxEventProto::Suggestion::SHORTCUTS; + if (name == "ExtensionApps") + return OmniboxEventProto::Suggestion::EXTENSION_APPS; + + NOTREACHED(); + return OmniboxEventProto::Suggestion::UNKNOWN_PROVIDER; +} + +OmniboxEventProto::Suggestion::ResultType AsOmniboxEventResultType( + AutocompleteMatch::Type type) { + switch (type) { + case AutocompleteMatch::URL_WHAT_YOU_TYPED: + return OmniboxEventProto::Suggestion::URL_WHAT_YOU_TYPED; + case AutocompleteMatch::HISTORY_URL: + return OmniboxEventProto::Suggestion::HISTORY_URL; + case AutocompleteMatch::HISTORY_TITLE: + return OmniboxEventProto::Suggestion::HISTORY_TITLE; + case AutocompleteMatch::HISTORY_BODY: + return OmniboxEventProto::Suggestion::HISTORY_BODY; + case AutocompleteMatch::HISTORY_KEYWORD: + return OmniboxEventProto::Suggestion::HISTORY_KEYWORD; + case AutocompleteMatch::NAVSUGGEST: + return OmniboxEventProto::Suggestion::NAVSUGGEST; + case AutocompleteMatch::SEARCH_WHAT_YOU_TYPED: + return OmniboxEventProto::Suggestion::SEARCH_WHAT_YOU_TYPED; + case AutocompleteMatch::SEARCH_HISTORY: + return OmniboxEventProto::Suggestion::SEARCH_HISTORY; + case AutocompleteMatch::SEARCH_SUGGEST: + return OmniboxEventProto::Suggestion::SEARCH_SUGGEST; + case AutocompleteMatch::SEARCH_OTHER_ENGINE: + return OmniboxEventProto::Suggestion::SEARCH_OTHER_ENGINE; + case AutocompleteMatch::EXTENSION_APP: + return OmniboxEventProto::Suggestion::EXTENSION_APP; + default: + NOTREACHED(); + return OmniboxEventProto::Suggestion::UNKNOWN_RESULT_TYPE; + } +} + // Returns the plugin preferences corresponding for this user, if available. // If multiple user profiles are loaded, returns the preferences corresponding // to an arbitrary one of the profiles. PluginPrefs* GetPluginPrefs() { ProfileManager* profile_manager = g_browser_process->profile_manager(); + + if (!profile_manager) { + // The profile manager can be NULL when testing. + return NULL; + } + std::vector<Profile*> profiles = profile_manager->GetLoadedProfiles(); if (profiles.empty()) return NULL; @@ -67,6 +160,17 @@ PluginPrefs* GetPluginPrefs() { return PluginPrefs::GetForProfile(profiles.front()); } +// Fills |plugin| with the info contained in |plugin_info| and |plugin_prefs|. +void SetPluginInfo(const webkit::WebPluginInfo& plugin_info, + const PluginPrefs* plugin_prefs, + SystemProfileProto::Plugin* plugin) { + plugin->set_name(UTF16ToUTF8(plugin_info.name)); + plugin->set_filename(plugin_info.path.BaseName().AsUTF8Unsafe()); + plugin->set_version(UTF16ToUTF8(plugin_info.version)); + if (plugin_prefs) + plugin->set_is_disabled(!plugin_prefs->IsPluginEnabled(plugin_info)); +} + } // namespace static base::LazyInstance<std::string>::Leaky @@ -124,7 +228,8 @@ const std::string& MetricsLog::version_extension() { return g_version_extension.Get(); } -void MetricsLog::RecordIncrementalStabilityElements() { +void MetricsLog::RecordIncrementalStabilityElements( + const std::vector<webkit::WebPluginInfo>& plugin_list) { DCHECK(!locked_); PrefService* pref = g_browser_process->local_state(); @@ -140,15 +245,15 @@ void MetricsLog::RecordIncrementalStabilityElements() { WriteRequiredStabilityAttributes(pref); WriteRealtimeStabilityAttributes(pref); - WritePluginStabilityElements(pref); + WritePluginStabilityElements(plugin_list, pref); } } -void MetricsLog::WriteStabilityElement(PrefService* pref) { +void MetricsLog::WriteStabilityElement( + const std::vector<webkit::WebPluginInfo>& plugin_list, + PrefService* pref) { DCHECK(!locked_); - DCHECK(pref); - // Get stability attributes out of Local State, zeroing out stored values. // NOTE: This could lead to some data loss if this report isn't successfully // sent, but that's true for all the metrics. @@ -157,31 +262,51 @@ void MetricsLog::WriteStabilityElement(PrefService* pref) { WriteRequiredStabilityAttributes(pref); WriteRealtimeStabilityAttributes(pref); - // TODO(jar): The following are all optional, so we *could* optimize them for - // values of zero (and not include them). - WriteIntAttribute("incompleteshutdowncount", - pref->GetInteger( - prefs::kStabilityIncompleteSessionEndCount)); + int incomplete_shutdown_count = + pref->GetInteger(prefs::kStabilityIncompleteSessionEndCount); pref->SetInteger(prefs::kStabilityIncompleteSessionEndCount, 0); - - - WriteIntAttribute("breakpadregistrationok", - pref->GetInteger(prefs::kStabilityBreakpadRegistrationSuccess)); + int breakpad_registration_success_count = + pref->GetInteger(prefs::kStabilityBreakpadRegistrationSuccess); pref->SetInteger(prefs::kStabilityBreakpadRegistrationSuccess, 0); - WriteIntAttribute("breakpadregistrationfail", - pref->GetInteger(prefs::kStabilityBreakpadRegistrationFail)); + int breakpad_registration_failure_count = + pref->GetInteger(prefs::kStabilityBreakpadRegistrationFail); pref->SetInteger(prefs::kStabilityBreakpadRegistrationFail, 0); - WriteIntAttribute("debuggerpresent", - pref->GetInteger(prefs::kStabilityDebuggerPresent)); + int debugger_present_count = + pref->GetInteger(prefs::kStabilityDebuggerPresent); pref->SetInteger(prefs::kStabilityDebuggerPresent, 0); - WriteIntAttribute("debuggernotpresent", - pref->GetInteger(prefs::kStabilityDebuggerNotPresent)); + int debugger_not_present_count = + pref->GetInteger(prefs::kStabilityDebuggerNotPresent); pref->SetInteger(prefs::kStabilityDebuggerNotPresent, 0); - WritePluginStabilityElements(pref); + // TODO(jar): The following are all optional, so we *could* optimize them for + // values of zero (and not include them). + + // Write the XML version. + WriteIntAttribute("incompleteshutdowncount", incomplete_shutdown_count); + WriteIntAttribute("breakpadregistrationok", + breakpad_registration_success_count); + WriteIntAttribute("breakpadregistrationfail", + breakpad_registration_failure_count); + WriteIntAttribute("debuggerpresent", debugger_present_count); + WriteIntAttribute("debuggernotpresent", debugger_not_present_count); + + // Write the protobuf version. + SystemProfileProto::Stability* stability = + uma_proto_.mutable_system_profile()->mutable_stability(); + stability->set_incomplete_shutdown_count(incomplete_shutdown_count); + stability->set_breakpad_registration_success_count( + breakpad_registration_success_count); + stability->set_breakpad_registration_failure_count( + breakpad_registration_failure_count); + stability->set_debugger_present_count(debugger_present_count); + stability->set_debugger_not_present_count(debugger_not_present_count); + + WritePluginStabilityElements(plugin_list, pref); } -void MetricsLog::WritePluginStabilityElements(PrefService* pref) { +void MetricsLog::WritePluginStabilityElements( + const std::vector<webkit::WebPluginInfo>& plugin_list, + PrefService* pref) { // Now log plugin stability info. const ListValue* plugin_stats_list = pref->GetList( prefs::kStabilityPluginStats); @@ -189,6 +314,9 @@ void MetricsLog::WritePluginStabilityElements(PrefService* pref) { return; OPEN_ELEMENT_FOR_SCOPE("plugins"); + SystemProfileProto::Stability* stability = + uma_proto_.mutable_system_profile()->mutable_stability(); + PluginPrefs* plugin_prefs = GetPluginPrefs(); for (ListValue::const_iterator iter = plugin_stats_list->begin(); iter != plugin_stats_list->end(); ++iter) { if (!(*iter)->IsType(Value::TYPE_DICTIONARY)) { @@ -200,10 +328,15 @@ void MetricsLog::WritePluginStabilityElements(PrefService* pref) { std::string plugin_name; plugin_dict->GetString(prefs::kStabilityPluginName, &plugin_name); + std::string base64_name_hash; + uint64 numeric_name_hash_ignored; + CreateHashes(plugin_name, &base64_name_hash, &numeric_name_hash_ignored); + + // Write the XML verison. OPEN_ELEMENT_FOR_SCOPE("pluginstability"); // Use "filename" instead of "name", otherwise we need to update the // UMA servers. - WriteAttribute("filename", CreateBase64Hash(plugin_name)); + WriteAttribute("filename", base64_name_hash); int launches = 0; plugin_dict->GetInteger(prefs::kStabilityPluginLaunches, &launches); @@ -216,20 +349,60 @@ void MetricsLog::WritePluginStabilityElements(PrefService* pref) { int crashes = 0; plugin_dict->GetInteger(prefs::kStabilityPluginCrashes, &crashes); WriteIntAttribute("crashcount", crashes); + + // Write the protobuf version. + // Note that this search is potentially a quadratic operation, but given the + // low number of plugins installed on a "reasonable" setup, this should be + // fine. + // TODO(isherman): Verify that this does not show up as a hotspot in + // profiler runs. + const webkit::WebPluginInfo* plugin_info = NULL; + const string16 plugin_name_utf16 = UTF8ToUTF16(plugin_name); + for (std::vector<webkit::WebPluginInfo>::const_iterator iter = + plugin_list.begin(); + iter != plugin_list.end(); ++iter) { + if (iter->name == plugin_name_utf16) { + plugin_info = &(*iter); + break; + } + } + + if (!plugin_info) { + NOTREACHED(); + continue; + } + + SystemProfileProto::Stability::PluginStability* plugin_stability = + stability->add_plugin_stability(); + SetPluginInfo(*plugin_info, plugin_prefs, + plugin_stability->mutable_plugin()); + plugin_stability->set_launch_count(launches); + plugin_stability->set_instance_count(instances); + plugin_stability->set_crash_count(crashes); } pref->ClearPref(prefs::kStabilityPluginStats); } +// The server refuses data that doesn't have certain values. crashcount and +// launchcount are currently "required" in the "stability" group. +// TODO(isherman): Stop writing these attributes specially once the migration to +// protobufs is complete. void MetricsLog::WriteRequiredStabilityAttributes(PrefService* pref) { - // The server refuses data that doesn't have certain values. crashcount and - // launchcount are currently "required" in the "stability" group. - WriteIntAttribute("launchcount", - pref->GetInteger(prefs::kStabilityLaunchCount)); + int launch_count = pref->GetInteger(prefs::kStabilityLaunchCount); pref->SetInteger(prefs::kStabilityLaunchCount, 0); - WriteIntAttribute("crashcount", - pref->GetInteger(prefs::kStabilityCrashCount)); + int crash_count = pref->GetInteger(prefs::kStabilityCrashCount); pref->SetInteger(prefs::kStabilityCrashCount, 0); + + // Write the XML version. + WriteIntAttribute("launchcount", launch_count); + WriteIntAttribute("crashcount", crash_count); + + // Write the protobuf version. + SystemProfileProto::Stability* stability = + uma_proto_.mutable_system_profile()->mutable_stability(); + stability->set_launch_count(launch_count); + stability->set_crash_count(crash_count); } void MetricsLog::WriteRealtimeStabilityAttributes(PrefService* pref) { @@ -237,71 +410,68 @@ void MetricsLog::WriteRealtimeStabilityAttributes(PrefService* pref) { // Since these are "optional," only list ones that are non-zero, as the counts // are aggergated (summed) server side. + SystemProfileProto::Stability* stability = + uma_proto_.mutable_system_profile()->mutable_stability(); int count = pref->GetInteger(prefs::kStabilityPageLoadCount); if (count) { WriteIntAttribute("pageloadcount", count); + stability->set_page_load_count(count); pref->SetInteger(prefs::kStabilityPageLoadCount, 0); } count = pref->GetInteger(prefs::kStabilityRendererCrashCount); if (count) { WriteIntAttribute("renderercrashcount", count); + stability->set_renderer_crash_count(count); pref->SetInteger(prefs::kStabilityRendererCrashCount, 0); } count = pref->GetInteger(prefs::kStabilityExtensionRendererCrashCount); if (count) { WriteIntAttribute("extensionrenderercrashcount", count); + stability->set_extension_renderer_crash_count(count); pref->SetInteger(prefs::kStabilityExtensionRendererCrashCount, 0); } count = pref->GetInteger(prefs::kStabilityRendererHangCount); if (count) { WriteIntAttribute("rendererhangcount", count); + stability->set_renderer_hang_count(count); pref->SetInteger(prefs::kStabilityRendererHangCount, 0); } count = pref->GetInteger(prefs::kStabilityChildProcessCrashCount); if (count) { WriteIntAttribute("childprocesscrashcount", count); + stability->set_child_process_crash_count(count); pref->SetInteger(prefs::kStabilityChildProcessCrashCount, 0); } #if defined(OS_CHROMEOS) count = pref->GetInteger(prefs::kStabilityOtherUserCrashCount); if (count) { - // TODO(kmixter): Write attribute once log server supports it - // and remove warning log. - // WriteIntAttribute("otherusercrashcount", count); - LOG(WARNING) << "Not yet able to send otherusercrashcount=" - << count; + stability->set_other_user_crash_count(count); pref->SetInteger(prefs::kStabilityOtherUserCrashCount, 0); } count = pref->GetInteger(prefs::kStabilityKernelCrashCount); if (count) { - // TODO(kmixter): Write attribute once log server supports it - // and remove warning log. - // WriteIntAttribute("kernelcrashcount", count); - LOG(WARNING) << "Not yet able to send kernelcrashcount=" - << count; + stability->set_kernel_crash_count(count); pref->SetInteger(prefs::kStabilityKernelCrashCount, 0); } count = pref->GetInteger(prefs::kStabilitySystemUncleanShutdownCount); if (count) { - // TODO(kmixter): Write attribute once log server supports it - // and remove warning log. - // WriteIntAttribute("systemuncleanshutdowns", count); - LOG(WARNING) << "Not yet able to send systemuncleanshutdowns=" - << count; + stability->set_unclean_system_shutdown_count(count); pref->SetInteger(prefs::kStabilitySystemUncleanShutdownCount, 0); } #endif // OS_CHROMEOS int64 recent_duration = GetIncrementalUptime(pref); - if (recent_duration) + if (recent_duration) { WriteInt64Attribute("uptimesec", recent_duration); + stability->set_uptime_sec(recent_duration); + } } void MetricsLog::WritePluginList( @@ -311,32 +481,53 @@ void MetricsLog::WritePluginList( PluginPrefs* plugin_prefs = GetPluginPrefs(); OPEN_ELEMENT_FOR_SCOPE("plugins"); - + SystemProfileProto* system_profile = uma_proto_.mutable_system_profile(); for (std::vector<webkit::WebPluginInfo>::const_iterator iter = plugin_list.begin(); iter != plugin_list.end(); ++iter) { + std::string base64_name_hash; + uint64 numeric_name_hash_ignored; + CreateHashes(UTF16ToUTF8(iter->name), + &base64_name_hash, + &numeric_name_hash_ignored); + + std::string filename_bytes = iter->path.BaseName().AsUTF8Unsafe(); + std::string base64_filename_hash; + uint64 numeric_filename_hash; + CreateHashes(filename_bytes, + &base64_filename_hash, + &numeric_filename_hash); + + // Write the XML version. OPEN_ELEMENT_FOR_SCOPE("plugin"); // Plugin name and filename are hashed for the privacy of those // testing unreleased new extensions. - WriteAttribute("name", CreateBase64Hash(UTF16ToUTF8(iter->name))); - std::string filename_bytes = -#if defined(OS_WIN) - UTF16ToUTF8(iter->path.BaseName().value()); -#else - iter->path.BaseName().value(); -#endif - WriteAttribute("filename", CreateBase64Hash(filename_bytes)); + WriteAttribute("name", base64_name_hash); + WriteAttribute("filename", base64_filename_hash); WriteAttribute("version", UTF16ToUTF8(iter->version)); if (plugin_prefs) WriteIntAttribute("disabled", !plugin_prefs->IsPluginEnabled(*iter)); + + // Write the protobuf version. + SystemProfileProto::Plugin* plugin = system_profile->add_plugin(); + SetPluginInfo(*iter, plugin_prefs, plugin); } } void MetricsLog::WriteInstallElement() { + std::string install_date = GetInstallDate(); + + // Write the XML version. OPEN_ELEMENT_FOR_SCOPE("install"); - WriteAttribute("installdate", GetInstallDate()); + WriteAttribute("installdate", install_date); WriteIntAttribute("buildid", 0); // We're using appversion instead. + + // Write the protobuf version. + int numeric_install_date; + bool success = base::StringToInt(install_date, &numeric_install_date); + DCHECK(success); + uma_proto_.mutable_system_profile()->set_install_date(numeric_install_date); } void MetricsLog::RecordEnvironment( @@ -353,42 +544,96 @@ void MetricsLog::RecordEnvironment( WritePluginList(plugin_list); - WriteStabilityElement(pref); + WriteStabilityElement(plugin_list, pref); + SystemProfileProto* system_profile = uma_proto_.mutable_system_profile(); + system_profile->set_application_locale( + content::GetContentClient()->browser()->GetApplicationLocale()); + + SystemProfileProto::Hardware* hardware = system_profile->mutable_hardware(); { + std::string cpu_architecture = base::SysInfo::CPUArchitecture(); + + // Write the XML version. OPEN_ELEMENT_FOR_SCOPE("cpu"); - WriteAttribute("arch", base::SysInfo::CPUArchitecture()); + WriteAttribute("arch", cpu_architecture); + + // Write the protobuf version. + hardware->set_cpu_architecture(cpu_architecture); } { + int system_memory_mb = base::SysInfo::AmountOfPhysicalMemoryMB(); + + // Write the XML version. OPEN_ELEMENT_FOR_SCOPE("memory"); - WriteIntAttribute("mb", base::SysInfo::AmountOfPhysicalMemoryMB()); + WriteIntAttribute("mb", system_memory_mb); #if defined(OS_WIN) WriteIntAttribute("dllbase", reinterpret_cast<int>(&__ImageBase)); #endif + + // Write the protobuf version. + hardware->set_system_ram_mb(system_memory_mb); +#if defined(OS_WIN) + hardware->set_dll_base(reinterpret_cast<uint64>(&__ImageBase)); +#endif } { + std::string os_name = base::SysInfo::OperatingSystemName(); + std::string os_version = base::SysInfo::OperatingSystemVersion(); + + // Write the XML version. OPEN_ELEMENT_FOR_SCOPE("os"); - WriteAttribute("name", - base::SysInfo::OperatingSystemName()); - WriteAttribute("version", - base::SysInfo::OperatingSystemVersion()); + WriteAttribute("name", os_name); + WriteAttribute("version", os_version); + + // Write the protobuf version. + SystemProfileProto::OS* os = system_profile->mutable_os(); + os->set_name(os_name); + os->set_version(os_version); } { OPEN_ELEMENT_FOR_SCOPE("gpu"); - content::GPUInfo gpu_info = GpuDataManager::GetInstance()->GetGPUInfo(); + const content::GPUInfo& gpu_info = + GpuDataManager::GetInstance()->GetGPUInfo(); + GpuPerformanceStats gpu_performance_stats = + GpuPerformanceStats::RetrieveGpuPerformanceStats(); + + // Write the XML version. WriteIntAttribute("vendorid", gpu_info.vendor_id); WriteIntAttribute("deviceid", gpu_info.device_id); + + // Write the protobuf version. + SystemProfileProto::Hardware::Graphics* gpu = hardware->mutable_gpu(); + gpu->set_vendor_id(gpu_info.vendor_id); + gpu->set_device_id(gpu_info.device_id); + gpu->set_driver_version(gpu_info.driver_version); + gpu->set_driver_date(gpu_info.driver_date); + SystemProfileProto::Hardware::Graphics::PerformanceStatistics* + gpu_performance = gpu->mutable_performance_statistics(); + gpu_performance->set_graphics_score(gpu_performance_stats.graphics); + gpu_performance->set_gaming_score(gpu_performance_stats.gaming); + gpu_performance->set_overall_score(gpu_performance_stats.overall); } { - OPEN_ELEMENT_FOR_SCOPE("display"); const gfx::Size display_size = gfx::Screen::GetPrimaryMonitorSize(); - WriteIntAttribute("xsize", display_size.width()); - WriteIntAttribute("ysize", display_size.height()); - WriteIntAttribute("screens", gfx::Screen::GetNumMonitors()); + int display_width = display_size.width(); + int display_height = display_size.height(); + int screen_count = gfx::Screen::GetNumMonitors(); + + // Write the XML version. + OPEN_ELEMENT_FOR_SCOPE("display"); + WriteIntAttribute("xsize", display_width); + WriteIntAttribute("ysize", display_height); + WriteIntAttribute("screens", screen_count); + + // Write the protobuf version. + hardware->set_primary_screen_width(display_width); + hardware->set_primary_screen_height(display_height); + hardware->set_screen_count(screen_count); } { @@ -493,6 +738,7 @@ void MetricsLog::WriteProfileMetrics(const std::string& profileidhash, void MetricsLog::RecordOmniboxOpenedURL(const AutocompleteLog& log) { DCHECK(!locked_); + // Write the XML version. OPEN_ELEMENT_FOR_SCOPE("uielement"); WriteAttribute("action", "autocomplete"); WriteAttribute("targetidhash", ""); @@ -538,5 +784,25 @@ void MetricsLog::RecordOmniboxOpenedURL(const AutocompleteLog& log) { } } + // Write the protobuf version. + OmniboxEventProto* omnibox_event = uma_proto_.add_omnibox_event(); + omnibox_event->set_time(MetricsLogBase::GetCurrentTime()); + if (log.tab_id != -1) { + // If we know what tab the autocomplete URL was opened in, log it. + omnibox_event->set_tab_id(log.tab_id); + } + omnibox_event->set_typed_length(log.text.length()); + omnibox_event->set_selected_index(log.selected_index); + omnibox_event->set_completed_length(log.inline_autocompleted_length); + omnibox_event->set_input_type(AsOmniboxEventInputType(log.input_type)); + for (AutocompleteResult::const_iterator i(log.result.begin()); + i != log.result.end(); ++i) { + OmniboxEventProto::Suggestion* suggestion = omnibox_event->add_suggestion(); + suggestion->set_provider(AsOmniboxEventProviderType(i->provider)); + suggestion->set_result_type(AsOmniboxEventResultType(i->type)); + suggestion->set_relevance(i->relevance); + suggestion->set_is_starred(i->starred); + } + ++num_events_; } diff --git a/chrome/browser/metrics/metrics_log.h b/chrome/browser/metrics/metrics_log.h index a5a3504..5935139 100644 --- a/chrome/browser/metrics/metrics_log.h +++ b/chrome/browser/metrics/metrics_log.h @@ -65,18 +65,25 @@ class MetricsLog : public MetricsLogBase { // Record recent delta for critical stability metrics. We can't wait for a // restart to gather these, as that delay biases our observation away from // users that run happily for a looooong time. We send increments with each - // uma log upload, just as we send histogram data. - void RecordIncrementalStabilityElements(); + // uma log upload, just as we send histogram data. Takes the list of + // installed plugins as a parameter because that can't be obtained + // synchronously from the UI thread. + void RecordIncrementalStabilityElements( + const std::vector<webkit::WebPluginInfo>& plugin_list); private: FRIEND_TEST_ALL_PREFIXES(MetricsLogTest, ChromeOSStabilityData); // Writes application stability metrics (as part of the profile log). // NOTE: Has the side-effect of clearing those counts. - void WriteStabilityElement(PrefService* pref); + void WriteStabilityElement( + const std::vector<webkit::WebPluginInfo>& plugin_list, + PrefService* pref); // Within stability group, write plugin crash stats. - void WritePluginStabilityElements(PrefService* pref); + void WritePluginStabilityElements( + const std::vector<webkit::WebPluginInfo>& plugin_list, + PrefService* pref); // Within the stability group, write required attributes. void WriteRequiredStabilityAttributes(PrefService* pref); diff --git a/chrome/browser/metrics/metrics_log_serializer.cc b/chrome/browser/metrics/metrics_log_serializer.cc index bbddf60..3369f85 100644 --- a/chrome/browser/metrics/metrics_log_serializer.cc +++ b/chrome/browser/metrics/metrics_log_serializer.cc @@ -12,10 +12,12 @@ #include "chrome/browser/prefs/scoped_user_pref_update.h" #include "chrome/common/pref_names.h" +namespace { + // 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; +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 @@ -26,15 +28,14 @@ static const size_t kMaxInitialLogsPersisted = 20; // 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; +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; +const size_t kChecksumEntryCount = 2; -namespace { -// TODO(ziadh): This is here temporarily for a side experiment. Remove later -// on. +// TODO(isherman): Remove this histogram once it's confirmed that there are no +// encoding failures for protobuf logs. enum LogStoreStatus { STORE_SUCCESS, // Successfully presisted log. ENCODE_FAIL, // Failed to encode log. @@ -43,17 +44,23 @@ enum LogStoreStatus { }; MetricsLogSerializer::LogReadStatus MakeRecallStatusHistogram( - MetricsLogSerializer::LogReadStatus status) { - UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogRecall", status, - MetricsLogSerializer::END_RECALL_STATUS); + MetricsLogSerializer::LogReadStatus status, + bool is_xml) { + if (is_xml) { + UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogRecall", + status, MetricsLogSerializer::END_RECALL_STATUS); + } else { + UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogRecallProtobufs", + 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 @@ -61,52 +68,76 @@ MetricsLogSerializer::MetricsLogSerializer() {} MetricsLogSerializer::~MetricsLogSerializer() {} -void MetricsLogSerializer::SerializeLogs(const std::vector<std::string>& logs, - MetricsLogManager::LogType log_type) { +void MetricsLogSerializer::SerializeLogs( + const std::vector<MetricsLogManager::SerializedLog>& logs, + MetricsLogManager::LogType log_type) { PrefService* local_state = g_browser_process->local_state(); DCHECK(local_state); - const char* pref = NULL; + const char* pref_xml = NULL; + const char* pref_proto = NULL; size_t max_store_count = 0; switch (log_type) { case MetricsLogManager::INITIAL_LOG: - pref = prefs::kMetricsInitialLogs; + pref_xml = prefs::kMetricsInitialLogsXml; + pref_proto = prefs::kMetricsInitialLogsProto; max_store_count = kMaxInitialLogsPersisted; break; case MetricsLogManager::ONGOING_LOG: - pref = prefs::kMetricsOngoingLogs; + pref_xml = prefs::kMetricsOngoingLogsXml; + pref_proto = prefs::kMetricsOngoingLogsProto; 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); + + // Write the XML version. + ListPrefUpdate update_xml(local_state, pref_xml); + WriteLogsToPrefList(logs, true, max_store_count, update_xml.Get()); + + // Write the protobuf version. + ListPrefUpdate update_proto(local_state, pref_proto); + WriteLogsToPrefList(logs, false, max_store_count, update_proto.Get()); } -void MetricsLogSerializer::DeserializeLogs(MetricsLogManager::LogType log_type, - std::vector<std::string>* logs) { +void MetricsLogSerializer::DeserializeLogs( + MetricsLogManager::LogType log_type, + std::vector<MetricsLogManager::SerializedLog>* 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); + const char* pref_xml; + const char* pref_proto; + if (log_type == MetricsLogManager::INITIAL_LOG) { + pref_xml = prefs::kMetricsInitialLogsXml; + pref_proto = prefs::kMetricsInitialLogsProto; + } else { + pref_xml = prefs::kMetricsOngoingLogsXml; + pref_proto = prefs::kMetricsOngoingLogsProto; + } + + const ListValue* unsent_logs_xml = local_state->GetList(pref_xml); + const ListValue* unsent_logs_proto = local_state->GetList(pref_proto); + if (ReadLogsFromPrefList(*unsent_logs_xml, true, logs) == RECALL_SUCCESS) { + // In order to try to keep the data sent to both servers roughly in sync, + // only read the protobuf data if we read the XML data successfully. + ReadLogsFromPrefList(*unsent_logs_proto, false, logs); + } } // static void MetricsLogSerializer::WriteLogsToPrefList( - const std::vector<std::string>& local_list, - const size_t kMaxLocalListSize, - ListValue* list) { + const std::vector<MetricsLogManager::SerializedLog>& local_list, + bool is_xml, + size_t max_list_size, + base::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() > max_list_size) + start = local_list.size() - max_list_size; + DCHECK_LE(start, local_list.size()); if (local_list.size() <= start) return; @@ -116,11 +147,13 @@ void MetricsLogSerializer::WriteLogsToPrefList( base::MD5Context ctx; base::MD5Init(&ctx); std::string encoded_log; - for (std::vector<std::string>::const_iterator it = local_list.begin() + start; + for (std::vector<MetricsLogManager::SerializedLog>::const_iterator it = + local_list.begin() + start; it != local_list.end(); ++it) { + const std::string& value = is_xml ? it->xml : it->proto; // We encode the compressed log as Value::CreateStringValue() expects to // take a valid UTF8 string. - if (!base::Base64Encode(*it, &encoded_log)) { + if (!base::Base64Encode(value, &encoded_log)) { MakeStoreStatusHistogram(ENCODE_FAIL); list->Clear(); return; @@ -140,44 +173,58 @@ void MetricsLogSerializer::WriteLogsToPrefList( // static MetricsLogSerializer::LogReadStatus MetricsLogSerializer::ReadLogsFromPrefList( const ListValue& list, - std::vector<std::string>* local_list) { - DCHECK(local_list->empty()); + bool is_xml, + std::vector<MetricsLogManager::SerializedLog>* local_list) { if (list.GetSize() == 0) - return MakeRecallStatusHistogram(LIST_EMPTY); + return MakeRecallStatusHistogram(LIST_EMPTY, is_xml); if (list.GetSize() < 3) - return MakeRecallStatusHistogram(LIST_SIZE_TOO_SMALL); + return MakeRecallStatusHistogram(LIST_SIZE_TOO_SMALL, is_xml); // 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); - + return MakeRecallStatusHistogram(LIST_SIZE_MISSING, is_xml); // Account for checksum and size included in the list. if (static_cast<unsigned int>(size) != list.GetSize() - kChecksumEntryCount) { - return MakeRecallStatusHistogram(LIST_SIZE_CORRUPTION); + return MakeRecallStatusHistogram(LIST_SIZE_CORRUPTION, is_xml); + } + + // Allocate strings for all of the logs we are going to read in. + // Do this ahead of time so that we can decode the string values directly into + // the elements of |local_list|, and thereby avoid making copies of the + // serialized logs, which can be fairly large. + if (is_xml) { + DCHECK(local_list->empty()); + local_list->resize(size); + } else if (local_list->size() != static_cast<size_t>(size)) { + return MakeRecallStatusHistogram(XML_PROTO_MISMATCH, false); } base::MD5Context ctx; base::MD5Init(&ctx); std::string encoded_log; - std::string decoded_log; + size_t local_index = 0; for (ListValue::const_iterator it = list.begin() + 1; - it != list.end() - 1; ++it) { // Last element is the checksum. - valid = (*it)->GetAsString(&encoded_log); + it != list.end() - 1; // Last element is the checksum. + ++it, ++local_index) { + bool valid = (*it)->GetAsString(&encoded_log); if (!valid) { local_list->clear(); - return MakeRecallStatusHistogram(LOG_STRING_CORRUPTION); + return MakeRecallStatusHistogram(LOG_STRING_CORRUPTION, is_xml); } base::MD5Update(&ctx, encoded_log); + DCHECK_LT(local_index, local_list->size()); + std::string& decoded_log = is_xml ? + (*local_list)[local_index].xml : + (*local_list)[local_index].proto; if (!base::Base64Decode(encoded_log, &decoded_log)) { local_list->clear(); - return MakeRecallStatusHistogram(DECODE_FAIL); + return MakeRecallStatusHistogram(DECODE_FAIL, is_xml); } - local_list->push_back(decoded_log); } // Verify checksum. @@ -188,11 +235,11 @@ MetricsLogSerializer::LogReadStatus MetricsLogSerializer::ReadLogsFromPrefList( valid = (*(list.end() - 1))->GetAsString(&recovered_md5); if (!valid) { local_list->clear(); - return MakeRecallStatusHistogram(CHECKSUM_STRING_CORRUPTION); + return MakeRecallStatusHistogram(CHECKSUM_STRING_CORRUPTION, is_xml); } if (recovered_md5 != base::MD5DigestToBase16(digest)) { local_list->clear(); - return MakeRecallStatusHistogram(CHECKSUM_CORRUPTION); + return MakeRecallStatusHistogram(CHECKSUM_CORRUPTION, is_xml); } - return MakeRecallStatusHistogram(RECALL_SUCCESS); + return MakeRecallStatusHistogram(RECALL_SUCCESS, is_xml); } diff --git a/chrome/browser/metrics/metrics_log_serializer.h b/chrome/browser/metrics/metrics_log_serializer.h index 69986b6..9a1e630 100644 --- a/chrome/browser/metrics/metrics_log_serializer.h +++ b/chrome/browser/metrics/metrics_log_serializer.h @@ -17,7 +17,7 @@ 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 + // Used to produce a histogram that keeps track of the status of recalling // persisted per logs. enum LogReadStatus { RECALL_SUCCESS, // We were able to correctly recall a persisted log. @@ -28,8 +28,9 @@ class MetricsLogSerializer : public MetricsLogManager::LogSerializer { 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(). + // GetAsString(). DECODE_FAIL, // Failed to decode log. + XML_PROTO_MISMATCH, // The XML and protobuf logs have inconsistent data. END_RECALL_STATUS // Number of bins to use to create the histogram. }; @@ -37,23 +38,30 @@ class MetricsLogSerializer : public MetricsLogManager::LogSerializer { virtual ~MetricsLogSerializer(); // Implementation of MetricsLogManager::LogSerializer - virtual void SerializeLogs(const std::vector<std::string>& logs, - MetricsLogManager::LogType log_type) OVERRIDE; - virtual void DeserializeLogs(MetricsLogManager::LogType log_type, - std::vector<std::string>* logs) OVERRIDE; + virtual void SerializeLogs( + const std::vector<MetricsLogManager::SerializedLog>& logs, + MetricsLogManager::LogType log_type) OVERRIDE; + virtual void DeserializeLogs( + MetricsLogManager::LogType log_type, + std::vector<MetricsLogManager::SerializedLog>* logs) OVERRIDE; 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); + // pref list, along with list size and checksum. If |is_xml| is true, writes + // the XML data from |local_list|; otherwise writes the protobuf data. + static void WriteLogsToPrefList( + const std::vector<MetricsLogManager::SerializedLog>& local_list, + bool is_xml, + size_t max_list_size, + base::ListValue* list); // Decodes and verifies the textual log data from |list|, populating - // |local_list| and returning a status code. + // |local_list| and returning a status code. If |is_xml| is true, populates + // the XML data in |local_list|; otherwise populates the protobuf data. static LogReadStatus ReadLogsFromPrefList( const base::ListValue& list, - std::vector<std::string>* local_list); + bool is_xml, + std::vector<MetricsLogManager::SerializedLog>* local_list); FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, EmptyLogList); FRIEND_TEST_ALL_PREFIXES(MetricsLogSerializerTest, SingleElementLogList); diff --git a/chrome/browser/metrics/metrics_log_serializer_unittest.cc b/chrome/browser/metrics/metrics_log_serializer_unittest.cc index 59c257b..f023a7c 100644 --- a/chrome/browser/metrics/metrics_log_serializer_unittest.cc +++ b/chrome/browser/metrics/metrics_log_serializer_unittest.cc @@ -1,4 +1,4 @@ -// Copyright (c) 2011 The Chromium Authors. All rights reserved. +// Copyright (c) 2012 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. @@ -8,42 +8,46 @@ #include "chrome/browser/metrics/metrics_log_serializer.h" #include "testing/gtest/include/gtest/gtest.h" +typedef MetricsLogManager::SerializedLog SerializedLog; + namespace { - class MetricsLogSerializerTest : public ::testing::Test { - }; -} -static const size_t kMaxLocalListSize = 3; +const size_t kMaxLocalListSize = 3; + +} // namespace + +class MetricsLogSerializerTest : public ::testing::Test { +}; // Store and retrieve empty list. TEST(MetricsLogSerializerTest, EmptyLogList) { ListValue list; - std::vector<std::string> local_list; + std::vector<SerializedLog> local_list; - MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + MetricsLogSerializer::WriteLogsToPrefList(local_list, true, 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( + MetricsLogSerializer::LIST_EMPTY, + MetricsLogSerializer::ReadLogsFromPrefList(list, true, &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()); + std::vector<SerializedLog> local_list(1); + local_list[0].xml = "Hello world!"; - MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + MetricsLogSerializer::WriteLogsToPrefList(local_list, true, kMaxLocalListSize, &list); // |list| will now contain the following: // [1, Base64Encode("Hello world!"), MD5("Hello world!")]. - EXPECT_EQ(3U, list.GetSize()); + ASSERT_EQ(3U, list.GetSize()); // Examine each element. ListValue::const_iterator it = list.begin(); @@ -66,55 +70,56 @@ TEST(MetricsLogSerializerTest, SingleElementLogList) { EXPECT_TRUE(it == list.end()); // Reached end of list. local_list.clear(); - EXPECT_EQ(MetricsLogSerializer::RECALL_SUCCESS, - MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ( + MetricsLogSerializer::RECALL_SUCCESS, + MetricsLogSerializer::ReadLogsFromPrefList(list, true, &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::vector<SerializedLog> local_list(4); + local_list[0].proto = "one"; + local_list[1].proto = "two"; + local_list[2].proto = "three"; + local_list[3].proto = "four"; std::string expected_first; - base::Base64Encode(local_list[local_list.size() - kMaxLocalListSize], + base::Base64Encode(local_list[local_list.size() - kMaxLocalListSize].proto, &expected_first); std::string expected_last; - base::Base64Encode(local_list[local_list.size() - 1], + base::Base64Encode(local_list[local_list.size() - 1].proto, &expected_last); - MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, - &list); + MetricsLogSerializer::WriteLogsToPrefList(local_list, false, + 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); + EXPECT_EQ(expected_first, actual_first); std::string actual_last; EXPECT_TRUE((*(list.end() - 2))->GetAsString(&actual_last)); - EXPECT_TRUE(expected_last == actual_last); + EXPECT_EQ(expected_last, actual_last); local_list.clear(); - EXPECT_EQ(MetricsLogSerializer::RECALL_SUCCESS, - MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ( + MetricsLogSerializer::RECALL_SUCCESS, + MetricsLogSerializer::ReadLogsFromPrefList(list, true, &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, + std::vector<SerializedLog> local_list(1); + local_list[0].xml = "Hello world!"; + + MetricsLogSerializer::WriteLogsToPrefList(local_list, true, kMaxLocalListSize, &list); EXPECT_EQ(3U, list.GetSize()); @@ -123,19 +128,20 @@ TEST(MetricsLogSerializerTest, SmallRecoveredListSize) { EXPECT_EQ(2U, list.GetSize()); local_list.clear(); - EXPECT_EQ(MetricsLogSerializer::LIST_SIZE_TOO_SMALL, - MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ( + MetricsLogSerializer::LIST_SIZE_TOO_SMALL, + MetricsLogSerializer::ReadLogsFromPrefList(list, true, &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"); + std::vector<SerializedLog> local_list(2); + local_list[0].xml = "one"; + local_list[1].xml = "two"; EXPECT_EQ(2U, local_list.size()); - MetricsLogSerializer::WriteLogsToPrefList(local_list, kMaxLocalListSize, + MetricsLogSerializer::WriteLogsToPrefList(local_list, true, kMaxLocalListSize, &list); EXPECT_EQ(4U, list.GetSize()); @@ -143,18 +149,19 @@ TEST(MetricsLogSerializerTest, RemoveSizeFromLogList) { EXPECT_EQ(3U, list.GetSize()); local_list.clear(); - EXPECT_EQ(MetricsLogSerializer::LIST_SIZE_MISSING, - MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ( + MetricsLogSerializer::LIST_SIZE_MISSING, + MetricsLogSerializer::ReadLogsFromPrefList(list, true, &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, + std::vector<SerializedLog> local_list(1); + local_list[0].xml = "Hello world!"; + + MetricsLogSerializer::WriteLogsToPrefList(local_list, true, kMaxLocalListSize, &list); EXPECT_EQ(3U, list.GetSize()); @@ -163,19 +170,19 @@ TEST(MetricsLogSerializerTest, CorruptSizeOfLogList) { EXPECT_EQ(3U, list.GetSize()); local_list.clear(); - EXPECT_EQ(MetricsLogSerializer::LIST_SIZE_CORRUPTION, - MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ( + MetricsLogSerializer::LIST_SIZE_CORRUPTION, + MetricsLogSerializer::ReadLogsFromPrefList(list, true, &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, + std::vector<SerializedLog> local_list(1); + local_list[0].xml = "Hello world!"; + + MetricsLogSerializer::WriteLogsToPrefList(local_list, true, kMaxLocalListSize, &list); EXPECT_EQ(3U, list.GetSize()); @@ -187,6 +194,7 @@ TEST(MetricsLogSerializerTest, CorruptChecksumOfLogList) { EXPECT_EQ(3U, list.GetSize()); local_list.clear(); - EXPECT_EQ(MetricsLogSerializer::CHECKSUM_CORRUPTION, - MetricsLogSerializer::ReadLogsFromPrefList(list, &local_list)); + EXPECT_EQ( + MetricsLogSerializer::CHECKSUM_CORRUPTION, + MetricsLogSerializer::ReadLogsFromPrefList(list, true, &local_list)); } diff --git a/chrome/browser/metrics/metrics_log_unittest.cc b/chrome/browser/metrics/metrics_log_unittest.cc index edea42b..4c4b555 100644 --- a/chrome/browser/metrics/metrics_log_unittest.cc +++ b/chrome/browser/metrics/metrics_log_unittest.cc @@ -14,18 +14,15 @@ #include "chrome/test/base/testing_pref_service.h" #include "googleurl/src/gurl.h" #include "testing/gtest/include/gtest/gtest.h" +#include "webkit/plugins/webplugininfo.h" using base::TimeDelta; namespace { - class MetricsLogTest : public testing::Test { - }; -}; - // Since buildtime is highly variable, this function will scan an output log and // replace it with a consistent number. -static void NormalizeBuildtime(std::string* xml_encoded) { +void NormalizeBuildtime(std::string* xml_encoded) { std::string prefix = "buildtime=\""; const char postfix = '\"'; size_t offset = xml_encoded->find(prefix); @@ -43,54 +40,6 @@ static void NormalizeBuildtime(std::string* xml_encoded) { xml_encoded->replace(offset, postfix_position - offset, "123246"); } -TEST(MetricsLogTest, EmptyRecord) { - std::string expected_output = base::StringPrintf( - "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " - "appversion=\"%s\"/>", MetricsLog::GetVersionString().c_str()); - - MetricsLog log("bogus client ID", 0); - log.CloseLog(); - - int size = log.GetEncodedLogSize(); - ASSERT_GT(size, 0); - - std::string encoded; - // Leave room for the NUL terminator. - ASSERT_TRUE(log.GetEncodedLog(WriteInto(&encoded, size + 1), size)); - TrimWhitespaceASCII(encoded, TRIM_ALL, &encoded); - NormalizeBuildtime(&encoded); - NormalizeBuildtime(&expected_output); - - ASSERT_EQ(expected_output, encoded); -} - -#if defined(OS_CHROMEOS) -TEST(MetricsLogTest, ChromeOSEmptyRecord) { - std::string expected_output = base::StringPrintf( - "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " - "appversion=\"%s\" hardwareclass=\"sample-class\"/>", - MetricsLog::GetVersionString().c_str()); - - MetricsLog log("bogus client ID", 0); - log.set_hardware_class("sample-class"); - log.CloseLog(); - - int size = log.GetEncodedLogSize(); - ASSERT_GT(size, 0); - - std::string encoded; - // Leave room for the NUL terminator. - ASSERT_TRUE(log.GetEncodedLog(WriteInto(&encoded, size + 1), size)); - TrimWhitespaceASCII(encoded, TRIM_ALL, &encoded); - NormalizeBuildtime(&encoded); - NormalizeBuildtime(&expected_output); - - ASSERT_EQ(expected_output, encoded); -} -#endif // OS_CHROMEOS - -namespace { - class NoTimeMetricsLog : public MetricsLog { public: NoTimeMetricsLog(std::string client_id, int session_id): @@ -103,103 +52,12 @@ class NoTimeMetricsLog : public MetricsLog { } }; -}; // namespace +} // namespace -TEST(MetricsLogTest, WindowEvent) { - std::string expected_output = base::StringPrintf( - "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " - "appversion=\"%s\">\n" - " <window action=\"create\" windowid=\"0\" session=\"0\" time=\"\"/>\n" - " <window action=\"open\" windowid=\"1\" parent=\"0\" " - "session=\"0\" time=\"\"/>\n" - " <window action=\"close\" windowid=\"1\" parent=\"0\" " - "session=\"0\" time=\"\"/>\n" - " <window action=\"destroy\" windowid=\"0\" session=\"0\" time=\"\"/>\n" - "</log>", MetricsLog::GetVersionString().c_str()); - - NoTimeMetricsLog log("bogus client ID", 0); - log.RecordWindowEvent(MetricsLog::WINDOW_CREATE, 0, -1); - log.RecordWindowEvent(MetricsLog::WINDOW_OPEN, 1, 0); - log.RecordWindowEvent(MetricsLog::WINDOW_CLOSE, 1, 0); - log.RecordWindowEvent(MetricsLog::WINDOW_DESTROY, 0, -1); - log.CloseLog(); - - ASSERT_EQ(4, log.num_events()); - - int size = log.GetEncodedLogSize(); - ASSERT_GT(size, 0); - - std::string encoded; - // Leave room for the NUL terminator. - ASSERT_TRUE(log.GetEncodedLog(WriteInto(&encoded, size + 1), size)); - TrimWhitespaceASCII(encoded, TRIM_ALL, &encoded); - NormalizeBuildtime(&encoded); - NormalizeBuildtime(&expected_output); - - ASSERT_EQ(expected_output, encoded); -} - -TEST(MetricsLogTest, LoadEvent) { - std::string expected_output = base::StringPrintf( - "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " - "appversion=\"%s\">\n" - " <document action=\"load\" docid=\"1\" window=\"3\" loadtime=\"7219\" " - "origin=\"link\" session=\"0\" time=\"\"/>\n" - "</log>", MetricsLog::GetVersionString().c_str()); - - NoTimeMetricsLog log("bogus client ID", 0); - log.RecordLoadEvent(3, GURL("http://google.com"), - content::PAGE_TRANSITION_LINK, 1, - TimeDelta::FromMilliseconds(7219)); - - log.CloseLog(); - - ASSERT_EQ(1, log.num_events()); - - int size = log.GetEncodedLogSize(); - ASSERT_GT(size, 0); - - std::string encoded; - // Leave room for the NUL terminator. - ASSERT_TRUE(log.GetEncodedLog(WriteInto(&encoded, size + 1), size)); - TrimWhitespaceASCII(encoded, TRIM_ALL, &encoded); - NormalizeBuildtime(&encoded); - NormalizeBuildtime(&expected_output); - - ASSERT_EQ(expected_output, encoded); -} +class MetricsLogTest : public testing::Test { +}; #if defined(OS_CHROMEOS) -TEST(MetricsLogTest, ChromeOSLoadEvent) { - std::string expected_output = base::StringPrintf( - "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " - "appversion=\"%s\" hardwareclass=\"sample-class\">\n" - " <document action=\"load\" docid=\"1\" window=\"3\" loadtime=\"7219\" " - "origin=\"link\" session=\"0\" time=\"\"/>\n" - "</log>", MetricsLog::GetVersionString().c_str()); - - NoTimeMetricsLog log("bogus client ID", 0); - log.RecordLoadEvent(3, GURL("http://google.com"), - content::PAGE_TRANSITION_LINK, 1, - TimeDelta::FromMilliseconds(7219)); - log.set_hardware_class("sample-class"); - log.CloseLog(); - - ASSERT_EQ(1, log.num_events()); - - int size = log.GetEncodedLogSize(); - ASSERT_GT(size, 0); - - std::string encoded; - // Leave room for the NUL terminator. - ASSERT_TRUE(log.GetEncodedLog(WriteInto(&encoded, size + 1), size)); - TrimWhitespaceASCII(encoded, TRIM_ALL, &encoded); - NormalizeBuildtime(&encoded); - NormalizeBuildtime(&expected_output); - - ASSERT_EQ(expected_output, encoded); -} - TEST(MetricsLogTest, ChromeOSStabilityData) { NoTimeMetricsLog log("bogus client ID", 0); TestingPrefService prefs; @@ -209,16 +67,19 @@ TEST(MetricsLogTest, ChromeOSStabilityData) { prefs.SetInteger(prefs::kStabilityOtherUserCrashCount, 11); prefs.SetInteger(prefs::kStabilityKernelCrashCount, 12); prefs.SetInteger(prefs::kStabilitySystemUncleanShutdownCount, 13); + + std::vector<webkit::WebPluginInfo> plugins; + std::string expected_output = base::StringPrintf( "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " "appversion=\"%s\">\n" "<stability stuff>\n", MetricsLog::GetVersionString().c_str()); // Expect 3 warnings about not yet being able to send the // Chrome OS stability stats. - log.WriteStabilityElement(&prefs); + log.WriteStabilityElement(plugins, &prefs); log.CloseLog(); - int size = log.GetEncodedLogSize(); + int size = log.GetEncodedLogSizeXml(); ASSERT_GT(size, 0); EXPECT_EQ(0, prefs.GetInteger(prefs::kStabilityChildProcessCrashCount)); @@ -228,7 +89,7 @@ TEST(MetricsLogTest, ChromeOSStabilityData) { std::string encoded; // Leave room for the NUL terminator. - bool encoding_result = log.GetEncodedLog( + bool encoding_result = log.GetEncodedLogXml( WriteInto(&encoded, size + 1), size); ASSERT_TRUE(encoding_result); @@ -244,31 +105,4 @@ TEST(MetricsLogTest, ChromeOSStabilityData) { EXPECT_EQ(std::string::npos, encoded.find(" systemuncleanshutdowns=")); } - #endif // OS_CHROMEOS - -// Make sure our ID hashes are the same as what we see on the server side. -TEST(MetricsLogTest, CreateHash) { - static const struct { - std::string input; - std::string output; - } cases[] = { - {"Back", "0x0557fa923dcee4d0"}, - {"Forward", "0x67d2f6740a8eaebf"}, - {"NewTab", "0x290eb683f96572f1"}, - }; - - for (size_t i = 0; i < ARRAYSIZE_UNSAFE(cases); i++) { - std::string hash_string = MetricsLog::CreateHash(cases[i].input); - - // Convert to hex string - // We're only checking the first 8 bytes, because that's what - // the metrics server uses. - std::string hash_hex = "0x"; - for (size_t j = 0; j < 8; j++) { - base::StringAppendF(&hash_hex, "%02x", - static_cast<uint8>(hash_string.data()[j])); - } - EXPECT_EQ(cases[i].output, hash_hex); - } -}; diff --git a/chrome/browser/metrics/metrics_service.cc b/chrome/browser/metrics/metrics_service.cc index 1626a5c..fdf9bfd 100644 --- a/chrome/browser/metrics/metrics_service.cc +++ b/chrome/browser/metrics/metrics_service.cc @@ -182,6 +182,7 @@ #include "content/public/browser/plugin_service.h" #include "content/public/browser/render_process_host.h" #include "content/public/common/url_fetcher.h" +#include "net/base/load_flags.h" #include "webkit/plugins/webplugininfo.h" // TODO(port): port browser_distribution.h. @@ -200,30 +201,44 @@ using content::BrowserThread; using content::ChildProcessData; using content::PluginService; +namespace { + // Check to see that we're being called on only one thread. -static bool IsSingleThreaded(); +bool IsSingleThreaded() { + static base::PlatformThreadId thread_id = 0; + if (!thread_id) + thread_id = base::PlatformThread::CurrentId(); + return base::PlatformThread::CurrentId() == thread_id; +} + +const char kMetricsTypeXml[] = "application/vnd.mozilla.metrics.bz2"; +const char kMetricsTypeProto[] = "application/vnd.chrome.uma"; -static const char kMetricsType[] = "application/vnd.mozilla.metrics.bz2"; +const char kServerUrlXml[] = + "https://clients4.google.com/firefox/metrics/collect"; +const char kServerUrlProto[] = "https://clients4.google.com/uma/v2"; // The delay, in seconds, after starting recording before doing expensive // initialization work. -static const int kInitializationDelaySeconds = 30; +const int kInitializationDelaySeconds = 30; // This specifies the amount of time to wait for all renderers to send their // data. -static const int kMaxHistogramGatheringWaitDuration = 60000; // 60 seconds. +const int kMaxHistogramGatheringWaitDuration = 60000; // 60 seconds. // The maximum number of events in a log uploaded to the UMA server. -static const int kEventLimit = 2400; +const int kEventLimit = 2400; // If an upload fails, and the transmission was over this byte count, then we // will discard the log, and not try to retransmit it. We also don't persist // the log to the prefs for transmission during the next chrome session if this // limit is exceeded. -static const int kUploadLogAvoidRetransmitSize = 50000; +const size_t kUploadLogAvoidRetransmitSize = 50000; // Interval, in minutes, between state saves. -static const int kSaveStateIntervalMinutes = 5; +const int kSaveStateIntervalMinutes = 5; + +} // static MetricsService::ShutdownCleanliness MetricsService::clean_shutdown_status_ = @@ -323,8 +338,10 @@ void MetricsService::RegisterPrefs(PrefService* local_state) { 0); local_state->RegisterIntegerPref(prefs::kNumFoldersInOtherBookmarkFolder, 0); local_state->RegisterIntegerPref(prefs::kNumKeywords, 0); - local_state->RegisterListPref(prefs::kMetricsInitialLogs); - local_state->RegisterListPref(prefs::kMetricsOngoingLogs); + local_state->RegisterListPref(prefs::kMetricsInitialLogsXml); + local_state->RegisterListPref(prefs::kMetricsOngoingLogsXml); + local_state->RegisterListPref(prefs::kMetricsInitialLogsProto); + local_state->RegisterListPref(prefs::kMetricsOngoingLogsProto); local_state->RegisterInt64Pref(prefs::kUninstallMetricsPageLoadCount, 0); local_state->RegisterInt64Pref(prefs::kUninstallLaunchCount, 0); @@ -357,15 +374,16 @@ void MetricsService::DiscardOldStabilityStats(PrefService* local_state) { local_state->ClearPref(prefs::kStabilityPluginStats); - local_state->ClearPref(prefs::kMetricsInitialLogs); - local_state->ClearPref(prefs::kMetricsOngoingLogs); + local_state->ClearPref(prefs::kMetricsInitialLogsXml); + local_state->ClearPref(prefs::kMetricsOngoingLogsXml); + local_state->ClearPref(prefs::kMetricsInitialLogsProto); + local_state->ClearPref(prefs::kMetricsOngoingLogsProto); } MetricsService::MetricsService() : recording_active_(false), reporting_active_(false), state_(INITIALIZED), - current_fetch_(NULL), io_thread_(NULL), idle_since_last_transmission_(false), next_window_id_(0), @@ -628,11 +646,13 @@ void MetricsService::RecordBreakpadHasDebugger(bool has_debugger) { void MetricsService::InitializeMetricsState() { #if defined(OS_POSIX) - server_url_ = L"https://clients4.google.com/firefox/metrics/collect"; + server_url_xml_ = ASCIIToUTF16(kServerUrlXml); + server_url_proto_ = ASCIIToUTF16(kServerUrlProto); network_stats_server_ = "chrome.googleechotest.com"; #else BrowserDistribution* dist = BrowserDistribution::GetDistribution(); - server_url_ = dist->GetStatsServerURL(); + server_url_xml_ = dist->GetStatsServerURL(); + server_url_proto_ = ASCIIToUTF16(kServerUrlProto); network_stats_server_ = dist->GetNetworkStatsServer(); #endif @@ -840,7 +860,7 @@ void MetricsService::StopRecording() { MetricsLog* current_log = static_cast<MetricsLog*>(log_manager_.current_log()); DCHECK(current_log); - current_log->RecordIncrementalStabilityElements(); + current_log->RecordIncrementalStabilityElements(plugins_); RecordCurrentHistograms(); log_manager_.StageCurrentLogForUpload(); @@ -935,8 +955,9 @@ void MetricsService::OnHistogramSynchronizationDone() { // If somehow there is a fetch in progress, we return and hope things work // out. The scheduler isn't informed since if this happens, the scheduler // will get a response from the upload. - DCHECK(!current_fetch_.get()); - if (current_fetch_.get()) + DCHECK(!current_fetch_xml_.get()); + DCHECK(!current_fetch_proto_.get()); + if (current_fetch_xml_.get() || current_fetch_proto_.get()) return; // This function should only be called as the callback from an ansynchronous @@ -966,7 +987,8 @@ void MetricsService::OnHistogramSynchronizationDone() { PrepareFetchWithStagedLog(); - if (!current_fetch_.get()) { + if (!current_fetch_xml_.get()) { + DCHECK(!current_fetch_proto_.get()); // Compression failed, and log discarded :-/. log_manager_.DiscardStagedLog(); scheduler_->UploadCancelled(); @@ -974,11 +996,19 @@ void MetricsService::OnHistogramSynchronizationDone() { // compressed that, so that we can signal that we're losing logs. return; } + // Currently, the staged log for the protobuf version of the data is discarded + // after we create the URL request, so that there is no chance for + // re-transmission in case the corresponding XML request fails. We will + // handle protobuf failures more carefully once that becomes the main + // pipeline, i.e. once we switch away from the XML pipeline. + DCHECK(current_fetch_proto_.get() || !log_manager_.has_staged_log_proto()); DCHECK(!waiting_for_asynchronus_reporting_step_); waiting_for_asynchronus_reporting_step_ = true; - current_fetch_->Start(); + current_fetch_xml_->Start(); + if (current_fetch_proto_.get()) + current_fetch_proto_->Start(); HandleIdleSinceLastTransmission(true); } @@ -1052,13 +1082,40 @@ void MetricsService::StoreUnsentLogs() { void MetricsService::PrepareFetchWithStagedLog() { DCHECK(!log_manager_.staged_log_text().empty()); - DCHECK(!current_fetch_.get()); - current_fetch_.reset(content::URLFetcher::Create( - GURL(WideToUTF16(server_url_)), content::URLFetcher::POST, this)); - current_fetch_->SetRequestContext( + // Prepare the XML version. + DCHECK(!current_fetch_xml_.get()); + current_fetch_xml_.reset(content::URLFetcher::Create( + GURL(server_url_xml_), content::URLFetcher::POST, this)); + current_fetch_xml_->SetRequestContext( g_browser_process->system_request_context()); - current_fetch_->SetUploadData(kMetricsType, log_manager_.staged_log_text()); + current_fetch_xml_->SetUploadData(kMetricsTypeXml, + log_manager_.staged_log_text().xml); + // We already drop cookies server-side, but we might as well strip them out + // client-side as well. + current_fetch_xml_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES | + net::LOAD_DO_NOT_SEND_COOKIES); + + // Prepare the protobuf version. + DCHECK(!current_fetch_proto_.get()); + if (log_manager_.has_staged_log_proto()) { + current_fetch_proto_.reset(content::URLFetcher::Create( + GURL(server_url_proto_), content::URLFetcher::POST, this)); + current_fetch_proto_->SetRequestContext( + g_browser_process->system_request_context()); + current_fetch_proto_->SetUploadData(kMetricsTypeProto, + log_manager_.staged_log_text().proto); + // We already drop cookies server-side, but we might as well strip them out + // client-side as well. + current_fetch_proto_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES | + net::LOAD_DO_NOT_SEND_COOKIES); + + // Discard the protobuf version of the staged log, so that we will avoid + // re-uploading it even if we need to re-upload the XML version. + // TODO(isherman): Handle protobuf upload failures more gracefully once we + // transition away from the XML-based pipeline. + log_manager_.DiscardStagedLogProto(); + } } static const char* StatusToString(const net::URLRequestStatus& status) { @@ -1084,30 +1141,71 @@ static const char* StatusToString(const net::URLRequestStatus& status) { } } +// We need to wait for two responses: the response to the XML upload, and the +// response to the protobuf upload. For now, only the XML upload's response +// affects decisions like whether to retry the upload, whether to abandon the +// upload because it is too large, etc. However, we still need to wait for the +// protobuf upload, as we cannot reset |current_fetch_proto_| until we have +// confirmation that the network request was sent; and the easiest way to do +// that is to wait for the response. In case the XML upload's response arrives +// first, we cache that response until the protobuf upload's response also +// arrives. +// +// Note that if the XML upload succeeds but the protobuf upload fails, we will +// not retry the protobuf upload. If the XML upload fails while the protobuf +// upload succeeds, we will still avoid re-uploading the protobuf data because +// we "zap" the data after the first upload attempt. This means that we might +// lose protobuf uploads when XML ones succeed; but we will never duplicate any +// protobuf uploads. Protobuf failures should be rare enough to where this +// should be ok while we have the two pipelines running in parallel. void MetricsService::OnURLFetchComplete(const content::URLFetcher* source) { DCHECK(waiting_for_asynchronus_reporting_step_); + + // We're not allowed to re-use the existing |URLFetcher|s, so free them here. + scoped_ptr<content::URLFetcher> s; + if (source == current_fetch_xml_.get()) { + s.reset(current_fetch_xml_.release()); + + // Cache the XML responses, in case we still need to wait for the protobuf + // response. + response_code_ = source->GetResponseCode(); + response_status_ = StatusToString(source->GetStatus()); + source->GetResponseAsString(&response_data_); + } else if (source == current_fetch_proto_.get()) { + s.reset(current_fetch_proto_.release()); + } else { + NOTREACHED(); + return; + } + + // If we're still waiting for one of the responses, keep waiting... + if (current_fetch_xml_.get() || current_fetch_proto_.get()) + return; + + // We should only be able to reach here once we've received responses to both + // the XML and the protobuf requests. We should always have the response code + // available. + DCHECK_NE(response_code_, content::URLFetcher::RESPONSE_CODE_INVALID); waiting_for_asynchronus_reporting_step_ = false; - DCHECK(current_fetch_.get()); - // We're not allowed to re-use it. Delete it on function exit since we use it. - scoped_ptr<content::URLFetcher> s(current_fetch_.release()); + // Confirm send so that we can move on. - VLOG(1) << "METRICS RESPONSE CODE: " << source->GetResponseCode() - << " status=" << StatusToString(source->GetStatus()); + VLOG(1) << "METRICS RESPONSE CODE: " << response_code_ + << " status=" << response_status_; - bool upload_succeeded = source->GetResponseCode() == 200; + bool upload_succeeded = response_code_ == 200; // Provide boolean for error recovery (allow us to ignore response_code). bool discard_log = false; if (!upload_succeeded && - (log_manager_.staged_log_text().length() > - static_cast<size_t>(kUploadLogAvoidRetransmitSize))) { + log_manager_.staged_log_text().xml.length() > + kUploadLogAvoidRetransmitSize) { UMA_HISTOGRAM_COUNTS( "UMA.Large Rejected Log was Discarded", - static_cast<int>(log_manager_.staged_log_text().length())); + static_cast<int>(log_manager_.staged_log_text().xml.length())); discard_log = true; - } else if (source->GetResponseCode() == 400) { + } else if (response_code_ == 400) { // Bad syntax. Retransmission won't work. UMA_HISTOGRAM_COUNTS("UMA.Unacceptable_Log_Discarded", state_); discard_log = true; @@ -1115,12 +1213,10 @@ void MetricsService::OnURLFetchComplete(const content::URLFetcher* source) { if (!upload_succeeded && !discard_log) { VLOG(1) << "METRICS: transmission attempt returned a failure code: " - << source->GetResponseCode() << ". Verify network connectivity"; + << response_code_ << ". Verify network connectivity"; LogBadResponseCode(); } else { // Successful receipt (or we are discarding log). - std::string data; - source->GetResponseAsString(&data); - VLOG(1) << "METRICS RESPONSE DATA: " << data; + VLOG(1) << "METRICS RESPONSE DATA: " << response_data_; switch (state_) { case INITIAL_LOG_READY: state_ = SENDING_OLD_LOGS; @@ -1147,7 +1243,7 @@ void MetricsService::OnURLFetchComplete(const content::URLFetcher* source) { // Error 400 indicates a problem with the log, not with the server, so // don't consider that a sign that the server is in trouble. - bool server_is_healthy = upload_succeeded || source->GetResponseCode() == 400; + bool server_is_healthy = upload_succeeded || response_code_ == 400; scheduler_->UploadFinished(server_is_healthy, log_manager_.has_unsent_logs()); @@ -1155,16 +1251,21 @@ void MetricsService::OnURLFetchComplete(const content::URLFetcher* source) { // Collect network stats if UMA upload succeeded. if (server_is_healthy && io_thread_) chrome_browser_net::CollectNetworkStats(network_stats_server_, io_thread_); + + // Reset the cached response data. + response_code_ = content::URLFetcher::RESPONSE_CODE_INVALID; + response_data_ = std::string(); + response_status_ = std::string(); } void MetricsService::LogBadResponseCode() { VLOG(1) << "Verify your metrics logs are formatted correctly. Verify server " - "is active at " << server_url_; + "is active at " << server_url_xml_; if (!log_manager_.has_staged_log()) { VLOG(1) << "METRICS: Recorder shutdown during log transmission."; } else { VLOG(1) << "METRICS: transmission retry being scheduled for " - << log_manager_.staged_log_text(); + << log_manager_.staged_log_text().xml; } } @@ -1536,13 +1637,6 @@ bool MetricsService::IsPluginProcess(content::ProcessType type) { type == content::PROCESS_TYPE_PPAPI_PLUGIN); } -static bool IsSingleThreaded() { - static base::PlatformThreadId thread_id = 0; - if (!thread_id) - thread_id = base::PlatformThread::CurrentId(); - return base::PlatformThread::CurrentId() == thread_id; -} - #if defined(OS_CHROMEOS) void MetricsService::StartExternalMetrics() { external_metrics_ = new chromeos::ExternalMetrics; diff --git a/chrome/browser/metrics/metrics_service.h b/chrome/browser/metrics/metrics_service.h index 56f9776..8803905 100644 --- a/chrome/browser/metrics/metrics_service.h +++ b/chrome/browser/metrics/metrics_service.h @@ -340,10 +340,18 @@ class MetricsService : public content::NotificationObserver, std::vector<webkit::WebPluginInfo> plugins_; // The outstanding transmission appears as a URL Fetch operation. - scoped_ptr<content::URLFetcher> current_fetch_; - - // The URL for the metrics server. - std::wstring server_url_; + scoped_ptr<content::URLFetcher> current_fetch_xml_; + scoped_ptr<content::URLFetcher> current_fetch_proto_; + + // Cached responses from the XML request while we wait for a response to the + // protubuf request. + int response_code_; + std::string response_status_; + std::string response_data_; + + // The URLs for the XML and protobuf metrics servers. + string16 server_url_xml_; + string16 server_url_proto_; // The TCP/UDP echo server to collect network connectivity stats. std::string network_stats_server_; diff --git a/chrome/chrome_tests.gypi b/chrome/chrome_tests.gypi index 1a690c6..67884a2 100644 --- a/chrome/chrome_tests.gypi +++ b/chrome/chrome_tests.gypi @@ -2071,6 +2071,7 @@ 'common/mac/mock_launchd.h', 'common/mac/objc_method_swizzle_unittest.mm', 'common/mac/objc_zombie_unittest.mm', + 'common/metrics/metrics_log_base_unittest.cc', 'common/metrics/metrics_log_manager_unittest.cc', 'common/multi_process_lock_unittest.cc', 'common/net/gaia/gaia_auth_fetcher_unittest.cc', diff --git a/chrome/common/metrics/metrics_log_base.cc b/chrome/common/metrics/metrics_log_base.cc index b2c42f6..d6a467f 100644 --- a/chrome/common/metrics/metrics_log_base.cc +++ b/chrome/common/metrics/metrics_log_base.cc @@ -9,10 +9,13 @@ #include "base/md5.h" #include "base/perftimer.h" #include "base/string_number_conversions.h" +#include "base/sys_byteorder.h" #include "base/sys_info.h" #include "base/third_party/nspr/prtime.h" #include "base/utf_string_conversions.h" #include "chrome/common/logging_chrome.h" +#include "chrome/common/metrics/proto/histogram_event.pb.h" +#include "chrome/common/metrics/proto/user_action_event.pb.h" #include "libxml/xmlwriter.h" #define OPEN_ELEMENT_FOR_SCOPE(name) ScopedElement scoped_element(this, name) @@ -20,11 +23,8 @@ using base::Histogram; using base::Time; using base::TimeDelta; - -// http://blogs.msdn.com/oldnewthing/archive/2004/10/25/247180.aspx -#if defined(OS_WIN) -extern "C" IMAGE_DOS_HEADER __ImageBase; -#endif +using metrics::HistogramEventProto; +using metrics::UserActionEventProto; namespace { @@ -33,6 +33,43 @@ inline const unsigned char* UnsignedChar(const char* input) { return reinterpret_cast<const unsigned char*>(input); } +// Any id less than 16 bytes is considered to be a testing id. +bool IsTestingID(const std::string& id) { + return id.size() < 16; +} + +// Converts the 8-byte prefix of an MD5 hash into a uint64 value. +inline uint64 HashToUInt64(const std::string& hash) { + uint64 value; + DCHECK_GE(hash.size(), sizeof(value)); + memcpy(&value, hash.data(), sizeof(value)); + return base::htonll(value); +} + +// Creates an MD5 hash of the given value, and returns hash as a byte buffer +// encoded as an std::string. +std::string CreateHash(const std::string& value) { + base::MD5Context context; + base::MD5Init(&context); + base::MD5Update(&context, value); + + base::MD5Digest digest; + base::MD5Final(&digest, &context); + + std::string hash(reinterpret_cast<char*>(digest.a), arraysize(digest.a)); + + // The following log is VERY helpful when folks add some named histogram into + // the code, but forgot to update the descriptive list of histograms. When + // that happens, all we get to see (server side) is a hash of the histogram + // name. We can then use this logging to find out what histogram name was + // being hashed to a given MD5 value by just running the version of Chromium + // in question with --enable-logging. + DVLOG(1) << "Metrics: Hash numeric [" << value << "]=[" << HashToUInt64(hash) + << "]"; + + return hash; +} + } // namespace class MetricsLogBase::XmlWrapper { @@ -92,11 +129,23 @@ MetricsLogBase::MetricsLogBase(const std::string& client_id, int session_id, locked_(false), xml_wrapper_(new XmlWrapper), num_events_(0) { + int64_t build_time = GetBuildTime(); + // Write the XML version. StartElement("log"); WriteAttribute("clientid", client_id_); - WriteInt64Attribute("buildtime", GetBuildTime()); + WriteInt64Attribute("buildtime", build_time); WriteAttribute("appversion", version_string); + + // Write the protobuf version. + if (IsTestingID(client_id_)) { + uma_proto_.set_client_id(0); + } else { + uma_proto_.set_client_id(HashToUInt64(CreateHash(client_id))); + } + uma_proto_.set_session_id(session_id); + uma_proto_.mutable_system_profile()->set_build_timestamp(build_time); + uma_proto_.mutable_system_profile()->set_app_version(version_string); } MetricsLogBase::~MetricsLogBase() { @@ -109,6 +158,38 @@ MetricsLogBase::~MetricsLogBase() { xml_wrapper_ = NULL; } +// static +void MetricsLogBase::CreateHashes(const std::string& string, + std::string* base64_encoded_hash, + uint64* numeric_hash) { + std::string hash = CreateHash(string); + + std::string encoded_digest; + if (base::Base64Encode(hash, &encoded_digest)) + DVLOG(1) << "Metrics: Hash [" << encoded_digest << "]=[" << string << "]"; + + *base64_encoded_hash = encoded_digest; + *numeric_hash = HashToUInt64(hash); +} + +// static +int64 MetricsLogBase::GetBuildTime() { + static int64 integral_build_time = 0; + if (!integral_build_time) { + Time time; + const char* kDateTime = __DATE__ " " __TIME__ " GMT"; + bool result = Time::FromString(kDateTime, &time); + DCHECK(result); + integral_build_time = static_cast<int64>(time.ToTimeT()); + } + return integral_build_time; +} + +// static +int64 MetricsLogBase::GetCurrentTime() { + return (base::TimeTicks::Now() - base::TimeTicks()).InSeconds(); +} + void MetricsLogBase::CloseLog() { DCHECK(!locked_); locked_ = true; @@ -120,6 +201,9 @@ void MetricsLogBase::CloseLog() { DCHECK_GE(result, 0); #if defined(OS_CHROMEOS) + // TODO(isherman): Once the XML pipeline is deprecated, there will be no need + // to track the hardware class in a separate member variable and only write it + // out when the log is closed. xmlNodePtr root = xmlDocGetRootElement(xml_wrapper_->doc()); if (!hardware_class_.empty()) { // The hardware class is determined after the first ongoing log is @@ -127,6 +211,10 @@ void MetricsLogBase::CloseLog() { // attribute when the log is closed instead. xmlNewProp(root, UnsignedChar("hardwareclass"), UnsignedChar(hardware_class_.c_str())); + + // Write to the protobuf too. + uma_proto_.mutable_system_profile()->mutable_hardware()->set_hardware_class( + hardware_class_); } // Flattens the XML tree into a character buffer. @@ -142,79 +230,51 @@ void MetricsLogBase::CloseLog() { #endif // OS_CHROMEOS } -int MetricsLogBase::GetEncodedLogSize() { +int MetricsLogBase::GetEncodedLogSizeXml() { DCHECK(locked_); CHECK(xml_wrapper_); CHECK(xml_wrapper_->buffer()); return xml_wrapper_->buffer()->use; } -bool MetricsLogBase::GetEncodedLog(char* buffer, int buffer_size) { +bool MetricsLogBase::GetEncodedLogXml(char* buffer, int buffer_size) { DCHECK(locked_); - if (buffer_size < GetEncodedLogSize()) + if (buffer_size < GetEncodedLogSizeXml()) return false; - memcpy(buffer, xml_wrapper_->buffer()->content, GetEncodedLogSize()); + memcpy(buffer, xml_wrapper_->buffer()->content, GetEncodedLogSizeXml()); return true; } -std::string MetricsLogBase::GetEncodedLogString() { +void MetricsLogBase::GetEncodedLogProto(std::string* encoded_log) { DCHECK(locked_); - return std::string(reinterpret_cast<char*>(xml_wrapper_->buffer()->content)); + uma_proto_.SerializeToString(encoded_log); } int MetricsLogBase::GetElapsedSeconds() { return static_cast<int>((Time::Now() - start_time_).InSeconds()); } -std::string MetricsLogBase::CreateHash(const std::string& value) { - base::MD5Context ctx; - base::MD5Init(&ctx); - base::MD5Update(&ctx, value); - - base::MD5Digest digest; - base::MD5Final(&digest, &ctx); - - uint64 reverse_uint64; - // UMA only uses first 8 chars of hash. We use the above uint64 instead - // of a unsigned char[8] so that we don't run into strict aliasing issues - // in the LOG statement below when trying to interpret reverse as a uint64. - unsigned char* reverse = reinterpret_cast<unsigned char *>(&reverse_uint64); - DCHECK(arraysize(digest.a) >= sizeof(reverse_uint64)); - for (size_t i = 0; i < sizeof(reverse_uint64); ++i) - reverse[i] = digest.a[sizeof(reverse_uint64) - i - 1]; - // The following log is VERY helpful when folks add some named histogram into - // the code, but forgot to update the descriptive list of histograms. When - // that happens, all we get to see (server side) is a hash of the histogram - // name. We can then use this logging to find out what histogram name was - // being hashed to a given MD5 value by just running the version of Chromium - // in question with --enable-logging. - DVLOG(1) << "Metrics: Hash numeric [" << value - << "]=[" << reverse_uint64 << "]"; - return std::string(reinterpret_cast<char*>(digest.a), arraysize(digest.a)); -} - -std::string MetricsLogBase::CreateBase64Hash(const std::string& string) { - std::string encoded_digest; - if (base::Base64Encode(CreateHash(string), &encoded_digest)) { - DVLOG(1) << "Metrics: Hash [" << encoded_digest << "]=[" << string << "]"; - return encoded_digest; - } - return std::string(); -} - void MetricsLogBase::RecordUserAction(const char* key) { DCHECK(!locked_); - std::string command_hash = CreateBase64Hash(key); - if (command_hash.empty()) { + std::string base64_hash; + uint64 numeric_hash; + CreateHashes(key, &base64_hash, &numeric_hash); + if (base64_hash.empty()) { NOTREACHED() << "Unable generate encoded hash of command: " << key; return; } + // Write the XML version. OPEN_ELEMENT_FOR_SCOPE("uielement"); WriteAttribute("action", "command"); - WriteAttribute("targetidhash", command_hash); + WriteAttribute("targetidhash", base64_hash); + + // Write the protobuf version. + UserActionEventProto* user_action = uma_proto_.add_user_action_event(); + user_action->set_name_hash(numeric_hash); + user_action->set_time(MetricsLogBase::GetCurrentTime()); // TODO(jhughes): Properly track windows. WriteIntAttribute("window", 0); @@ -310,7 +370,7 @@ void MetricsLogBase::WriteCommonEventAttributes() { } void MetricsLogBase::WriteAttribute(const std::string& name, - const std::string& value) { + const std::string& value) { DCHECK(!locked_); DCHECK(!name.empty()); @@ -359,19 +419,6 @@ void MetricsLogBase::EndElement() { DCHECK_GE(result, 0); } -// static -int64 MetricsLogBase::GetBuildTime() { - static int64 integral_build_time = 0; - if (!integral_build_time) { - Time time; - const char* kDateTime = __DATE__ " " __TIME__ " GMT"; - bool result = Time::FromString(kDateTime, &time); - DCHECK(result); - integral_build_time = static_cast<int64>(time.ToTimeT()); - } - return integral_build_time; -} - // TODO(JAR): A The following should really be part of the histogram class. // Internal state is being needlessly exposed, and it would be hard to reuse // this code. If we moved this into the Histogram class, then we could use @@ -387,7 +434,14 @@ void MetricsLogBase::RecordHistogramDelta( OPEN_ELEMENT_FOR_SCOPE("histogram"); - WriteAttribute("name", CreateBase64Hash(histogram.histogram_name())); + std::string base64_name_hash; + uint64 numeric_name_hash; + CreateHashes(histogram.histogram_name(), + &base64_name_hash, + &numeric_name_hash); + + // Write the XML version. + WriteAttribute("name", base64_name_hash); WriteInt64Attribute("sum", snapshot.sum()); // TODO(jar): Remove sumsquares when protobuffer accepts this as optional. @@ -401,4 +455,19 @@ void MetricsLogBase::RecordHistogramDelta( WriteIntAttribute("count", snapshot.counts(i)); } } + + // Write the protobuf version. + HistogramEventProto* histogram_proto = uma_proto_.add_histogram_event(); + histogram_proto->set_name_hash(numeric_name_hash); + histogram_proto->set_sum(snapshot.sum()); + + for (size_t i = 0; i < histogram.bucket_count(); ++i) { + if (snapshot.counts(i)) { + HistogramEventProto::Bucket* bucket = histogram_proto->add_bucket(); + bucket->set_min(histogram.ranges(i)); + bucket->set_max(histogram.ranges(i + 1)); + bucket->set_bucket_index(i); + bucket->set_count(snapshot.counts(i)); + } + } } diff --git a/chrome/common/metrics/metrics_log_base.h b/chrome/common/metrics/metrics_log_base.h index 62981be..3c493dd 100644 --- a/chrome/common/metrics/metrics_log_base.h +++ b/chrome/common/metrics/metrics_log_base.h @@ -14,6 +14,7 @@ #include "base/basictypes.h" #include "base/metrics/histogram.h" #include "base/time.h" +#include "chrome/common/metrics/proto/chrome_user_metrics_extension.pb.h" #include "content/public/common/page_transition_types.h" class GURL; @@ -29,6 +30,24 @@ class MetricsLogBase { const std::string& version_string); virtual ~MetricsLogBase(); + // Computes the MD5 hash of the given string. + // Fills |base64_encoded_hash| with the hash, encoded in base64. + // Fills |numeric_hash| with the first 8 bytes of the hash. + static void CreateHashes(const std::string& string, + std::string* base64_encoded_hash, + uint64* numeric_hash); + + // Get the GMT buildtime for the current binary, expressed in seconds since + // Januray 1, 1970 GMT. + // The value is used to identify when a new build is run, so that previous + // reliability stats, from other builds, can be abandoned. + static int64 GetBuildTime(); + + // Convenience function to return the current time at a resolution in seconds. + // This wraps base::TimeTicks, and hence provides an abstract time that is + // always incrementing for use in measuring time durations. + static int64 GetCurrentTime(); + // Records a user-initiated action. void RecordUserAction(const char* key); @@ -64,10 +83,12 @@ class MetricsLogBase { // record. They can only be called after CloseLog() has been called. // GetEncodedLog returns false if buffer_size is less than // GetEncodedLogSize(); - int GetEncodedLogSize(); - bool GetEncodedLog(char* buffer, int buffer_size); - // Returns an empty string on failure. - std::string GetEncodedLogString(); + int GetEncodedLogSizeXml(); + bool GetEncodedLogXml(char* buffer, int buffer_size); + + // Fills |encoded_log| with the protobuf representation of the record. Can + // only be called after CloseLog() has been called. + void GetEncodedLogProto(std::string* encoded_log); // Returns the amount of time in seconds that this log has been in use. int GetElapsedSeconds(); @@ -78,19 +99,6 @@ class MetricsLogBase { hardware_class_ = hardware_class; } - // Creates an MD5 hash of the given value, and returns hash as a byte - // buffer encoded as a std::string. - static std::string CreateHash(const std::string& value); - - // Return a base64-encoded MD5 hash of the given string. - static std::string CreateBase64Hash(const std::string& string); - - // Get the GMT buildtime for the current binary, expressed in seconds since - // Januray 1, 1970 GMT. - // The value is used to identify when a new build is run, so that previous - // reliability stats, from other builds, can be abandoned. - static int64 GetBuildTime(); - protected: class XmlWrapper; @@ -156,6 +164,9 @@ class MetricsLogBase { int num_events_; // the number of events recorded in this log + // Stores the protocol buffer representation for this log. + metrics::ChromeUserMetricsExtension uma_proto_; + private: DISALLOW_COPY_AND_ASSIGN(MetricsLogBase); }; diff --git a/chrome/common/metrics/metrics_log_base_unittest.cc b/chrome/common/metrics/metrics_log_base_unittest.cc new file mode 100644 index 0000000..610c11ca --- /dev/null +++ b/chrome/common/metrics/metrics_log_base_unittest.cc @@ -0,0 +1,195 @@ +// Copyright (c) 2012 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 <string> + +#include "base/base64.h" +#include "base/format_macros.h" +#include "base/stringprintf.h" +#include "base/string_util.h" +#include "base/time.h" +#include "chrome/common/metrics/metrics_log_base.h" +#include "googleurl/src/gurl.h" +#include "testing/gtest/include/gtest/gtest.h" + +using base::TimeDelta; + +namespace { + +// Since buildtime is highly variable, this function will scan an output log and +// replace it with a consistent number. +void NormalizeBuildtime(std::string* xml_encoded) { + std::string prefix = "buildtime=\""; + const char postfix = '\"'; + size_t offset = xml_encoded->find(prefix); + ASSERT_NE(std::string::npos, offset); + offset += prefix.size(); + size_t postfix_position = xml_encoded->find(postfix, offset); + ASSERT_NE(std::string::npos, postfix_position); + for (size_t i = offset; i < postfix_position; ++i) { + char digit = xml_encoded->at(i); + ASSERT_GE(digit, '0'); + ASSERT_LE(digit, '9'); + } + + // Insert a single fake buildtime. + xml_encoded->replace(offset, postfix_position - offset, "123246"); +} + +class NoTimeMetricsLogBase : public MetricsLogBase { + public: + NoTimeMetricsLogBase(std::string client_id, + int session_id, + std::string version_string): + MetricsLogBase(client_id, session_id, version_string) {} + virtual ~NoTimeMetricsLogBase() {} + + // Override this so that output is testable. + virtual std::string GetCurrentTimeString() OVERRIDE { + return std::string(); + } +}; + +} // namespace + +TEST(MetricsLogBaseTest, EmptyRecord) { + std::string expected_output = +#if defined(OS_CHROMEOS) + "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " + "appversion=\"bogus version\" hardwareclass=\"sample-class\"/>"; +#else + "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " + "appversion=\"bogus version\"/>"; +#endif // OS_CHROMEOS + + MetricsLogBase log("bogus client ID", 0, "bogus version"); + log.set_hardware_class("sample-class"); + log.CloseLog(); + + int size = log.GetEncodedLogSizeXml(); + ASSERT_GT(size, 0); + + std::string encoded; + // Leave room for the NUL terminator. + ASSERT_TRUE(log.GetEncodedLogXml(WriteInto(&encoded, size + 1), size)); + TrimWhitespaceASCII(encoded, TRIM_ALL, &encoded); + NormalizeBuildtime(&encoded); + NormalizeBuildtime(&expected_output); + + ASSERT_EQ(expected_output, encoded); +} + +TEST(MetricsLogBaseTest, WindowEvent) { + std::string expected_output = + "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " + "appversion=\"bogus version\">\n" + " <window action=\"create\" windowid=\"0\" session=\"0\" time=\"\"/>\n" + " <window action=\"open\" windowid=\"1\" parent=\"0\" " + "session=\"0\" time=\"\"/>\n" + " <window action=\"close\" windowid=\"1\" parent=\"0\" " + "session=\"0\" time=\"\"/>\n" + " <window action=\"destroy\" windowid=\"0\" session=\"0\" time=\"\"/>\n" + "</log>"; + + NoTimeMetricsLogBase log("bogus client ID", 0, "bogus version"); + log.RecordWindowEvent(MetricsLogBase::WINDOW_CREATE, 0, -1); + log.RecordWindowEvent(MetricsLogBase::WINDOW_OPEN, 1, 0); + log.RecordWindowEvent(MetricsLogBase::WINDOW_CLOSE, 1, 0); + log.RecordWindowEvent(MetricsLogBase::WINDOW_DESTROY, 0, -1); + log.CloseLog(); + + ASSERT_EQ(4, log.num_events()); + + int size = log.GetEncodedLogSizeXml(); + ASSERT_GT(size, 0); + + std::string encoded; + // Leave room for the NUL terminator. + ASSERT_TRUE(log.GetEncodedLogXml(WriteInto(&encoded, size + 1), size)); + TrimWhitespaceASCII(encoded, TRIM_ALL, &encoded); + NormalizeBuildtime(&encoded); + NormalizeBuildtime(&expected_output); + + ASSERT_EQ(expected_output, encoded); +} + +TEST(MetricsLogBaseTest, LoadEvent) { + std::string expected_output = +#if defined(OS_CHROMEOS) + "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " + "appversion=\"bogus version\" hardwareclass=\"sample-class\">\n" + " <document action=\"load\" docid=\"1\" window=\"3\" loadtime=\"7219\" " + "origin=\"link\" session=\"0\" time=\"\"/>\n" + "</log>"; +#else + "<log clientid=\"bogus client ID\" buildtime=\"123456789\" " + "appversion=\"bogus version\">\n" + " <document action=\"load\" docid=\"1\" window=\"3\" loadtime=\"7219\" " + "origin=\"link\" session=\"0\" time=\"\"/>\n" + "</log>"; +#endif // OS_CHROMEOS + + NoTimeMetricsLogBase log("bogus client ID", 0, "bogus version"); + log.RecordLoadEvent(3, GURL("http://google.com"), + content::PAGE_TRANSITION_LINK, 1, + TimeDelta::FromMilliseconds(7219)); + log.set_hardware_class("sample-class"); + log.CloseLog(); + + ASSERT_EQ(1, log.num_events()); + + int size = log.GetEncodedLogSizeXml(); + ASSERT_GT(size, 0); + + std::string encoded; + // Leave room for the NUL terminator. + ASSERT_TRUE(log.GetEncodedLogXml(WriteInto(&encoded, size + 1), size)); + TrimWhitespaceASCII(encoded, TRIM_ALL, &encoded); + NormalizeBuildtime(&encoded); + NormalizeBuildtime(&expected_output); + + ASSERT_EQ(expected_output, encoded); +} + +// Make sure our ID hashes are the same as what we see on the server side. +TEST(MetricsLogBaseTest, CreateHashes) { + static const struct { + std::string input; + std::string output; + } cases[] = { + {"Back", "0x0557fa923dcee4d0"}, + {"Forward", "0x67d2f6740a8eaebf"}, + {"NewTab", "0x290eb683f96572f1"}, + }; + + for (size_t i = 0; i < ARRAYSIZE_UNSAFE(cases); i++) { + std::string hash_string; + uint64 hash_numeric; + MetricsLogBase::CreateHashes(cases[i].input, &hash_string, &hash_numeric); + + // Verify the numeric representation. + { + std::string hash_numeric_hex = + base::StringPrintf("0x%016" PRIx64, hash_numeric); + EXPECT_EQ(cases[i].output, hash_numeric_hex); + } + + // Verify the string representation. + { + std::string hash_string_decoded; + ASSERT_TRUE(base::Base64Decode(hash_string, &hash_string_decoded)); + + // Convert to hex string + // We're only checking the first 8 bytes, because that's what + // the metrics server uses. + std::string hash_string_hex = "0x"; + ASSERT_GE(hash_string_decoded.size(), 8U); + for (size_t j = 0; j < 8; j++) { + base::StringAppendF(&hash_string_hex, "%02x", + static_cast<uint8>(hash_string_decoded.data()[j])); + } + EXPECT_EQ(cases[i].output, hash_string_hex); + } + } +}; diff --git a/chrome/common/metrics/metrics_log_manager.cc b/chrome/common/metrics/metrics_log_manager.cc index 32fe51c..a917bcf 100644 --- a/chrome/common/metrics/metrics_log_manager.cc +++ b/chrome/common/metrics/metrics_log_manager.cc @@ -14,10 +14,23 @@ #include "base/string_util.h" #include "chrome/common/metrics/metrics_log_base.h" +namespace { + +// Used to keep track of discarded protobuf logs without having to track xml and +// protobuf logs in separate lists. +const char kDiscardedLog[] = "Log discarded"; + +} // anonymous namespace + MetricsLogManager::MetricsLogManager() : max_ongoing_log_store_size_(0) {} MetricsLogManager::~MetricsLogManager() {} +bool MetricsLogManager::SerializedLog::empty() const { + DCHECK_EQ(xml.empty(), proto.empty()); + return xml.empty(); +} + void MetricsLogManager::BeginLoggingWithLog(MetricsLogBase* log) { DCHECK(!current_log_.get()); current_log_.reset(log); @@ -31,12 +44,21 @@ void MetricsLogManager::StageCurrentLogForUpload() { } bool MetricsLogManager::has_staged_log() const { - return staged_log_.get() || !compressed_staged_log_text_.empty(); + return staged_log_.get() || !staged_log_text().empty(); +} + +bool MetricsLogManager::has_staged_log_proto() const { + return has_staged_log() && staged_log_text().proto != kDiscardedLog; } void MetricsLogManager::DiscardStagedLog() { staged_log_.reset(); - compressed_staged_log_text_.clear(); + staged_log_text_.xml.clear(); + staged_log_text_.proto.clear(); +} + +void MetricsLogManager::DiscardStagedLogProto() { + staged_log_text_.proto = kDiscardedLog; } void MetricsLogManager::DiscardCurrentLog() { @@ -56,21 +78,26 @@ void MetricsLogManager::ResumePausedLog() { void MetricsLogManager::StoreStagedLogAsUnsent(LogType log_type) { DCHECK(has_staged_log()); + // If compressing the log failed, there's nothing to store. - if (compressed_staged_log_text_.empty()) + if (staged_log_text().empty()) return; if (log_type == INITIAL_LOG) { - unsent_initial_logs_.push_back(compressed_staged_log_text_); + unsent_initial_logs_.push_back(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_) { + staged_log_text().xml.length() > max_ongoing_log_store_size_) { + // TODO(isherman): We probably want a similar check for protobufs, but we + // don't want to prevent XML upload just because the protobuf version is + // too long. In practice, I'm pretty sure the XML version should always + // be longer, or at least on the same order of magnitude in length. UMA_HISTOGRAM_COUNTS( "UMA.Large Accumulated Log Not Persisted", - static_cast<int>(compressed_staged_log_text_.length())); + static_cast<int>(staged_log_text().xml.length())); } else { - unsent_ongoing_logs_.push_back(compressed_staged_log_text_); + unsent_ongoing_logs_.push_back(staged_log_text_); } } DiscardStagedLog(); @@ -78,11 +105,13 @@ void MetricsLogManager::StoreStagedLogAsUnsent(LogType log_type) { void MetricsLogManager::StageNextStoredLogForUpload() { // Prioritize initial logs for uploading. - std::vector<std::string>* source_list = unsent_initial_logs_.empty() ? - &unsent_ongoing_logs_ : &unsent_initial_logs_; + std::vector<SerializedLog>* 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(); + DCHECK(staged_log_text().empty()); + staged_log_text_ = source_list->back(); source_list->pop_back(); } @@ -103,16 +132,20 @@ void MetricsLogManager::LoadPersistedUnsentLogs() { } void MetricsLogManager::CompressStagedLog() { - int text_size = staged_log_->GetEncodedLogSize(); + int text_size = staged_log_->GetEncodedLogSizeXml(); std::string staged_log_text; DCHECK_GT(text_size, 0); - staged_log_->GetEncodedLog(WriteInto(&staged_log_text, text_size + 1), - text_size); + staged_log_->GetEncodedLogXml(WriteInto(&staged_log_text, text_size + 1), + text_size); - bool success = Bzip2Compress(staged_log_text, &compressed_staged_log_text_); + bool success = Bzip2Compress(staged_log_text, &staged_log_text_.xml); if (success) { // Allow security-conscious users to see all metrics logs that we send. DVLOG(1) << "METRICS LOG: " << staged_log_text; + + // Note that we only save the protobuf version if we succeeded in + // compressing the XML, so that the two data streams are the same. + staged_log_->GetEncodedLogProto(&staged_log_text_.proto); } else { NOTREACHED() << "Failed to compress log for transmission."; } diff --git a/chrome/common/metrics/metrics_log_manager.h b/chrome/common/metrics/metrics_log_manager.h index 3eb04f0..9ae20ad 100644 --- a/chrome/common/metrics/metrics_log_manager.h +++ b/chrome/common/metrics/metrics_log_manager.h @@ -22,6 +22,17 @@ class MetricsLogManager { MetricsLogManager(); ~MetricsLogManager(); + // Stores both XML and protocol buffer serializations for a log. + struct SerializedLog { + public: + // Exposed to reduce code churn as we transition from the XML pipeline to + // the protocol buffer pipeline. + bool empty() const; + + std::string xml; + std::string proto; + }; + // 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); @@ -36,13 +47,25 @@ class MetricsLogManager { // 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_; } + // Returns true if there is a protobuf log that needs to be uploaded. + // In the case that an XML upload needs to be re-issued due to a previous + // failure, |has_staged_log()| will return true while this returns false. + bool has_staged_log_proto() const; - // Discards the staged log. + // The text of the staged log, in compressed XML or protobuf format. Empty if + // there is no staged log, or if compression of the staged log failed. + const SerializedLog& staged_log_text() const { + return staged_log_text_; + } + + // Discards the staged log (both the XML and the protobuf data). void DiscardStagedLog(); + // Discards the protobuf data in the staged log. + // This is useful to prevent needlessly re-issuing successful protobuf uploads + // due to XML upload failures. + void DiscardStagedLogProto(); + // Closes and discards |current_log|. void DiscardCurrentLog(); @@ -91,13 +114,13 @@ class MetricsLogManager { // Serializes |logs| to persistent storage, replacing any previously // serialized logs of the same type. - virtual void SerializeLogs(const std::vector<std::string>& logs, + virtual void SerializeLogs(const std::vector<SerializedLog>& 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; + std::vector<SerializedLog>* logs) = 0; }; // Sets the serializer to use for persisting and loading logs; takes ownership @@ -115,8 +138,8 @@ class MetricsLogManager { void LoadPersistedUnsentLogs(); private: - // Compresses staged_log_ and stores the result in - // compressed_staged_log_text_. + // Compresses |staged_log_| and stores the result in + // |compressed_staged_xml_log_text_|. void CompressStagedLog(); // Compresses the text in |input| using bzip2, store the result in |output|. @@ -130,21 +153,25 @@ class MetricsLogManager { // 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. + // |compressed_staged_xml_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_; + // The text representations of the staged log, ready for upload to the server. + // The first item in the pair is the compressed XML representation; the second + // is the protobuf representation. + SerializedLog staged_log_text_; // Logs from a previous session that have not yet been sent. + // The first item in each pair is the XML representation; the second item is + // the protobuf representation. // 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_; + std::vector<SerializedLog> unsent_initial_logs_; + std::vector<SerializedLog> unsent_ongoing_logs_; size_t max_ongoing_log_store_size_; diff --git a/chrome/common/metrics/metrics_log_manager_unittest.cc b/chrome/common/metrics/metrics_log_manager_unittest.cc index 0373186..43b2071 100644 --- a/chrome/common/metrics/metrics_log_manager_unittest.cc +++ b/chrome/common/metrics/metrics_log_manager_unittest.cc @@ -2,27 +2,31 @@ // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. +#include <string> +#include <utility> +#include <vector> + #include "chrome/common/metrics/metrics_log_base.h" #include "chrome/common/metrics/metrics_log_manager.h" #include "testing/gtest/include/gtest/gtest.h" -#include <string> -#include <vector> +typedef MetricsLogManager::SerializedLog SerializedLog; 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, + virtual void SerializeLogs(const std::vector<SerializedLog>& logs, MetricsLogManager::LogType log_type) { persisted_logs_[log_type] = logs; } virtual void DeserializeLogs(MetricsLogManager::LogType log_type, - std::vector<std::string>* logs) { + std::vector<SerializedLog>* logs) { ASSERT_NE(static_cast<void*>(NULL), logs); *logs = persisted_logs_[log_type]; } @@ -33,9 +37,10 @@ class DummyLogSerializer : public MetricsLogManager::LogSerializer { } // In-memory "persitent storage". - std::vector<std::string> persisted_logs_[2]; + std::vector<SerializedLog> persisted_logs_[2]; }; -}; // namespace + +} // namespace TEST(MetricsLogManagerTest, StandardFlow) { MetricsLogManager log_manager; @@ -109,8 +114,8 @@ TEST(MetricsLogManagerTest, InterjectedLog) { } TEST(MetricsLogManagerTest, StoreAndLoad) { - std::vector<std::string> initial_logs; - std::vector<std::string> ongoing_logs; + std::vector<SerializedLog> initial_logs; + std::vector<SerializedLog> 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. @@ -119,7 +124,8 @@ TEST(MetricsLogManagerTest, StoreAndLoad) { 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"); + SerializedLog log = {"xml", "proto"}; + serializer->persisted_logs_[MetricsLogManager::ONGOING_LOG].push_back(log); EXPECT_FALSE(log_manager.has_unsent_logs()); log_manager.LoadPersistedUnsentLogs(); EXPECT_TRUE(log_manager.has_unsent_logs()); diff --git a/chrome/common/pref_names.cc b/chrome/common/pref_names.cc index 653039b..fb81da4 100644 --- a/chrome/common/pref_names.cc +++ b/chrome/common/pref_names.cc @@ -984,16 +984,20 @@ const char kMetricsReportingEnabled[] = // Array of strings that are each UMA logs that were supposed to be sent in the // first minute of a browser session. These logs include things like crash count -// info, etc. -const char kMetricsInitialLogs[] = +// info, etc. Currently we store both XML and protobuf versions of these logs. +const char kMetricsInitialLogsXml[] = "user_experience_metrics.initial_logs"; +const char kMetricsInitialLogsProto[] = + "user_experience_metrics.initial_logs_as_protobufs"; // Array of strings that are each UMA logs that were not sent because the // browser terminated before these accumulated metrics could be sent. These // logs typically include histograms and memory reports, as well as ongoing -// user activities. -const char kMetricsOngoingLogs[] = +// user activities. Currently we store both XML and protobuf versions. +const char kMetricsOngoingLogsXml[] = "user_experience_metrics.ongoing_logs"; +const char kMetricsOngoingLogsProto[] = + "user_experience_metrics.ongoing_logs_as_protobufs"; // Where profile specific metrics are placed. const char kProfileMetrics[] = "user_experience_metrics.profiles"; diff --git a/chrome/common/pref_names.h b/chrome/common/pref_names.h index 14c6565..248a4b2 100644 --- a/chrome/common/pref_names.h +++ b/chrome/common/pref_names.h @@ -351,8 +351,10 @@ extern const char kMetricsClientID[]; extern const char kMetricsSessionID[]; extern const char kMetricsClientIDTimestamp[]; extern const char kMetricsReportingEnabled[]; -extern const char kMetricsInitialLogs[]; -extern const char kMetricsOngoingLogs[]; +extern const char kMetricsInitialLogsXml[]; +extern const char kMetricsInitialLogsProto[]; +extern const char kMetricsOngoingLogsXml[]; +extern const char kMetricsOngoingLogsProto[]; extern const char kProfileLastUsed[]; extern const char kProfilesLastActive[]; diff --git a/chrome_frame/metrics_service.cc b/chrome_frame/metrics_service.cc index 01e3c50..622a892 100644 --- a/chrome_frame/metrics_service.cc +++ b/chrome_frame/metrics_service.cc @@ -419,6 +419,8 @@ bool MetricsService::TransmissionPermitted() const { return user_permits_upload_; } +// TODO(isherman): Update this to log to the protobuf server as well... +// http://crbug.com/109817 bool MetricsService::UploadData() { DCHECK_EQ(thread_, base::PlatformThread::CurrentId()); @@ -441,7 +443,7 @@ bool MetricsService::UploadData() { ret = false; } else { HRESULT hr = ChromeFrameMetricsDataUploader::UploadDataHelper( - log_manager_.staged_log_text()); + log_manager_.staged_log_text().xml); DCHECK(SUCCEEDED(hr)); } log_manager_.DiscardStagedLog(); |