login_event_recorder.cc 15 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427
  1. // Copyright 2014 The Chromium Authors. All rights reserved.
  2. // Use of this source code is governed by a BSD-style license that can be
  3. // found in the LICENSE file.
  4. #include "chromeos/metrics/login_event_recorder.h"
  5. #include <vector>
  6. #include "base/command_line.h"
  7. #include "base/files/file_path.h"
  8. #include "base/files/file_util.h"
  9. #include "base/json/json_reader.h"
  10. #include "base/json/json_writer.h"
  11. #include "base/lazy_instance.h"
  12. #include "base/logging.h"
  13. #include "base/metrics/histogram_macros.h"
  14. #include "base/strings/string_number_conversions.h"
  15. #include "base/strings/stringprintf.h"
  16. #include "base/system/sys_info.h"
  17. #include "base/task/current_thread.h"
  18. #include "base/task/sequenced_task_runner.h"
  19. #include "base/task/thread_pool.h"
  20. #include "base/threading/thread.h"
  21. #include "base/threading/thread_restrictions.h"
  22. #include "base/threading/thread_task_runner_handle.h"
  23. #include "base/time/time.h"
  24. #include "base/trace_event/trace_event.h"
  25. #include "base/values.h"
  26. namespace chromeos {
  27. namespace {
  28. constexpr char kUptime[] = "uptime";
  29. constexpr char kDisk[] = "disk";
  30. // The pointer to this object is used as a perfetto async event id.
  31. constexpr char kBootTimes[] = "BootTimes";
  32. #define FPL(value) FILE_PATH_LITERAL(value)
  33. // Dir uptime & disk logs are located in.
  34. constexpr const base::FilePath::CharType kLogPath[] = FPL("/tmp");
  35. // Dir log{in,out} logs are located in.
  36. constexpr base::FilePath::CharType kLoginLogPath[] = FPL("/home/chronos/user");
  37. // Prefix for the time measurement files.
  38. constexpr base::FilePath::CharType kUptimePrefix[] = FPL("uptime-");
  39. // Prefix for the disk usage files.
  40. constexpr base::FilePath::CharType kDiskPrefix[] = FPL("disk-");
  41. // Prefix and suffix for the "stats saved" flags file.
  42. constexpr base::FilePath::CharType kStatsPrefix[] = FPL("stats-");
  43. constexpr base::FilePath::CharType kWrittenSuffix[] = FPL(".written");
  44. // Names of login stats files.
  45. constexpr base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
  46. // The login times will be written immediately when the login animation ends,
  47. // and this is used to ensure the data is always written if this amount is
  48. // elapsed after login.
  49. constexpr int64_t kLoginTimeWriteDelayMs = 20000;
  50. // Appends the given buffer into the file. Returns the number of bytes
  51. // written, or -1 on error.<
  52. // TODO(satorux): Move this to file_util.
  53. int AppendFile(const base::FilePath& file_path, const char* data, int size) {
  54. // Appending boot times to (probably) a symlink in /tmp is a security risk for
  55. // developers with chromeos=1 builds.
  56. if (!base::SysInfo::IsRunningOnChromeOS())
  57. return -1;
  58. FILE* file = base::OpenFile(file_path, "a");
  59. if (!file)
  60. return -1;
  61. const int num_bytes_written = fwrite(data, 1, size, file);
  62. base::CloseFile(file);
  63. return num_bytes_written;
  64. }
  65. void WriteTimes(const std::string base_name,
  66. const std::string uma_name,
  67. const std::string uma_prefix,
  68. std::vector<LoginEventRecorder::TimeMarker> times) {
  69. DCHECK(times.size());
  70. const int kMinTimeMillis = 1;
  71. const int kMaxTimeMillis = 30000;
  72. const int kNumBuckets = 100;
  73. const base::FilePath log_path(kLoginLogPath);
  74. // Need to sort by time since the entries may have been pushed onto the
  75. // vector (on the UI thread) in a different order from which they were
  76. // created (potentially on other threads).
  77. std::sort(times.begin(), times.end());
  78. base::Time first = times.front().time();
  79. base::Time last = times.back().time();
  80. base::TimeDelta total = last - first;
  81. base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
  82. uma_name, base::Milliseconds(kMinTimeMillis),
  83. base::Milliseconds(kMaxTimeMillis), kNumBuckets,
  84. base::HistogramBase::kUmaTargetedHistogramFlag);
  85. total_hist->AddTime(total);
  86. std::string output =
  87. base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
  88. base::Time prev = first;
  89. // Convert base::Time to base::TimeTicks for tracing.
  90. auto time2timeticks = [](const base::Time& ts) {
  91. return base::TimeTicks::Now() - (base::Time::Now() - ts);
  92. };
  93. // Send first event to name the track:
  94. // "In Chrome, we usually don't bother setting explicit track names. If none
  95. // is provided, the track is named after the first event on the track."
  96. TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
  97. "startup", kBootTimes, TRACE_ID_LOCAL(kBootTimes), time2timeticks(prev));
  98. for (unsigned int i = 0; i < times.size(); ++i) {
  99. const LoginEventRecorder::TimeMarker& tm = times[i];
  100. if (tm.url().has_value()) {
  101. TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1(
  102. "startup", tm.name(), TRACE_ID_LOCAL(kBootTimes),
  103. time2timeticks(prev), "url", *tm.url());
  104. TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP1(
  105. "startup", tm.name(), TRACE_ID_LOCAL(kBootTimes),
  106. time2timeticks(tm.time()), "url", *tm.url());
  107. } else {
  108. TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
  109. "startup", tm.name(), TRACE_ID_LOCAL(kBootTimes),
  110. time2timeticks(prev));
  111. TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0("startup", tm.name(),
  112. TRACE_ID_LOCAL(kBootTimes),
  113. time2timeticks(tm.time()));
  114. }
  115. base::TimeDelta since_first = tm.time() - first;
  116. base::TimeDelta since_prev = tm.time() - prev;
  117. std::string name;
  118. if (tm.send_to_uma()) {
  119. name = uma_prefix + tm.name();
  120. base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
  121. name, base::Milliseconds(kMinTimeMillis),
  122. base::Milliseconds(kMaxTimeMillis), kNumBuckets,
  123. base::HistogramBase::kUmaTargetedHistogramFlag);
  124. prev_hist->AddTime(since_prev);
  125. } else {
  126. name = tm.name();
  127. }
  128. if (tm.write_to_file()) {
  129. output += base::StringPrintf("\n%.2f +%.4f %s", since_first.InSecondsF(),
  130. since_prev.InSecondsF(), name.data());
  131. if (tm.url().has_value()) {
  132. output += ": ";
  133. output += *tm.url();
  134. }
  135. }
  136. prev = tm.time();
  137. }
  138. output += '\n';
  139. TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
  140. "startup", kBootTimes, TRACE_ID_LOCAL(kBootTimes), time2timeticks(prev));
  141. base::WriteFile(log_path.Append(base_name), output.data(), output.size());
  142. }
  143. } // namespace
  144. LoginEventRecorder::TimeMarker::TimeMarker(const char* name,
  145. absl::optional<std::string> url,
  146. bool send_to_uma,
  147. bool write_to_file)
  148. : name_(name),
  149. url_(url),
  150. send_to_uma_(send_to_uma),
  151. write_to_file_(write_to_file) {}
  152. LoginEventRecorder::TimeMarker::TimeMarker(const TimeMarker& other) = default;
  153. LoginEventRecorder::TimeMarker::~TimeMarker() = default;
  154. // static
  155. LoginEventRecorder::Stats LoginEventRecorder::Stats::GetCurrentStats() {
  156. const base::FilePath kProcUptime(FPL("/proc/uptime"));
  157. const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
  158. Stats stats;
  159. // Callers of this method expect synchronous behavior.
  160. // It's safe to allow IO here, because only virtual FS are accessed.
  161. base::ThreadRestrictions::ScopedAllowIO allow_io;
  162. base::ReadFileToString(kProcUptime, &stats.uptime_);
  163. base::ReadFileToString(kDiskStat, &stats.disk_);
  164. return stats;
  165. }
  166. std::string LoginEventRecorder::Stats::SerializeToString() const {
  167. if (uptime_.empty() && disk_.empty())
  168. return std::string();
  169. base::DictionaryValue dictionary;
  170. dictionary.SetString(kUptime, uptime_);
  171. dictionary.SetString(kDisk, disk_);
  172. std::string result;
  173. if (!base::JSONWriter::Write(dictionary, &result)) {
  174. LOG(WARNING) << "LoginEventRecorder::Stats::SerializeToString(): failed.";
  175. return std::string();
  176. }
  177. return result;
  178. }
  179. // static
  180. LoginEventRecorder::Stats LoginEventRecorder::Stats::DeserializeFromString(
  181. const std::string& source) {
  182. if (source.empty())
  183. return Stats();
  184. std::unique_ptr<base::Value> value = base::JSONReader::ReadDeprecated(source);
  185. base::DictionaryValue* dictionary;
  186. if (!value || !value->GetAsDictionary(&dictionary)) {
  187. LOG(ERROR) << "LoginEventRecorder::Stats::DeserializeFromString(): not a "
  188. "dictionary: '"
  189. << source << "'";
  190. return Stats();
  191. }
  192. Stats result;
  193. if (!dictionary->GetString(kUptime, &result.uptime_) ||
  194. !dictionary->GetString(kDisk, &result.disk_)) {
  195. LOG(ERROR)
  196. << "LoginEventRecorder::Stats::DeserializeFromString(): format error: '"
  197. << source << "'";
  198. return Stats();
  199. }
  200. return result;
  201. }
  202. bool LoginEventRecorder::Stats::UptimeDouble(double* result) const {
  203. std::string uptime = uptime_;
  204. const size_t space_at = uptime.find_first_of(' ');
  205. if (space_at == std::string::npos)
  206. return false;
  207. uptime.resize(space_at);
  208. if (base::StringToDouble(uptime, result))
  209. return true;
  210. return false;
  211. }
  212. void LoginEventRecorder::Stats::RecordStats(const std::string& name,
  213. bool write_flag_file) const {
  214. base::ThreadPool::PostTask(
  215. FROM_HERE, {base::MayBlock(), base::TaskPriority::BEST_EFFORT},
  216. base::BindOnce(&LoginEventRecorder::Stats::RecordStatsAsync,
  217. base::Owned(new Stats(*this)), name, write_flag_file));
  218. }
  219. void LoginEventRecorder::Stats::RecordStatsWithCallback(
  220. const std::string& name,
  221. bool write_flag_file,
  222. base::OnceClosure callback) const {
  223. base::ThreadPool::PostTaskAndReply(
  224. FROM_HERE, {base::MayBlock(), base::TaskPriority::BEST_EFFORT},
  225. base::BindOnce(&LoginEventRecorder::Stats::RecordStatsAsync,
  226. base::Owned(new Stats(*this)), name, write_flag_file),
  227. std::move(callback));
  228. }
  229. void LoginEventRecorder::Stats::RecordStatsAsync(
  230. const base::FilePath::StringType& name,
  231. bool write_flag_file) const {
  232. const base::FilePath log_path(kLogPath);
  233. const base::FilePath uptime_output =
  234. log_path.Append(base::FilePath(kUptimePrefix + name));
  235. const base::FilePath disk_output =
  236. log_path.Append(base::FilePath(kDiskPrefix + name));
  237. // Append numbers to the files.
  238. AppendFile(uptime_output, uptime_.data(), uptime_.size());
  239. AppendFile(disk_output, disk_.data(), disk_.size());
  240. if (write_flag_file) {
  241. const base::FilePath flag_path =
  242. log_path.Append(base::FilePath(kStatsPrefix + name + kWrittenSuffix));
  243. AppendFile(flag_path, "", 0);
  244. }
  245. }
  246. static base::LazyInstance<LoginEventRecorder>::DestructorAtExit
  247. g_login_event_recorder = LAZY_INSTANCE_INITIALIZER;
  248. LoginEventRecorder::LoginEventRecorder()
  249. : task_runner_(base::SequencedTaskRunnerHandle::Get()) {
  250. DCHECK(base::CurrentUIThread::IsSet());
  251. login_time_markers_.reserve(30);
  252. logout_time_markers_.reserve(30);
  253. // Remember login events for later retrieval by tests.
  254. constexpr char kKeepLoginEventsForTesting[] = "keep-login-events-for-testing";
  255. if (base::CommandLine::ForCurrentProcess()->HasSwitch(
  256. kKeepLoginEventsForTesting)) {
  257. PrepareEventCollectionForTesting(); // IN-TEST
  258. }
  259. }
  260. LoginEventRecorder::~LoginEventRecorder() = default;
  261. // static
  262. LoginEventRecorder* LoginEventRecorder::Get() {
  263. return g_login_event_recorder.Pointer();
  264. }
  265. void LoginEventRecorder::AddLoginTimeMarker(const char* marker_name,
  266. bool send_to_uma,
  267. bool write_to_file) {
  268. AddLoginTimeMarkerWithURL(marker_name, absl::optional<std::string>(),
  269. send_to_uma, write_to_file);
  270. }
  271. void LoginEventRecorder::AddLoginTimeMarkerWithURL(
  272. const char* marker_name,
  273. absl::optional<std::string> url,
  274. bool send_to_uma,
  275. bool write_to_file) {
  276. AddMarker(&login_time_markers_,
  277. TimeMarker(marker_name, url, send_to_uma, write_to_file));
  278. // Store a copy for testing.
  279. if (login_time_markers_for_testing_.has_value()) {
  280. login_time_markers_for_testing_.value().push_back(
  281. login_time_markers_.back());
  282. }
  283. }
  284. void LoginEventRecorder::AddLogoutTimeMarker(const char* marker_name,
  285. bool send_to_uma) {
  286. AddMarker(&logout_time_markers_,
  287. TimeMarker(marker_name, absl::optional<std::string>(), send_to_uma,
  288. /*write_to_file=*/true));
  289. }
  290. void LoginEventRecorder::RecordAuthenticationSuccess() {
  291. AddLoginTimeMarker("Authenticate", true);
  292. RecordCurrentStats(kLoginSuccess);
  293. }
  294. void LoginEventRecorder::RecordAuthenticationFailure() {
  295. // no nothing for now.
  296. }
  297. void LoginEventRecorder::RecordCurrentStats(const std::string& name) {
  298. Stats::GetCurrentStats().RecordStats(name, /*write_flag_file=*/false);
  299. }
  300. void LoginEventRecorder::ClearLoginTimeMarkers() {
  301. login_time_markers_.clear();
  302. }
  303. void LoginEventRecorder::ScheduleWriteLoginTimes(const std::string base_name,
  304. const std::string uma_name,
  305. const std::string uma_prefix) {
  306. callback_ = base::BindOnce(&WriteTimes, base_name, uma_name, uma_prefix);
  307. DCHECK(task_runner_->RunsTasksInCurrentSequence());
  308. task_runner_->PostDelayedTask(
  309. FROM_HERE,
  310. base::BindOnce(&LoginEventRecorder::WriteLoginTimesDelayed,
  311. weak_ptr_factory_.GetWeakPtr()),
  312. base::Milliseconds(kLoginTimeWriteDelayMs));
  313. }
  314. void LoginEventRecorder::RunScheduledWriteLoginTimes() {
  315. DCHECK(task_runner_->RunsTasksInCurrentSequence());
  316. if (callback_.is_null())
  317. return;
  318. base::ThreadPool::PostTask(
  319. FROM_HERE, {base::MayBlock(), base::TaskPriority::BEST_EFFORT},
  320. base::BindOnce(std::move(callback_), std::move(login_time_markers_)));
  321. }
  322. void LoginEventRecorder::WriteLogoutTimes(const std::string base_name,
  323. const std::string uma_name,
  324. const std::string uma_prefix) {
  325. WriteTimes(base_name, uma_name, uma_prefix, std::move(logout_time_markers_));
  326. }
  327. void LoginEventRecorder::PrepareEventCollectionForTesting() {
  328. if (login_time_markers_for_testing_.has_value())
  329. return;
  330. login_time_markers_for_testing_ = login_time_markers_;
  331. }
  332. const std::vector<LoginEventRecorder::TimeMarker>&
  333. LoginEventRecorder::GetCollectedLoginEventsForTesting() {
  334. PrepareEventCollectionForTesting(); // IN-TEST
  335. return login_time_markers_for_testing_.value();
  336. }
  337. void LoginEventRecorder::AddMarker(std::vector<TimeMarker>* vector,
  338. TimeMarker&& marker) {
  339. // The marker vectors can only be safely manipulated on the main thread.
  340. // If we're late in the process of shutting down (eg. as can be the case at
  341. // logout), then we have to assume we're on the main thread already.
  342. if (task_runner_->RunsTasksInCurrentSequence()) {
  343. vector->push_back(marker);
  344. } else {
  345. // Add the marker on the UI thread.
  346. task_runner_->PostTask(FROM_HERE,
  347. base::BindOnce(&LoginEventRecorder::AddMarker,
  348. weak_ptr_factory_.GetWeakPtr(),
  349. base::Unretained(vector), marker));
  350. }
  351. }
  352. void LoginEventRecorder::WriteLoginTimesDelayed() {
  353. if (callback_.is_null())
  354. return;
  355. DCHECK(task_runner_->RunsTasksInCurrentSequence());
  356. base::ThreadPool::PostTask(
  357. FROM_HERE, {base::MayBlock(), base::TaskPriority::BEST_EFFORT},
  358. base::BindOnce(std::move(callback_), std::move(login_time_markers_)));
  359. }
  360. } // namespace chromeos