OLD | NEW |
1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. | 1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. |
2 // Use of this source code is governed by a BSD-style license that can be | 2 // Use of this source code is governed by a BSD-style license that can be |
3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
4 | 4 |
5 //------------------------------------------------------------------------------ | 5 //------------------------------------------------------------------------------ |
6 // Description of the life cycle of a instance of MetricsService. | 6 // Description of the life cycle of a instance of MetricsService. |
7 // | 7 // |
8 // OVERVIEW | 8 // OVERVIEW |
9 // | 9 // |
10 // A MetricsService instance is typically created at application startup. It | 10 // A MetricsService instance is typically created at application startup. It is |
11 // is the central controller for the acquisition of log data, and the automatic | 11 // the central controller for the acquisition of log data, and the automatic |
12 // transmission of that log data to an external server. Its major job is to | 12 // transmission of that log data to an external server. Its major job is to |
13 // manage logs, grouping them for transmission, and transmitting them. As part | 13 // manage logs, grouping them for transmission, and transmitting them. As part |
14 // of its grouping, MS finalizes logs by including some just-in-time gathered | 14 // of its grouping, MS finalizes logs by including some just-in-time gathered |
15 // memory statistics, snapshotting the current stats of numerous histograms, | 15 // memory statistics, snapshotting the current stats of numerous histograms, |
16 // closing the logs, translating to XML text, and compressing the results for | 16 // closing the logs, translating to protocol buffer format, and compressing the |
17 // transmission. Transmission includes submitting a compressed log as data in a | 17 // results for transmission. Transmission includes submitting a compressed log |
18 // URL-post, and retransmitting (or retaining at process termination) if the | 18 // as data in a URL-post, and retransmitting (or retaining at process |
19 // attempted transmission failed. Retention across process terminations is done | 19 // termination) if the attempted transmission failed. Retention across process |
20 // using the the PrefServices facilities. The retained logs (the ones that never | 20 // terminations is done using the the PrefServices facilities. The retained logs |
21 // got transmitted) are compressed and base64-encoded before being persisted. | 21 // (the ones that never got transmitted) are compressed and base64-encoded |
| 22 // before being persisted. |
22 // | 23 // |
23 // Logs fall into one of two categories: "initial logs," and "ongoing logs." | 24 // Logs fall into one of two categories: "initial logs," and "ongoing logs." |
24 // There is at most one initial log sent for each complete run of the chromium | 25 // There is at most one initial log sent for each complete run of the chromium |
25 // product (from startup, to browser shutdown). An initial log is generally | 26 // product (from startup, to browser shutdown). An initial log is generally |
26 // transmitted some short time (1 minute?) after startup, and includes stats | 27 // transmitted some short time (1 minute?) after startup, and includes stats |
27 // such as recent crash info, the number and types of plugins, etc. The | 28 // such as recent crash info, the number and types of plugins, etc. The |
28 // external server's response to the initial log conceptually tells this MS if | 29 // external server's response to the initial log conceptually tells this MS if |
29 // it should continue transmitting logs (during this session). The server | 30 // it should continue transmitting logs (during this session). The server |
30 // response can actually be much more detailed, and always includes (at a | 31 // response can actually be much more detailed, and always includes (at a |
31 // minimum) how often additional ongoing logs should be sent. | 32 // minimum) how often additional ongoing logs should be sent. |
(...skipping 775 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
807 //------------------------------------------------------------------------------ | 808 //------------------------------------------------------------------------------ |
808 // private methods | 809 // private methods |
809 //------------------------------------------------------------------------------ | 810 //------------------------------------------------------------------------------ |
810 | 811 |
811 | 812 |
812 //------------------------------------------------------------------------------ | 813 //------------------------------------------------------------------------------ |
813 // Initialization methods | 814 // Initialization methods |
814 | 815 |
815 void MetricsService::InitializeMetricsState() { | 816 void MetricsService::InitializeMetricsState() { |
816 #if defined(OS_POSIX) | 817 #if defined(OS_POSIX) |
817 server_url_xml_ = ASCIIToUTF16(kServerUrlXml); | |
818 server_url_proto_ = ASCIIToUTF16(kServerUrlProto); | |
819 network_stats_server_ = chrome_common_net::kEchoTestServerLocation; | 818 network_stats_server_ = chrome_common_net::kEchoTestServerLocation; |
820 http_pipelining_test_server_ = chrome_common_net::kPipelineTestServerBaseUrl; | 819 http_pipelining_test_server_ = chrome_common_net::kPipelineTestServerBaseUrl; |
821 #else | 820 #else |
822 BrowserDistribution* dist = BrowserDistribution::GetDistribution(); | 821 BrowserDistribution* dist = BrowserDistribution::GetDistribution(); |
823 server_url_xml_ = dist->GetStatsServerURL(); | |
824 server_url_proto_ = ASCIIToUTF16(kServerUrlProto); | |
825 network_stats_server_ = dist->GetNetworkStatsServer(); | 822 network_stats_server_ = dist->GetNetworkStatsServer(); |
826 http_pipelining_test_server_ = dist->GetHttpPipeliningTestServer(); | 823 http_pipelining_test_server_ = dist->GetHttpPipeliningTestServer(); |
827 #endif | 824 #endif |
828 | 825 |
829 PrefService* pref = g_browser_process->local_state(); | 826 PrefService* pref = g_browser_process->local_state(); |
830 DCHECK(pref); | 827 DCHECK(pref); |
831 | 828 |
832 if ((pref->GetInt64(prefs::kStabilityStatsBuildTime) | 829 if ((pref->GetInt64(prefs::kStabilityStatsBuildTime) |
833 != MetricsLog::GetBuildTime()) || | 830 != MetricsLog::GetBuildTime()) || |
834 (pref->GetString(prefs::kStabilityStatsVersion) | 831 (pref->GetString(prefs::kStabilityStatsVersion) |
(...skipping 313 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
1148 log_manager_.FinishCurrentLog(); | 1145 log_manager_.FinishCurrentLog(); |
1149 } | 1146 } |
1150 | 1147 |
1151 void MetricsService::PushPendingLogsToPersistentStorage() { | 1148 void MetricsService::PushPendingLogsToPersistentStorage() { |
1152 if (state_ < INITIAL_LOG_READY) | 1149 if (state_ < INITIAL_LOG_READY) |
1153 return; // We didn't and still don't have time to get plugin list etc. | 1150 return; // We didn't and still don't have time to get plugin list etc. |
1154 | 1151 |
1155 if (log_manager_.has_staged_log()) { | 1152 if (log_manager_.has_staged_log()) { |
1156 // We may race here, and send second copy of the log later. | 1153 // We may race here, and send second copy of the log later. |
1157 MetricsLogManager::StoreType store_type; | 1154 MetricsLogManager::StoreType store_type; |
1158 if (current_fetch_xml_.get() || current_fetch_proto_.get()) | 1155 if (current_fetch_.get()) |
1159 store_type = MetricsLogManager::PROVISIONAL_STORE; | 1156 store_type = MetricsLogManager::PROVISIONAL_STORE; |
1160 else | 1157 else |
1161 store_type = MetricsLogManager::NORMAL_STORE; | 1158 store_type = MetricsLogManager::NORMAL_STORE; |
1162 log_manager_.StoreStagedLogAsUnsent(store_type); | 1159 log_manager_.StoreStagedLogAsUnsent(store_type); |
1163 } | 1160 } |
1164 DCHECK(!log_manager_.has_staged_log()); | 1161 DCHECK(!log_manager_.has_staged_log()); |
1165 CloseCurrentLog(); | 1162 CloseCurrentLog(); |
1166 StoreUnsentLogs(); | 1163 StoreUnsentLogs(); |
1167 | 1164 |
1168 // If there was a staged and/or current log, then there is now at least one | 1165 // If there was a staged and/or current log, then there is now at least one |
(...skipping 108 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
1277 DCHECK(waiting_for_asynchronous_reporting_step_); | 1274 DCHECK(waiting_for_asynchronous_reporting_step_); |
1278 | 1275 |
1279 waiting_for_asynchronous_reporting_step_ = false; | 1276 waiting_for_asynchronous_reporting_step_ = false; |
1280 OnFinalLogInfoCollectionDone(); | 1277 OnFinalLogInfoCollectionDone(); |
1281 } | 1278 } |
1282 | 1279 |
1283 void MetricsService::OnFinalLogInfoCollectionDone() { | 1280 void MetricsService::OnFinalLogInfoCollectionDone() { |
1284 // If somehow there is a fetch in progress, we return and hope things work | 1281 // If somehow there is a fetch in progress, we return and hope things work |
1285 // out. The scheduler isn't informed since if this happens, the scheduler | 1282 // out. The scheduler isn't informed since if this happens, the scheduler |
1286 // will get a response from the upload. | 1283 // will get a response from the upload. |
1287 DCHECK(!current_fetch_xml_.get()); | 1284 DCHECK(!current_fetch_.get()); |
1288 DCHECK(!current_fetch_proto_.get()); | 1285 if (current_fetch_.get()) |
1289 if (current_fetch_xml_.get() || current_fetch_proto_.get()) | |
1290 return; | 1286 return; |
1291 | 1287 |
1292 // Abort if metrics were turned off during the final info gathering. | 1288 // Abort if metrics were turned off during the final info gathering. |
1293 if (!recording_active()) { | 1289 if (!recording_active()) { |
1294 scheduler_->Stop(); | 1290 scheduler_->Stop(); |
1295 scheduler_->UploadCancelled(); | 1291 scheduler_->UploadCancelled(); |
1296 return; | 1292 return; |
1297 } | 1293 } |
1298 | 1294 |
1299 StageNewLog(); | 1295 StageNewLog(); |
(...skipping 74 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
1374 return; // We never Recalled the prior unsent logs. | 1370 return; // We never Recalled the prior unsent logs. |
1375 | 1371 |
1376 log_manager_.PersistUnsentLogs(); | 1372 log_manager_.PersistUnsentLogs(); |
1377 } | 1373 } |
1378 | 1374 |
1379 void MetricsService::SendStagedLog() { | 1375 void MetricsService::SendStagedLog() { |
1380 DCHECK(log_manager_.has_staged_log()); | 1376 DCHECK(log_manager_.has_staged_log()); |
1381 | 1377 |
1382 PrepareFetchWithStagedLog(); | 1378 PrepareFetchWithStagedLog(); |
1383 | 1379 |
1384 bool upload_created = current_fetch_xml_.get() || current_fetch_proto_.get(); | 1380 bool upload_created = (current_fetch_.get() != NULL); |
1385 UMA_HISTOGRAM_BOOLEAN("UMA.UploadCreation", upload_created); | 1381 UMA_HISTOGRAM_BOOLEAN("UMA.UploadCreation", upload_created); |
1386 if (!upload_created) { | 1382 if (!upload_created) { |
1387 // Compression failed, and log discarded :-/. | 1383 // Compression failed, and log discarded :-/. |
1388 // Skip this upload and hope things work out next time. | 1384 // Skip this upload and hope things work out next time. |
1389 log_manager_.DiscardStagedLog(); | 1385 log_manager_.DiscardStagedLog(); |
1390 scheduler_->UploadCancelled(); | 1386 scheduler_->UploadCancelled(); |
1391 return; | 1387 return; |
1392 } | 1388 } |
1393 | 1389 |
1394 DCHECK(!waiting_for_asynchronous_reporting_step_); | 1390 DCHECK(!waiting_for_asynchronous_reporting_step_); |
1395 waiting_for_asynchronous_reporting_step_ = true; | 1391 waiting_for_asynchronous_reporting_step_ = true; |
1396 | 1392 |
1397 if (current_fetch_xml_.get()) | 1393 current_fetch_->Start(); |
1398 current_fetch_xml_->Start(); | |
1399 if (current_fetch_proto_.get()) | |
1400 current_fetch_proto_->Start(); | |
1401 | 1394 |
1402 HandleIdleSinceLastTransmission(true); | 1395 HandleIdleSinceLastTransmission(true); |
1403 } | 1396 } |
1404 | 1397 |
1405 void MetricsService::PrepareFetchWithStagedLog() { | 1398 void MetricsService::PrepareFetchWithStagedLog() { |
1406 DCHECK(log_manager_.has_staged_log()); | 1399 DCHECK(log_manager_.has_staged_log()); |
1407 | 1400 |
1408 // Prepare the XML version. | 1401 // Prepare the protobuf version. |
1409 DCHECK(!current_fetch_xml_.get()); | 1402 DCHECK(!current_fetch_.get()); |
1410 if (log_manager_.has_staged_log_xml()) { | 1403 if (log_manager_.has_staged_log_proto()) { |
1411 current_fetch_xml_.reset(net::URLFetcher::Create( | 1404 current_fetch_.reset(net::URLFetcher::Create( |
1412 GURL(server_url_xml_), net::URLFetcher::POST, this)); | 1405 GURL(kServerUrlProto), net::URLFetcher::POST, this)); |
1413 current_fetch_xml_->SetRequestContext( | 1406 current_fetch_->SetRequestContext( |
1414 g_browser_process->system_request_context()); | 1407 g_browser_process->system_request_context()); |
1415 current_fetch_xml_->SetUploadData(kMimeTypeXml, | 1408 current_fetch_->SetUploadData(kMimeTypeProto, |
1416 log_manager_.staged_log_text().xml); | 1409 log_manager_.staged_log_text().proto); |
1417 // We already drop cookies server-side, but we might as well strip them out | 1410 // We already drop cookies server-side, but we might as well strip them out |
1418 // client-side as well. | 1411 // client-side as well. |
1419 current_fetch_xml_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES | | 1412 current_fetch_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES | |
1420 net::LOAD_DO_NOT_SEND_COOKIES); | 1413 net::LOAD_DO_NOT_SEND_COOKIES); |
1421 } | |
1422 | |
1423 // Prepare the protobuf version. | |
1424 DCHECK(!current_fetch_proto_.get()); | |
1425 if (log_manager_.has_staged_log_proto()) { | |
1426 current_fetch_proto_.reset(net::URLFetcher::Create( | |
1427 GURL(server_url_proto_), net::URLFetcher::POST, this)); | |
1428 current_fetch_proto_->SetRequestContext( | |
1429 g_browser_process->system_request_context()); | |
1430 current_fetch_proto_->SetUploadData(kMimeTypeProto, | |
1431 log_manager_.staged_log_text().proto); | |
1432 // We already drop cookies server-side, but we might as well strip them out | |
1433 // client-side as well. | |
1434 current_fetch_proto_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES | | |
1435 net::LOAD_DO_NOT_SEND_COOKIES); | |
1436 } | 1414 } |
1437 } | 1415 } |
1438 | 1416 |
1439 // We need to wait for two responses: the response to the XML upload, and the | |
1440 // response to the protobuf upload. In the case that exactly one of the uploads | |
1441 // fails and needs to be retried, we "zap" the other pipeline's staged log to | |
1442 // avoid incorrectly re-uploading it as well. | |
1443 void MetricsService::OnURLFetchComplete(const net::URLFetcher* source) { | 1417 void MetricsService::OnURLFetchComplete(const net::URLFetcher* source) { |
1444 DCHECK(waiting_for_asynchronous_reporting_step_); | 1418 DCHECK(waiting_for_asynchronous_reporting_step_); |
1445 | 1419 |
1446 // We're not allowed to re-use the existing |URLFetcher|s, so free them here. | 1420 // We're not allowed to re-use the existing |URLFetcher|s, so free them here. |
1447 // Note however that |source| is aliased to one of these, so we should be | 1421 // Note however that |source| is aliased to the fetcher, so we should be |
1448 // careful not to delete it too early. | 1422 // careful not to delete it too early. |
1449 scoped_ptr<net::URLFetcher> s; | 1423 DCHECK_EQ(current_fetch_.get(), source); |
1450 bool is_xml; | 1424 scoped_ptr<net::URLFetcher> s(current_fetch_.Pass()); |
1451 if (source == current_fetch_xml_.get()) { | |
1452 s.reset(current_fetch_xml_.release()); | |
1453 is_xml = true; | |
1454 } else if (source == current_fetch_proto_.get()) { | |
1455 s.reset(current_fetch_proto_.release()); | |
1456 is_xml = false; | |
1457 } else { | |
1458 NOTREACHED(); | |
1459 return; | |
1460 } | |
1461 | 1425 |
1462 int response_code = source->GetResponseCode(); | 1426 int response_code = source->GetResponseCode(); |
1463 | 1427 |
1464 // Log a histogram to track response success vs. failure rates. | 1428 // Log a histogram to track response success vs. failure rates. |
1465 if (is_xml) { | 1429 UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.Protobuf", |
1466 UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.XML", | 1430 ResponseCodeToStatus(response_code), |
1467 ResponseCodeToStatus(response_code), | 1431 NUM_RESPONSE_STATUSES); |
1468 NUM_RESPONSE_STATUSES); | |
1469 } else { | |
1470 UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.Protobuf", | |
1471 ResponseCodeToStatus(response_code), | |
1472 NUM_RESPONSE_STATUSES); | |
1473 } | |
1474 | 1432 |
1475 // If the upload was provisionally stored, drop it now that the upload is | 1433 // If the upload was provisionally stored, drop it now that the upload is |
1476 // known to have gone through. | 1434 // known to have gone through. |
1477 log_manager_.DiscardLastProvisionalStore(); | 1435 log_manager_.DiscardLastProvisionalStore(); |
1478 | 1436 |
1479 bool upload_succeeded = response_code == 200; | 1437 bool upload_succeeded = response_code == 200; |
1480 | 1438 |
1481 // Provide boolean for error recovery (allow us to ignore response_code). | 1439 // Provide boolean for error recovery (allow us to ignore response_code). |
1482 bool discard_log = false; | 1440 bool discard_log = false; |
1483 const size_t log_size = is_xml ? | 1441 const size_t log_size = log_manager_.staged_log_text().proto.length(); |
1484 log_manager_.staged_log_text().xml.length() : | |
1485 log_manager_.staged_log_text().proto.length(); | |
1486 if (!upload_succeeded && log_size > kUploadLogAvoidRetransmitSize) { | 1442 if (!upload_succeeded && log_size > kUploadLogAvoidRetransmitSize) { |
1487 UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded", | 1443 UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded", |
1488 static_cast<int>(log_size)); | 1444 static_cast<int>(log_size)); |
1489 discard_log = true; | 1445 discard_log = true; |
1490 } else if (response_code == 400) { | 1446 } else if (response_code == 400) { |
1491 // Bad syntax. Retransmission won't work. | 1447 // Bad syntax. Retransmission won't work. |
1492 discard_log = true; | 1448 discard_log = true; |
1493 } | 1449 } |
1494 | 1450 |
1495 if (upload_succeeded || discard_log) { | 1451 if (upload_succeeded || discard_log) |
1496 if (is_xml) | 1452 log_manager_.DiscardStagedLogProto(); |
1497 log_manager_.DiscardStagedLogXml(); | |
1498 else | |
1499 log_manager_.DiscardStagedLogProto(); | |
1500 } | |
1501 | |
1502 // If we're still waiting for one of the responses, keep waiting... | |
1503 if (current_fetch_xml_.get() || current_fetch_proto_.get()) | |
1504 return; | |
1505 | 1453 |
1506 waiting_for_asynchronous_reporting_step_ = false; | 1454 waiting_for_asynchronous_reporting_step_ = false; |
1507 | 1455 |
1508 if (!log_manager_.has_staged_log()) { | 1456 if (!log_manager_.has_staged_log()) { |
1509 switch (state_) { | 1457 switch (state_) { |
1510 case INITIAL_LOG_READY: | 1458 case INITIAL_LOG_READY: |
1511 state_ = log_manager_.has_unsent_logs() ? SENDING_OLD_LOGS | 1459 state_ = log_manager_.has_unsent_logs() ? SENDING_OLD_LOGS |
1512 : SENDING_CURRENT_LOGS; | 1460 : SENDING_CURRENT_LOGS; |
1513 break; | 1461 break; |
1514 | 1462 |
(...skipping 12 matching lines...) Expand all Loading... |
1527 break; | 1475 break; |
1528 } | 1476 } |
1529 | 1477 |
1530 if (log_manager_.has_unsent_logs()) | 1478 if (log_manager_.has_unsent_logs()) |
1531 DCHECK_LT(state_, SENDING_CURRENT_LOGS); | 1479 DCHECK_LT(state_, SENDING_CURRENT_LOGS); |
1532 } | 1480 } |
1533 | 1481 |
1534 // Error 400 indicates a problem with the log, not with the server, so | 1482 // Error 400 indicates a problem with the log, not with the server, so |
1535 // don't consider that a sign that the server is in trouble. | 1483 // don't consider that a sign that the server is in trouble. |
1536 bool server_is_healthy = upload_succeeded || response_code == 400; | 1484 bool server_is_healthy = upload_succeeded || response_code == 400; |
1537 | |
1538 // Note that we are essentially randomly choosing to report either the XML or | |
1539 // the protobuf server's health status, but this is ok: In the case that the | |
1540 // two statuses are not the same, one of the uploads succeeded but the other | |
1541 // did not. In this case, we'll re-try only the upload that failed. This first | |
1542 // re-try might ignore the server's unhealthiness; but the response to the | |
1543 // re-tried upload will correctly propagate the server's health status for any | |
1544 // subsequent re-tries. Hence, we'll at most delay slowing the upload rate by | |
1545 // one re-try, which is fine. | |
1546 scheduler_->UploadFinished(server_is_healthy, log_manager_.has_unsent_logs()); | 1485 scheduler_->UploadFinished(server_is_healthy, log_manager_.has_unsent_logs()); |
1547 | 1486 |
1548 // Collect network stats if UMA upload succeeded. | 1487 // Collect network stats if UMA upload succeeded. |
1549 IOThread* io_thread = g_browser_process->io_thread(); | 1488 IOThread* io_thread = g_browser_process->io_thread(); |
1550 if (server_is_healthy && io_thread) { | 1489 if (server_is_healthy && io_thread) { |
1551 chrome_browser_net::CollectNetworkStats(network_stats_server_, io_thread); | 1490 chrome_browser_net::CollectNetworkStats(network_stats_server_, io_thread); |
1552 chrome_browser_net::CollectPipeliningCapabilityStatsOnUIThread( | 1491 chrome_browser_net::CollectPipeliningCapabilityStatsOnUIThread( |
1553 http_pipelining_test_server_, io_thread); | 1492 http_pipelining_test_server_, io_thread); |
1554 } | 1493 } |
1555 } | 1494 } |
(...skipping 314 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
1870 if (local_state) { | 1809 if (local_state) { |
1871 const PrefService::Preference* uma_pref = | 1810 const PrefService::Preference* uma_pref = |
1872 local_state->FindPreference(prefs::kMetricsReportingEnabled); | 1811 local_state->FindPreference(prefs::kMetricsReportingEnabled); |
1873 if (uma_pref) { | 1812 if (uma_pref) { |
1874 bool success = uma_pref->GetValue()->GetAsBoolean(&result); | 1813 bool success = uma_pref->GetValue()->GetAsBoolean(&result); |
1875 DCHECK(success); | 1814 DCHECK(success); |
1876 } | 1815 } |
1877 } | 1816 } |
1878 return result; | 1817 return result; |
1879 } | 1818 } |
OLD | NEW |