123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427 |
- // Copyright 2014 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 "chromeos/metrics/login_event_recorder.h"
- #include <vector>
- #include "base/command_line.h"
- #include "base/files/file_path.h"
- #include "base/files/file_util.h"
- #include "base/json/json_reader.h"
- #include "base/json/json_writer.h"
- #include "base/lazy_instance.h"
- #include "base/logging.h"
- #include "base/metrics/histogram_macros.h"
- #include "base/strings/string_number_conversions.h"
- #include "base/strings/stringprintf.h"
- #include "base/system/sys_info.h"
- #include "base/task/current_thread.h"
- #include "base/task/sequenced_task_runner.h"
- #include "base/task/thread_pool.h"
- #include "base/threading/thread.h"
- #include "base/threading/thread_restrictions.h"
- #include "base/threading/thread_task_runner_handle.h"
- #include "base/time/time.h"
- #include "base/trace_event/trace_event.h"
- #include "base/values.h"
- namespace chromeos {
- namespace {
- constexpr char kUptime[] = "uptime";
- constexpr char kDisk[] = "disk";
- // The pointer to this object is used as a perfetto async event id.
- constexpr char kBootTimes[] = "BootTimes";
- #define FPL(value) FILE_PATH_LITERAL(value)
- // Dir uptime & disk logs are located in.
- constexpr const base::FilePath::CharType kLogPath[] = FPL("/tmp");
- // Dir log{in,out} logs are located in.
- constexpr base::FilePath::CharType kLoginLogPath[] = FPL("/home/chronos/user");
- // Prefix for the time measurement files.
- constexpr base::FilePath::CharType kUptimePrefix[] = FPL("uptime-");
- // Prefix for the disk usage files.
- constexpr base::FilePath::CharType kDiskPrefix[] = FPL("disk-");
- // Prefix and suffix for the "stats saved" flags file.
- constexpr base::FilePath::CharType kStatsPrefix[] = FPL("stats-");
- constexpr base::FilePath::CharType kWrittenSuffix[] = FPL(".written");
- // Names of login stats files.
- constexpr base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
- // The login times will be written immediately when the login animation ends,
- // and this is used to ensure the data is always written if this amount is
- // elapsed after login.
- constexpr int64_t kLoginTimeWriteDelayMs = 20000;
- // Appends the given buffer into the file. Returns the number of bytes
- // written, or -1 on error.<
- // TODO(satorux): Move this to file_util.
- int AppendFile(const base::FilePath& file_path, const char* data, int size) {
- // Appending boot times to (probably) a symlink in /tmp is a security risk for
- // developers with chromeos=1 builds.
- if (!base::SysInfo::IsRunningOnChromeOS())
- return -1;
- FILE* file = base::OpenFile(file_path, "a");
- if (!file)
- return -1;
- const int num_bytes_written = fwrite(data, 1, size, file);
- base::CloseFile(file);
- return num_bytes_written;
- }
- void WriteTimes(const std::string base_name,
- const std::string uma_name,
- const std::string uma_prefix,
- std::vector<LoginEventRecorder::TimeMarker> times) {
- DCHECK(times.size());
- const int kMinTimeMillis = 1;
- const int kMaxTimeMillis = 30000;
- const int kNumBuckets = 100;
- const base::FilePath log_path(kLoginLogPath);
- // Need to sort by time since the entries may have been pushed onto the
- // vector (on the UI thread) in a different order from which they were
- // created (potentially on other threads).
- std::sort(times.begin(), times.end());
- base::Time first = times.front().time();
- base::Time last = times.back().time();
- base::TimeDelta total = last - first;
- base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
- uma_name, base::Milliseconds(kMinTimeMillis),
- base::Milliseconds(kMaxTimeMillis), kNumBuckets,
- base::HistogramBase::kUmaTargetedHistogramFlag);
- total_hist->AddTime(total);
- std::string output =
- base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
- base::Time prev = first;
- // Convert base::Time to base::TimeTicks for tracing.
- auto time2timeticks = [](const base::Time& ts) {
- return base::TimeTicks::Now() - (base::Time::Now() - ts);
- };
- // Send first event to name the track:
- // "In Chrome, we usually don't bother setting explicit track names. If none
- // is provided, the track is named after the first event on the track."
- TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
- "startup", kBootTimes, TRACE_ID_LOCAL(kBootTimes), time2timeticks(prev));
- for (unsigned int i = 0; i < times.size(); ++i) {
- const LoginEventRecorder::TimeMarker& tm = times[i];
- if (tm.url().has_value()) {
- TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1(
- "startup", tm.name(), TRACE_ID_LOCAL(kBootTimes),
- time2timeticks(prev), "url", *tm.url());
- TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP1(
- "startup", tm.name(), TRACE_ID_LOCAL(kBootTimes),
- time2timeticks(tm.time()), "url", *tm.url());
- } else {
- TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
- "startup", tm.name(), TRACE_ID_LOCAL(kBootTimes),
- time2timeticks(prev));
- TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0("startup", tm.name(),
- TRACE_ID_LOCAL(kBootTimes),
- time2timeticks(tm.time()));
- }
- base::TimeDelta since_first = tm.time() - first;
- base::TimeDelta since_prev = tm.time() - prev;
- std::string name;
- if (tm.send_to_uma()) {
- name = uma_prefix + tm.name();
- base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
- name, base::Milliseconds(kMinTimeMillis),
- base::Milliseconds(kMaxTimeMillis), kNumBuckets,
- base::HistogramBase::kUmaTargetedHistogramFlag);
- prev_hist->AddTime(since_prev);
- } else {
- name = tm.name();
- }
- if (tm.write_to_file()) {
- output += base::StringPrintf("\n%.2f +%.4f %s", since_first.InSecondsF(),
- since_prev.InSecondsF(), name.data());
- if (tm.url().has_value()) {
- output += ": ";
- output += *tm.url();
- }
- }
- prev = tm.time();
- }
- output += '\n';
- TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
- "startup", kBootTimes, TRACE_ID_LOCAL(kBootTimes), time2timeticks(prev));
- base::WriteFile(log_path.Append(base_name), output.data(), output.size());
- }
- } // namespace
- LoginEventRecorder::TimeMarker::TimeMarker(const char* name,
- absl::optional<std::string> url,
- bool send_to_uma,
- bool write_to_file)
- : name_(name),
- url_(url),
- send_to_uma_(send_to_uma),
- write_to_file_(write_to_file) {}
- LoginEventRecorder::TimeMarker::TimeMarker(const TimeMarker& other) = default;
- LoginEventRecorder::TimeMarker::~TimeMarker() = default;
- // static
- LoginEventRecorder::Stats LoginEventRecorder::Stats::GetCurrentStats() {
- const base::FilePath kProcUptime(FPL("/proc/uptime"));
- const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
- Stats stats;
- // Callers of this method expect synchronous behavior.
- // It's safe to allow IO here, because only virtual FS are accessed.
- base::ThreadRestrictions::ScopedAllowIO allow_io;
- base::ReadFileToString(kProcUptime, &stats.uptime_);
- base::ReadFileToString(kDiskStat, &stats.disk_);
- return stats;
- }
- std::string LoginEventRecorder::Stats::SerializeToString() const {
- if (uptime_.empty() && disk_.empty())
- return std::string();
- base::DictionaryValue dictionary;
- dictionary.SetString(kUptime, uptime_);
- dictionary.SetString(kDisk, disk_);
- std::string result;
- if (!base::JSONWriter::Write(dictionary, &result)) {
- LOG(WARNING) << "LoginEventRecorder::Stats::SerializeToString(): failed.";
- return std::string();
- }
- return result;
- }
- // static
- LoginEventRecorder::Stats LoginEventRecorder::Stats::DeserializeFromString(
- const std::string& source) {
- if (source.empty())
- return Stats();
- std::unique_ptr<base::Value> value = base::JSONReader::ReadDeprecated(source);
- base::DictionaryValue* dictionary;
- if (!value || !value->GetAsDictionary(&dictionary)) {
- LOG(ERROR) << "LoginEventRecorder::Stats::DeserializeFromString(): not a "
- "dictionary: '"
- << source << "'";
- return Stats();
- }
- Stats result;
- if (!dictionary->GetString(kUptime, &result.uptime_) ||
- !dictionary->GetString(kDisk, &result.disk_)) {
- LOG(ERROR)
- << "LoginEventRecorder::Stats::DeserializeFromString(): format error: '"
- << source << "'";
- return Stats();
- }
- return result;
- }
- bool LoginEventRecorder::Stats::UptimeDouble(double* result) const {
- std::string uptime = uptime_;
- const size_t space_at = uptime.find_first_of(' ');
- if (space_at == std::string::npos)
- return false;
- uptime.resize(space_at);
- if (base::StringToDouble(uptime, result))
- return true;
- return false;
- }
- void LoginEventRecorder::Stats::RecordStats(const std::string& name,
- bool write_flag_file) const {
- base::ThreadPool::PostTask(
- FROM_HERE, {base::MayBlock(), base::TaskPriority::BEST_EFFORT},
- base::BindOnce(&LoginEventRecorder::Stats::RecordStatsAsync,
- base::Owned(new Stats(*this)), name, write_flag_file));
- }
- void LoginEventRecorder::Stats::RecordStatsWithCallback(
- const std::string& name,
- bool write_flag_file,
- base::OnceClosure callback) const {
- base::ThreadPool::PostTaskAndReply(
- FROM_HERE, {base::MayBlock(), base::TaskPriority::BEST_EFFORT},
- base::BindOnce(&LoginEventRecorder::Stats::RecordStatsAsync,
- base::Owned(new Stats(*this)), name, write_flag_file),
- std::move(callback));
- }
- void LoginEventRecorder::Stats::RecordStatsAsync(
- const base::FilePath::StringType& name,
- bool write_flag_file) const {
- const base::FilePath log_path(kLogPath);
- const base::FilePath uptime_output =
- log_path.Append(base::FilePath(kUptimePrefix + name));
- const base::FilePath disk_output =
- log_path.Append(base::FilePath(kDiskPrefix + name));
- // Append numbers to the files.
- AppendFile(uptime_output, uptime_.data(), uptime_.size());
- AppendFile(disk_output, disk_.data(), disk_.size());
- if (write_flag_file) {
- const base::FilePath flag_path =
- log_path.Append(base::FilePath(kStatsPrefix + name + kWrittenSuffix));
- AppendFile(flag_path, "", 0);
- }
- }
- static base::LazyInstance<LoginEventRecorder>::DestructorAtExit
- g_login_event_recorder = LAZY_INSTANCE_INITIALIZER;
- LoginEventRecorder::LoginEventRecorder()
- : task_runner_(base::SequencedTaskRunnerHandle::Get()) {
- DCHECK(base::CurrentUIThread::IsSet());
- login_time_markers_.reserve(30);
- logout_time_markers_.reserve(30);
- // Remember login events for later retrieval by tests.
- constexpr char kKeepLoginEventsForTesting[] = "keep-login-events-for-testing";
- if (base::CommandLine::ForCurrentProcess()->HasSwitch(
- kKeepLoginEventsForTesting)) {
- PrepareEventCollectionForTesting(); // IN-TEST
- }
- }
- LoginEventRecorder::~LoginEventRecorder() = default;
- // static
- LoginEventRecorder* LoginEventRecorder::Get() {
- return g_login_event_recorder.Pointer();
- }
- void LoginEventRecorder::AddLoginTimeMarker(const char* marker_name,
- bool send_to_uma,
- bool write_to_file) {
- AddLoginTimeMarkerWithURL(marker_name, absl::optional<std::string>(),
- send_to_uma, write_to_file);
- }
- void LoginEventRecorder::AddLoginTimeMarkerWithURL(
- const char* marker_name,
- absl::optional<std::string> url,
- bool send_to_uma,
- bool write_to_file) {
- AddMarker(&login_time_markers_,
- TimeMarker(marker_name, url, send_to_uma, write_to_file));
- // Store a copy for testing.
- if (login_time_markers_for_testing_.has_value()) {
- login_time_markers_for_testing_.value().push_back(
- login_time_markers_.back());
- }
- }
- void LoginEventRecorder::AddLogoutTimeMarker(const char* marker_name,
- bool send_to_uma) {
- AddMarker(&logout_time_markers_,
- TimeMarker(marker_name, absl::optional<std::string>(), send_to_uma,
- /*write_to_file=*/true));
- }
- void LoginEventRecorder::RecordAuthenticationSuccess() {
- AddLoginTimeMarker("Authenticate", true);
- RecordCurrentStats(kLoginSuccess);
- }
- void LoginEventRecorder::RecordAuthenticationFailure() {
- // no nothing for now.
- }
- void LoginEventRecorder::RecordCurrentStats(const std::string& name) {
- Stats::GetCurrentStats().RecordStats(name, /*write_flag_file=*/false);
- }
- void LoginEventRecorder::ClearLoginTimeMarkers() {
- login_time_markers_.clear();
- }
- void LoginEventRecorder::ScheduleWriteLoginTimes(const std::string base_name,
- const std::string uma_name,
- const std::string uma_prefix) {
- callback_ = base::BindOnce(&WriteTimes, base_name, uma_name, uma_prefix);
- DCHECK(task_runner_->RunsTasksInCurrentSequence());
- task_runner_->PostDelayedTask(
- FROM_HERE,
- base::BindOnce(&LoginEventRecorder::WriteLoginTimesDelayed,
- weak_ptr_factory_.GetWeakPtr()),
- base::Milliseconds(kLoginTimeWriteDelayMs));
- }
- void LoginEventRecorder::RunScheduledWriteLoginTimes() {
- DCHECK(task_runner_->RunsTasksInCurrentSequence());
- if (callback_.is_null())
- return;
- base::ThreadPool::PostTask(
- FROM_HERE, {base::MayBlock(), base::TaskPriority::BEST_EFFORT},
- base::BindOnce(std::move(callback_), std::move(login_time_markers_)));
- }
- void LoginEventRecorder::WriteLogoutTimes(const std::string base_name,
- const std::string uma_name,
- const std::string uma_prefix) {
- WriteTimes(base_name, uma_name, uma_prefix, std::move(logout_time_markers_));
- }
- void LoginEventRecorder::PrepareEventCollectionForTesting() {
- if (login_time_markers_for_testing_.has_value())
- return;
- login_time_markers_for_testing_ = login_time_markers_;
- }
- const std::vector<LoginEventRecorder::TimeMarker>&
- LoginEventRecorder::GetCollectedLoginEventsForTesting() {
- PrepareEventCollectionForTesting(); // IN-TEST
- return login_time_markers_for_testing_.value();
- }
- void LoginEventRecorder::AddMarker(std::vector<TimeMarker>* vector,
- TimeMarker&& marker) {
- // The marker vectors can only be safely manipulated on the main thread.
- // If we're late in the process of shutting down (eg. as can be the case at
- // logout), then we have to assume we're on the main thread already.
- if (task_runner_->RunsTasksInCurrentSequence()) {
- vector->push_back(marker);
- } else {
- // Add the marker on the UI thread.
- task_runner_->PostTask(FROM_HERE,
- base::BindOnce(&LoginEventRecorder::AddMarker,
- weak_ptr_factory_.GetWeakPtr(),
- base::Unretained(vector), marker));
- }
- }
- void LoginEventRecorder::WriteLoginTimesDelayed() {
- if (callback_.is_null())
- return;
- DCHECK(task_runner_->RunsTasksInCurrentSequence());
- base::ThreadPool::PostTask(
- FROM_HERE, {base::MayBlock(), base::TaskPriority::BEST_EFFORT},
- base::BindOnce(std::move(callback_), std::move(login_time_markers_)));
- }
- } // namespace chromeos
|