blob: 44d8d4ff2600a4cc397e5fc01c8b86129adf6d2a [file] [log] [blame]
Darin Petkov8032dd02011-05-09 16:33:19 -07001// Copyright (c) 2011 The Chromium OS Authors. All rights reserved.
Darin Petkov65b01462010-04-14 13:32:20 -07002// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "metrics_daemon.h"
Darin Petkov65b01462010-04-14 13:32:20 -07006
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -08007#include <fcntl.h>
Luigi Semenzato8accd332011-05-17 16:37:18 -07008#include <math.h>
Ken Mixter4c5daa42010-08-26 18:35:06 -07009#include <string.h>
Luigi Semenzato8accd332011-05-17 16:37:18 -070010#include <time.h>
Darin Petkov65b01462010-04-14 13:32:20 -070011
Darin Petkov38d5cb02010-06-24 12:10:26 -070012#include <base/file_util.h>
Darin Petkov65b01462010-04-14 13:32:20 -070013#include <base/logging.h>
Ben Chan2e6543d2014-02-05 23:26:25 -080014#include <base/strings/string_number_conversions.h>
15#include <base/strings/string_split.h>
16#include <base/strings/string_util.h>
17#include <base/strings/stringprintf.h>
Darin Petkov40f25732013-04-29 15:07:31 +020018#include <chromeos/dbus/service_constants.h>
Ken Mixter4c5daa42010-08-26 18:35:06 -070019#include <dbus/dbus-glib-lowlevel.h>
Darin Petkov65b01462010-04-14 13:32:20 -070020
Darin Petkovf1e85e42010-06-10 15:59:53 -070021#include "counter.h"
22
Ben Chan2e6543d2014-02-05 23:26:25 -080023using base::FilePath;
24using base::StringPrintf;
Darin Petkovf27f0362010-06-04 13:14:19 -070025using base::Time;
26using base::TimeDelta;
27using base::TimeTicks;
Luigi Semenzato8accd332011-05-17 16:37:18 -070028using std::map;
Darin Petkov38d5cb02010-06-24 12:10:26 -070029using std::string;
Luigi Semenzato8accd332011-05-17 16:37:18 -070030using std::vector;
31
Darin Petkovf27f0362010-06-04 13:14:19 -070032
Darin Petkov703ec972010-04-27 11:02:18 -070033#define SAFE_MESSAGE(e) (e.message ? e.message : "unknown error")
Darin Petkov40f25732013-04-29 15:07:31 +020034
35static const char kCrashReporterInterface[] = "org.chromium.CrashReporter";
36static const char kCrashReporterUserCrashSignal[] = "UserCrash";
Darin Petkov41e06232010-05-03 16:45:37 -070037
Darin Petkov41e06232010-05-03 16:45:37 -070038static const int kSecondsPerMinute = 60;
39static const int kMinutesPerHour = 60;
40static const int kHoursPerDay = 24;
41static const int kMinutesPerDay = kHoursPerDay * kMinutesPerHour;
Darin Petkov1bb904e2010-06-16 15:58:06 -070042static const int kSecondsPerDay = kSecondsPerMinute * kMinutesPerDay;
43static const int kDaysPerWeek = 7;
44static const int kSecondsPerWeek = kSecondsPerDay * kDaysPerWeek;
Darin Petkov41e06232010-05-03 16:45:37 -070045
46// The daily use monitor is scheduled to a 1-minute interval after
47// initial user activity and then it's exponentially backed off to
48// 10-minute intervals. Although not required, the back off is
49// implemented because the histogram buckets are spaced exponentially
50// anyway and to avoid too frequent metrics daemon process wake-ups
51// and file I/O.
52static const int kUseMonitorIntervalInit = 1 * kSecondsPerMinute;
53static const int kUseMonitorIntervalMax = 10 * kSecondsPerMinute;
Darin Petkov65b01462010-04-14 13:32:20 -070054
Luigi Semenzatoc5a92342014-02-14 15:05:51 -080055const char kKernelCrashDetectedFile[] = "/var/run/kernel-crash-detected";
Ken Mixterccd84c02010-08-16 19:57:13 -070056static const char kUncleanShutdownDetectedFile[] =
Luigi Semenzatoc5a92342014-02-14 15:05:51 -080057 "/var/run/unclean-shutdown-detected";
Ken Mixterccd84c02010-08-16 19:57:13 -070058
Ken Mixter4c5daa42010-08-26 18:35:06 -070059// static metrics parameters
Darin Petkov2ccef012010-05-05 16:06:37 -070060const char MetricsDaemon::kMetricDailyUseTimeName[] =
61 "Logging.DailyUseTime";
62const int MetricsDaemon::kMetricDailyUseTimeMin = 1;
63const int MetricsDaemon::kMetricDailyUseTimeMax = kMinutesPerDay;
64const int MetricsDaemon::kMetricDailyUseTimeBuckets = 50;
65
Ken Mixterccd84c02010-08-16 19:57:13 -070066// crash interval metrics
67const char MetricsDaemon::kMetricKernelCrashIntervalName[] =
68 "Logging.KernelCrashInterval";
69const char MetricsDaemon::kMetricUncleanShutdownIntervalName[] =
70 "Logging.UncleanShutdownInterval";
Darin Petkov1bb904e2010-06-16 15:58:06 -070071const char MetricsDaemon::kMetricUserCrashIntervalName[] =
72 "Logging.UserCrashInterval";
Ken Mixterccd84c02010-08-16 19:57:13 -070073
74const int MetricsDaemon::kMetricCrashIntervalMin = 1;
75const int MetricsDaemon::kMetricCrashIntervalMax =
76 4 * kSecondsPerWeek;
77const int MetricsDaemon::kMetricCrashIntervalBuckets = 50;
78
79// crash frequency metrics
80const char MetricsDaemon::kMetricAnyCrashesDailyName[] =
81 "Logging.AnyCrashesDaily";
Ken Mixter4c5daa42010-08-26 18:35:06 -070082const char MetricsDaemon::kMetricAnyCrashesWeeklyName[] =
83 "Logging.AnyCrashesWeekly";
Ken Mixterccd84c02010-08-16 19:57:13 -070084const char MetricsDaemon::kMetricKernelCrashesDailyName[] =
85 "Logging.KernelCrashesDaily";
Ken Mixter4c5daa42010-08-26 18:35:06 -070086const char MetricsDaemon::kMetricKernelCrashesWeeklyName[] =
87 "Logging.KernelCrashesWeekly";
Ken Mixterccd84c02010-08-16 19:57:13 -070088const char MetricsDaemon::kMetricUncleanShutdownsDailyName[] =
89 "Logging.UncleanShutdownsDaily";
Ken Mixter4c5daa42010-08-26 18:35:06 -070090const char MetricsDaemon::kMetricUncleanShutdownsWeeklyName[] =
91 "Logging.UncleanShutdownsWeekly";
Ken Mixterccd84c02010-08-16 19:57:13 -070092const char MetricsDaemon::kMetricUserCrashesDailyName[] =
93 "Logging.UserCrashesDaily";
Ken Mixter4c5daa42010-08-26 18:35:06 -070094const char MetricsDaemon::kMetricUserCrashesWeeklyName[] =
95 "Logging.UserCrashesWeekly";
96const char MetricsDaemon::kMetricCrashFrequencyMin = 1;
97const char MetricsDaemon::kMetricCrashFrequencyMax = 100;
98const char MetricsDaemon::kMetricCrashFrequencyBuckets = 50;
Ken Mixterccd84c02010-08-16 19:57:13 -070099
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800100// disk stats metrics
101
102// The {Read,Write}Sectors numbers are in sectors/second.
103// A sector is usually 512 bytes.
104
105const char MetricsDaemon::kMetricReadSectorsLongName[] =
106 "Platform.ReadSectorsLong";
107const char MetricsDaemon::kMetricWriteSectorsLongName[] =
108 "Platform.WriteSectorsLong";
109const char MetricsDaemon::kMetricReadSectorsShortName[] =
110 "Platform.ReadSectorsShort";
111const char MetricsDaemon::kMetricWriteSectorsShortName[] =
112 "Platform.WriteSectorsShort";
113
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700114const int MetricsDaemon::kMetricStatsShortInterval = 1; // seconds
115const int MetricsDaemon::kMetricStatsLongInterval = 30; // seconds
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800116
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700117const int MetricsDaemon::kMetricMeminfoInterval = 30; // seconds
118
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800119// Assume a max rate of 250Mb/s for reads (worse for writes) and 512 byte
120// sectors.
121const int MetricsDaemon::kMetricSectorsIOMax = 500000; // sectors/second
122const int MetricsDaemon::kMetricSectorsBuckets = 50; // buckets
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700123// Page size is 4k, sector size is 0.5k. We're not interested in page fault
124// rates that the disk cannot sustain.
125const int MetricsDaemon::kMetricPageFaultsMax = kMetricSectorsIOMax / 8;
126const int MetricsDaemon::kMetricPageFaultsBuckets = 50;
127
128// Major page faults, i.e. the ones that require data to be read from disk.
129
130const char MetricsDaemon::kMetricPageFaultsLongName[] =
131 "Platform.PageFaultsLong";
132const char MetricsDaemon::kMetricPageFaultsShortName[] =
133 "Platform.PageFaultsShort";
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800134
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700135// Swap in and Swap out
136
137const char MetricsDaemon::kMetricSwapInLongName[] =
138 "Platform.SwapInLong";
139const char MetricsDaemon::kMetricSwapInShortName[] =
140 "Platform.SwapInShort";
141
142const char MetricsDaemon::kMetricSwapOutLongName[] =
143 "Platform.SwapOutLong";
144const char MetricsDaemon::kMetricSwapOutShortName[] =
145 "Platform.SwapOutShort";
146
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700147// Thermal CPU throttling.
148
149const char MetricsDaemon::kMetricScaledCpuFrequencyName[] =
150 "Platform.CpuFrequencyThermalScaling";
151
Ken Mixter4c5daa42010-08-26 18:35:06 -0700152// persistent metrics path
153const char MetricsDaemon::kMetricsPath[] = "/var/log/metrics";
Ken Mixterccd84c02010-08-16 19:57:13 -0700154
Darin Petkov703ec972010-04-27 11:02:18 -0700155// static
Darin Petkov41e06232010-05-03 16:45:37 -0700156const char* MetricsDaemon::kPowerStates_[] = {
Darin Petkov703ec972010-04-27 11:02:18 -0700157#define STATE(name, capname) #name,
158#include "power_states.h"
159};
160
Darin Petkov41e06232010-05-03 16:45:37 -0700161// static
Darin Petkov41e06232010-05-03 16:45:37 -0700162const char* MetricsDaemon::kSessionStates_[] = {
163#define STATE(name, capname) #name,
164#include "session_states.h"
165};
166
Luigi Semenzato8accd332011-05-17 16:37:18 -0700167// Memory use stats collection intervals. We collect some memory use interval
168// at these intervals after boot, and we stop collecting after the last one,
169// with the assumption that in most cases the memory use won't change much
170// after that.
171static const int kMemuseIntervals[] = {
172 1 * kSecondsPerMinute, // 1 minute mark
173 4 * kSecondsPerMinute, // 5 minute mark
174 25 * kSecondsPerMinute, // 0.5 hour mark
175 120 * kSecondsPerMinute, // 2.5 hour mark
176 600 * kSecondsPerMinute, // 12.5 hour mark
177};
178
Darin Petkovf1e85e42010-06-10 15:59:53 -0700179MetricsDaemon::MetricsDaemon()
Sam Leffler239b8262010-08-30 08:56:58 -0700180 : power_state_(kUnknownPowerState),
Darin Petkovf1e85e42010-06-10 15:59:53 -0700181 session_state_(kUnknownSessionState),
182 user_active_(false),
183 usemon_interval_(0),
Luigi Semenzato8accd332011-05-17 16:37:18 -0700184 usemon_source_(NULL),
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800185 memuse_final_time_(0),
Luigi Semenzato8accd332011-05-17 16:37:18 -0700186 memuse_interval_index_(0),
187 read_sectors_(0),
188 write_sectors_(0),
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700189 vmstats_(),
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700190 stats_state_(kStatsShort),
191 stats_initial_time_(0) {}
Darin Petkovf1e85e42010-06-10 15:59:53 -0700192
Ken Mixter4c5daa42010-08-26 18:35:06 -0700193MetricsDaemon::~MetricsDaemon() {
194 DeleteFrequencyCounters();
195}
196
Luigi Semenzato8accd332011-05-17 16:37:18 -0700197double MetricsDaemon::GetActiveTime() {
198 struct timespec ts;
199 int r = clock_gettime(CLOCK_MONOTONIC, &ts);
200 if (r < 0) {
201 PLOG(WARNING) << "clock_gettime(CLOCK_MONOTONIC) failed";
202 return 0;
203 } else {
204 return ts.tv_sec + ((double) ts.tv_nsec) / (1000 * 1000 * 1000);
205 }
206}
207
Ken Mixter4c5daa42010-08-26 18:35:06 -0700208void MetricsDaemon::DeleteFrequencyCounters() {
209 for (FrequencyCounters::iterator i = frequency_counters_.begin();
210 i != frequency_counters_.end(); ++i) {
211 delete i->second;
212 i->second = NULL;
213 }
214}
Darin Petkovf1e85e42010-06-10 15:59:53 -0700215
Darin Petkov2ccef012010-05-05 16:06:37 -0700216void MetricsDaemon::Run(bool run_as_daemon) {
Darin Petkov38d5cb02010-06-24 12:10:26 -0700217 if (run_as_daemon && daemon(0, 0) != 0)
218 return;
219
Ken Mixterccd84c02010-08-16 19:57:13 -0700220 if (CheckSystemCrash(kKernelCrashDetectedFile)) {
221 ProcessKernelCrash();
222 }
223
224 if (CheckSystemCrash(kUncleanShutdownDetectedFile)) {
225 ProcessUncleanShutdown();
226 }
227
Darin Petkov38d5cb02010-06-24 12:10:26 -0700228 Loop();
Darin Petkov65b01462010-04-14 13:32:20 -0700229}
230
Ken Mixter4c5daa42010-08-26 18:35:06 -0700231FilePath MetricsDaemon::GetHistogramPath(const char* histogram_name) {
232 return FilePath(kMetricsPath).Append(histogram_name);
233}
234
235void MetricsDaemon::ConfigureCrashIntervalReporter(
236 const char* histogram_name,
237 scoped_ptr<chromeos_metrics::TaggedCounterReporter>* reporter) {
238 reporter->reset(new chromeos_metrics::TaggedCounterReporter());
239 FilePath file_path = GetHistogramPath(histogram_name);
240 (*reporter)->Init(file_path.value().c_str(),
241 histogram_name,
242 kMetricCrashIntervalMin,
243 kMetricCrashIntervalMax,
244 kMetricCrashIntervalBuckets);
245}
246
247void MetricsDaemon::ConfigureCrashFrequencyReporter(
248 const char* histogram_name) {
249 scoped_ptr<chromeos_metrics::TaggedCounterReporter> reporter(
250 new chromeos_metrics::TaggedCounterReporter());
251 FilePath file_path = GetHistogramPath(histogram_name);
252 reporter->Init(file_path.value().c_str(),
253 histogram_name,
254 kMetricCrashFrequencyMin,
255 kMetricCrashFrequencyMax,
256 kMetricCrashFrequencyBuckets);
257 scoped_ptr<chromeos_metrics::FrequencyCounter> new_counter(
258 new chromeos_metrics::FrequencyCounter());
259 time_t cycle_duration = strstr(histogram_name, "Weekly") != NULL ?
260 chromeos_metrics::kSecondsPerWeek :
261 chromeos_metrics::kSecondsPerDay;
262 new_counter->Init(
263 static_cast<chromeos_metrics::TaggedCounterInterface*>(
264 reporter.release()),
265 cycle_duration);
266 frequency_counters_[histogram_name] = new_counter.release();
267}
268
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800269void MetricsDaemon::Init(bool testing, MetricsLibraryInterface* metrics_lib,
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700270 const string& diskstats_path,
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700271 const string& vmstats_path,
272 const string& scaling_max_freq_path,
273 const string& cpuinfo_max_freq_path
274 ) {
Darin Petkov65b01462010-04-14 13:32:20 -0700275 testing_ = testing;
Darin Petkovfc91b422010-05-12 13:05:45 -0700276 DCHECK(metrics_lib != NULL);
277 metrics_lib_ = metrics_lib;
Ken Mixter4c5daa42010-08-26 18:35:06 -0700278 chromeos_metrics::TaggedCounterReporter::
279 SetMetricsLibraryInterface(metrics_lib);
Darin Petkov38d5cb02010-06-24 12:10:26 -0700280
281 static const char kDailyUseRecordFile[] = "/var/log/metrics/daily-usage";
Darin Petkovf1e85e42010-06-10 15:59:53 -0700282 daily_use_.reset(new chromeos_metrics::TaggedCounter());
Ken Mixterccd84c02010-08-16 19:57:13 -0700283 daily_use_->Init(kDailyUseRecordFile, &ReportDailyUse, this);
Darin Petkov38d5cb02010-06-24 12:10:26 -0700284
Ken Mixter4c5daa42010-08-26 18:35:06 -0700285 ConfigureCrashIntervalReporter(kMetricKernelCrashIntervalName,
286 &kernel_crash_interval_);
287 ConfigureCrashIntervalReporter(kMetricUncleanShutdownIntervalName,
288 &unclean_shutdown_interval_);
289 ConfigureCrashIntervalReporter(kMetricUserCrashIntervalName,
290 &user_crash_interval_);
Darin Petkov2ccef012010-05-05 16:06:37 -0700291
Ken Mixter4c5daa42010-08-26 18:35:06 -0700292 DeleteFrequencyCounters();
293 ConfigureCrashFrequencyReporter(kMetricAnyCrashesDailyName);
Ken Mixter4c5daa42010-08-26 18:35:06 -0700294 ConfigureCrashFrequencyReporter(kMetricAnyCrashesWeeklyName);
295 ConfigureCrashFrequencyReporter(kMetricKernelCrashesDailyName);
296 ConfigureCrashFrequencyReporter(kMetricKernelCrashesWeeklyName);
297 ConfigureCrashFrequencyReporter(kMetricUncleanShutdownsDailyName);
298 ConfigureCrashFrequencyReporter(kMetricUncleanShutdownsWeeklyName);
299 ConfigureCrashFrequencyReporter(kMetricUserCrashesDailyName);
300 ConfigureCrashFrequencyReporter(kMetricUserCrashesWeeklyName);
Darin Petkov38d5cb02010-06-24 12:10:26 -0700301
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700302 diskstats_path_ = diskstats_path;
303 vmstats_path_ = vmstats_path;
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700304 scaling_max_freq_path_ = scaling_max_freq_path;
305 cpuinfo_max_freq_path_ = cpuinfo_max_freq_path;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700306 StatsReporterInit();
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800307
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700308 // Start collecting meminfo stats.
309 ScheduleMeminfoCallback(kMetricMeminfoInterval);
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800310 memuse_final_time_ = GetActiveTime() + kMemuseIntervals[0];
311 ScheduleMemuseCallback(kMemuseIntervals[0]);
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700312
Darin Petkov2ccef012010-05-05 16:06:37 -0700313 // Don't setup D-Bus and GLib in test mode.
314 if (testing)
315 return;
Darin Petkov65b01462010-04-14 13:32:20 -0700316
Darin Petkov703ec972010-04-27 11:02:18 -0700317 g_type_init();
Ben Chan6f598422013-06-22 06:29:36 -0700318 dbus_threads_init_default();
Darin Petkov65b01462010-04-14 13:32:20 -0700319
Darin Petkov703ec972010-04-27 11:02:18 -0700320 DBusError error;
321 dbus_error_init(&error);
Darin Petkov65b01462010-04-14 13:32:20 -0700322
David James3b3add52010-06-04 15:01:19 -0700323 DBusConnection* connection = dbus_bus_get(DBUS_BUS_SYSTEM, &error);
Darin Petkov703ec972010-04-27 11:02:18 -0700324 LOG_IF(FATAL, dbus_error_is_set(&error)) <<
325 "No D-Bus connection: " << SAFE_MESSAGE(error);
Darin Petkov65b01462010-04-14 13:32:20 -0700326
Darin Petkov703ec972010-04-27 11:02:18 -0700327 dbus_connection_setup_with_g_main(connection, NULL);
Darin Petkov65b01462010-04-14 13:32:20 -0700328
Darin Petkov40f25732013-04-29 15:07:31 +0200329 vector<string> matches;
330 matches.push_back(
331 StringPrintf("type='signal',interface='%s',path='/',member='%s'",
332 kCrashReporterInterface,
333 kCrashReporterUserCrashSignal));
334 matches.push_back(
335 StringPrintf("type='signal',interface='%s',path='%s',member='%s'",
336 power_manager::kPowerManagerInterface,
337 power_manager::kPowerManagerServicePath,
338 power_manager::kPowerStateChangedSignal));
339 matches.push_back(
340 StringPrintf("type='signal',sender='%s',interface='%s',path='%s'",
341 login_manager::kSessionManagerServiceName,
342 login_manager::kSessionManagerInterface,
343 login_manager::kSessionManagerServicePath));
344
Darin Petkov703ec972010-04-27 11:02:18 -0700345 // Registers D-Bus matches for the signals we would like to catch.
Darin Petkov40f25732013-04-29 15:07:31 +0200346 for (vector<string>::const_iterator it = matches.begin();
347 it != matches.end(); ++it) {
348 const char* match = it->c_str();
Darin Petkov41e06232010-05-03 16:45:37 -0700349 DLOG(INFO) << "adding dbus match: " << match;
Darin Petkov703ec972010-04-27 11:02:18 -0700350 dbus_bus_add_match(connection, match, &error);
351 LOG_IF(FATAL, dbus_error_is_set(&error)) <<
352 "unable to add a match: " << SAFE_MESSAGE(error);
353 }
354
355 // Adds the D-Bus filter routine to be called back whenever one of
356 // the registered D-Bus matches is successful. The daemon is not
357 // activated for D-Bus messages that don't match.
358 CHECK(dbus_connection_add_filter(connection, MessageFilter, this, NULL));
Darin Petkov65b01462010-04-14 13:32:20 -0700359}
360
361void MetricsDaemon::Loop() {
Darin Petkov703ec972010-04-27 11:02:18 -0700362 GMainLoop* loop = g_main_loop_new(NULL, false);
363 g_main_loop_run(loop);
Darin Petkov65b01462010-04-14 13:32:20 -0700364}
365
Darin Petkov703ec972010-04-27 11:02:18 -0700366// static
367DBusHandlerResult MetricsDaemon::MessageFilter(DBusConnection* connection,
368 DBusMessage* message,
369 void* user_data) {
Darin Petkovf27f0362010-06-04 13:14:19 -0700370 Time now = Time::Now();
Darin Petkovf27f0362010-06-04 13:14:19 -0700371 DLOG(INFO) << "message intercepted @ " << now.ToInternalValue();
Darin Petkov703ec972010-04-27 11:02:18 -0700372
373 int message_type = dbus_message_get_type(message);
374 if (message_type != DBUS_MESSAGE_TYPE_SIGNAL) {
Darin Petkov41e06232010-05-03 16:45:37 -0700375 DLOG(WARNING) << "unexpected message type " << message_type;
Darin Petkov703ec972010-04-27 11:02:18 -0700376 return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
377 }
378
379 // Signal messages always have interfaces.
380 const char* interface = dbus_message_get_interface(message);
381 CHECK(interface != NULL);
382
383 MetricsDaemon* daemon = static_cast<MetricsDaemon*>(user_data);
384
385 DBusMessageIter iter;
386 dbus_message_iter_init(message, &iter);
Darin Petkov40f25732013-04-29 15:07:31 +0200387 if (strcmp(interface, kCrashReporterInterface) == 0) {
Darin Petkov1bb904e2010-06-16 15:58:06 -0700388 CHECK(strcmp(dbus_message_get_member(message),
Darin Petkov40f25732013-04-29 15:07:31 +0200389 kCrashReporterUserCrashSignal) == 0);
Darin Petkov1bb904e2010-06-16 15:58:06 -0700390 daemon->ProcessUserCrash();
Darin Petkov40f25732013-04-29 15:07:31 +0200391 } else if (strcmp(interface, power_manager::kPowerManagerInterface) == 0) {
Darin Petkov41e06232010-05-03 16:45:37 -0700392 CHECK(strcmp(dbus_message_get_member(message),
Darin Petkov40f25732013-04-29 15:07:31 +0200393 power_manager::kPowerStateChangedSignal) == 0);
David James3b3add52010-06-04 15:01:19 -0700394 char* state_name;
Darin Petkov41e06232010-05-03 16:45:37 -0700395 dbus_message_iter_get_basic(&iter, &state_name);
Darin Petkov40f25732013-04-29 15:07:31 +0200396 daemon->PowerStateChanged(state_name, now);
397 } else if (strcmp(interface, login_manager::kSessionManagerInterface) == 0) {
398 const char* member = dbus_message_get_member(message);
399 if (strcmp(member, login_manager::kScreenIsLockedSignal) == 0) {
400 daemon->SetUserActiveState(false, now);
401 } else if (strcmp(member, login_manager::kScreenIsUnlockedSignal) == 0) {
402 daemon->SetUserActiveState(true, now);
403 } else if (strcmp(member, login_manager::kSessionStateChangedSignal) == 0) {
404 char* state_name;
405 dbus_message_iter_get_basic(&iter, &state_name);
406 daemon->SessionStateChanged(state_name, now);
407 }
Darin Petkov703ec972010-04-27 11:02:18 -0700408 } else {
Darin Petkov41e06232010-05-03 16:45:37 -0700409 DLOG(WARNING) << "unexpected interface: " << interface;
Darin Petkov703ec972010-04-27 11:02:18 -0700410 return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
411 }
412
413 return DBUS_HANDLER_RESULT_HANDLED;
Darin Petkov65b01462010-04-14 13:32:20 -0700414}
415
Darin Petkovf27f0362010-06-04 13:14:19 -0700416void MetricsDaemon::PowerStateChanged(const char* state_name, Time now) {
Darin Petkov41e06232010-05-03 16:45:37 -0700417 DLOG(INFO) << "power state: " << state_name;
Darin Petkov703ec972010-04-27 11:02:18 -0700418 power_state_ = LookupPowerState(state_name);
Darin Petkov41e06232010-05-03 16:45:37 -0700419
420 if (power_state_ != kPowerStateOn)
421 SetUserActiveState(false, now);
Darin Petkov703ec972010-04-27 11:02:18 -0700422}
423
424MetricsDaemon::PowerState
425MetricsDaemon::LookupPowerState(const char* state_name) {
426 for (int i = 0; i < kNumberPowerStates; i++) {
Darin Petkov41e06232010-05-03 16:45:37 -0700427 if (strcmp(state_name, kPowerStates_[i]) == 0) {
Darin Petkov703ec972010-04-27 11:02:18 -0700428 return static_cast<PowerState>(i);
429 }
430 }
Darin Petkov41e06232010-05-03 16:45:37 -0700431 DLOG(WARNING) << "unknown power state: " << state_name;
Darin Petkov703ec972010-04-27 11:02:18 -0700432 return kUnknownPowerState;
Darin Petkov65b01462010-04-14 13:32:20 -0700433}
434
Darin Petkovf27f0362010-06-04 13:14:19 -0700435void MetricsDaemon::SessionStateChanged(const char* state_name, Time now) {
Darin Petkov41e06232010-05-03 16:45:37 -0700436 DLOG(INFO) << "user session state: " << state_name;
437 session_state_ = LookupSessionState(state_name);
438 SetUserActiveState(session_state_ == kSessionStateStarted, now);
439}
440
441MetricsDaemon::SessionState
442MetricsDaemon::LookupSessionState(const char* state_name) {
443 for (int i = 0; i < kNumberSessionStates; i++) {
444 if (strcmp(state_name, kSessionStates_[i]) == 0) {
445 return static_cast<SessionState>(i);
446 }
447 }
448 DLOG(WARNING) << "unknown user session state: " << state_name;
449 return kUnknownSessionState;
450}
451
Darin Petkovf27f0362010-06-04 13:14:19 -0700452void MetricsDaemon::SetUserActiveState(bool active, Time now) {
Darin Petkov41e06232010-05-03 16:45:37 -0700453 DLOG(INFO) << "user: " << (active ? "active" : "inactive");
454
455 // Calculates the seconds of active use since the last update and
Darin Petkovf27f0362010-06-04 13:14:19 -0700456 // the day since Epoch, and logs the usage data. Guards against the
457 // time jumping back and forth due to the user changing it by
458 // discarding the new use time.
459 int seconds = 0;
460 if (user_active_ && now > user_active_last_) {
461 TimeDelta since_active = now - user_active_last_;
462 if (since_active < TimeDelta::FromSeconds(
463 kUseMonitorIntervalMax + kSecondsPerMinute)) {
464 seconds = static_cast<int>(since_active.InSeconds());
465 }
466 }
467 TimeDelta since_epoch = now - Time();
468 int day = since_epoch.InDays();
Darin Petkovf1e85e42010-06-10 15:59:53 -0700469 daily_use_->Update(day, seconds);
Darin Petkov1bb904e2010-06-16 15:58:06 -0700470 user_crash_interval_->Update(0, seconds);
Darin Petkov38d5cb02010-06-24 12:10:26 -0700471 kernel_crash_interval_->Update(0, seconds);
Darin Petkov41e06232010-05-03 16:45:37 -0700472
Ken Mixter4c5daa42010-08-26 18:35:06 -0700473 // Flush finished cycles of all frequency counters.
474 for (FrequencyCounters::iterator i = frequency_counters_.begin();
475 i != frequency_counters_.end(); ++i) {
476 i->second->FlushFinishedCycles();
477 }
478
Darin Petkov41e06232010-05-03 16:45:37 -0700479 // Schedules a use monitor on inactive->active transitions and
480 // unschedules it on active->inactive transitions.
481 if (!user_active_ && active)
482 ScheduleUseMonitor(kUseMonitorIntervalInit, /* backoff */ false);
483 else if (user_active_ && !active)
484 UnscheduleUseMonitor();
485
486 // Remembers the current active state and the time of the last
487 // activity update.
488 user_active_ = active;
489 user_active_last_ = now;
490}
491
Darin Petkov1bb904e2010-06-16 15:58:06 -0700492void MetricsDaemon::ProcessUserCrash() {
493 // Counts the active use time up to now.
494 SetUserActiveState(user_active_, Time::Now());
495
496 // Reports the active use time since the last crash and resets it.
497 user_crash_interval_->Flush();
Ken Mixterccd84c02010-08-16 19:57:13 -0700498
Ken Mixter4c5daa42010-08-26 18:35:06 -0700499 frequency_counters_[kMetricUserCrashesDailyName]->Update(1);
500 frequency_counters_[kMetricUserCrashesWeeklyName]->Update(1);
501 frequency_counters_[kMetricAnyCrashesDailyName]->Update(1);
502 frequency_counters_[kMetricAnyCrashesWeeklyName]->Update(1);
Darin Petkov1bb904e2010-06-16 15:58:06 -0700503}
504
Darin Petkov38d5cb02010-06-24 12:10:26 -0700505void MetricsDaemon::ProcessKernelCrash() {
506 // Counts the active use time up to now.
507 SetUserActiveState(user_active_, Time::Now());
508
509 // Reports the active use time since the last crash and resets it.
510 kernel_crash_interval_->Flush();
Ken Mixterccd84c02010-08-16 19:57:13 -0700511
Ken Mixter4c5daa42010-08-26 18:35:06 -0700512 frequency_counters_[kMetricKernelCrashesDailyName]->Update(1);
513 frequency_counters_[kMetricKernelCrashesWeeklyName]->Update(1);
514 frequency_counters_[kMetricAnyCrashesDailyName]->Update(1);
515 frequency_counters_[kMetricAnyCrashesWeeklyName]->Update(1);
Darin Petkov38d5cb02010-06-24 12:10:26 -0700516}
517
Ken Mixterccd84c02010-08-16 19:57:13 -0700518void MetricsDaemon::ProcessUncleanShutdown() {
519 // Counts the active use time up to now.
520 SetUserActiveState(user_active_, Time::Now());
521
522 // Reports the active use time since the last crash and resets it.
523 unclean_shutdown_interval_->Flush();
524
Ken Mixter4c5daa42010-08-26 18:35:06 -0700525 frequency_counters_[kMetricUncleanShutdownsDailyName]->Update(1);
526 frequency_counters_[kMetricUncleanShutdownsWeeklyName]->Update(1);
527 frequency_counters_[kMetricAnyCrashesDailyName]->Update(1);
528 frequency_counters_[kMetricAnyCrashesWeeklyName]->Update(1);
Ken Mixterccd84c02010-08-16 19:57:13 -0700529}
530
Luigi Semenzato8accd332011-05-17 16:37:18 -0700531bool MetricsDaemon::CheckSystemCrash(const string& crash_file) {
Darin Petkov38d5cb02010-06-24 12:10:26 -0700532 FilePath crash_detected(crash_file);
Ben Chan2e6543d2014-02-05 23:26:25 -0800533 if (!base::PathExists(crash_detected))
Ken Mixterccd84c02010-08-16 19:57:13 -0700534 return false;
Darin Petkov38d5cb02010-06-24 12:10:26 -0700535
536 // Deletes the crash-detected file so that the daemon doesn't report
537 // another kernel crash in case it's restarted.
Ben Chan2e6543d2014-02-05 23:26:25 -0800538 base::DeleteFile(crash_detected,
539 false); // recursive
Ken Mixterccd84c02010-08-16 19:57:13 -0700540 return true;
Darin Petkov38d5cb02010-06-24 12:10:26 -0700541}
542
Darin Petkov41e06232010-05-03 16:45:37 -0700543// static
544gboolean MetricsDaemon::UseMonitorStatic(gpointer data) {
545 return static_cast<MetricsDaemon*>(data)->UseMonitor() ? TRUE : FALSE;
546}
547
548bool MetricsDaemon::UseMonitor() {
Darin Petkovf27f0362010-06-04 13:14:19 -0700549 SetUserActiveState(user_active_, Time::Now());
Darin Petkov41e06232010-05-03 16:45:37 -0700550
551 // If a new monitor source/instance is scheduled, returns false to
552 // tell GLib to destroy this monitor source/instance. Returns true
553 // otherwise to keep calling back this monitor.
554 return !ScheduleUseMonitor(usemon_interval_ * 2, /* backoff */ true);
555}
556
557bool MetricsDaemon::ScheduleUseMonitor(int interval, bool backoff)
558{
Darin Petkov2ccef012010-05-05 16:06:37 -0700559 if (testing_)
560 return false;
561
Darin Petkov41e06232010-05-03 16:45:37 -0700562 // Caps the interval -- the bigger the interval, the more active use
563 // time will be potentially dropped on system shutdown.
564 if (interval > kUseMonitorIntervalMax)
565 interval = kUseMonitorIntervalMax;
566
567 if (backoff) {
568 // Back-off mode is used by the use monitor to reschedule itself
569 // with exponential back-off in time. This mode doesn't create a
570 // new timeout source if the new interval is the same as the old
571 // one. Also, if a new timeout source is created, the old one is
572 // not destroyed explicitly here -- it will be destroyed by GLib
573 // when the monitor returns FALSE (see UseMonitor and
574 // UseMonitorStatic).
575 if (interval == usemon_interval_)
576 return false;
577 } else {
578 UnscheduleUseMonitor();
579 }
580
581 // Schedules a new use monitor for |interval| seconds from now.
582 DLOG(INFO) << "scheduling use monitor in " << interval << " seconds";
583 usemon_source_ = g_timeout_source_new_seconds(interval);
584 g_source_set_callback(usemon_source_, UseMonitorStatic, this,
585 NULL); // No destroy notification.
586 g_source_attach(usemon_source_,
587 NULL); // Default context.
588 usemon_interval_ = interval;
589 return true;
590}
591
592void MetricsDaemon::UnscheduleUseMonitor() {
593 // If there's a use monitor scheduled already, destroys it.
594 if (usemon_source_ == NULL)
595 return;
596
597 DLOG(INFO) << "destroying use monitor";
598 g_source_destroy(usemon_source_);
599 usemon_source_ = NULL;
600 usemon_interval_ = 0;
601}
602
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700603void MetricsDaemon::StatsReporterInit() {
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800604 DiskStatsReadStats(&read_sectors_, &write_sectors_);
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700605 VmStatsReadStats(&vmstats_);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800606 // The first time around just run the long stat, so we don't delay boot.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700607 stats_state_ = kStatsLong;
608 stats_initial_time_ = GetActiveTime();
609 if (stats_initial_time_ < 0) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700610 LOG(WARNING) << "not collecting disk stats";
611 } else {
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700612 ScheduleStatsCallback(kMetricStatsLongInterval);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700613 }
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800614}
615
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700616void MetricsDaemon::ScheduleStatsCallback(int wait) {
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800617 if (testing_) {
618 return;
619 }
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700620 g_timeout_add_seconds(wait, StatsCallbackStatic, this);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800621}
622
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700623bool MetricsDaemon::DiskStatsReadStats(long int* read_sectors,
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800624 long int* write_sectors) {
625 int nchars;
626 int nitems;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700627 bool success = false;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800628 char line[200];
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700629 if (diskstats_path_.empty()) {
630 return false;
631 }
Luigi Semenzato0f132bb2011-02-28 11:17:43 -0800632 int file = HANDLE_EINTR(open(diskstats_path_.c_str(), O_RDONLY));
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800633 if (file < 0) {
634 PLOG(WARNING) << "cannot open " << diskstats_path_;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700635 return false;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800636 }
637 nchars = HANDLE_EINTR(read(file, line, sizeof(line)));
638 if (nchars < 0) {
639 PLOG(WARNING) << "cannot read from " << diskstats_path_;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700640 return false;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800641 } else {
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700642 LOG_IF(WARNING, nchars == sizeof(line))
643 << "line too long in " << diskstats_path_;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800644 line[nchars] = '\0';
645 nitems = sscanf(line, "%*d %*d %ld %*d %*d %*d %ld",
646 read_sectors, write_sectors);
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700647 if (nitems == 2) {
648 success = true;
649 } else {
650 LOG(WARNING) << "found " << nitems << " items in "
651 << diskstats_path_ << ", expected 2";
652 }
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800653 }
654 HANDLE_EINTR(close(file));
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700655 return success;
656}
657
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700658bool MetricsDaemon::VmStatsParseStats(const char* stats,
659 struct VmstatRecord* record) {
660 // a mapping of string name to field in VmstatRecord and whether we found it
661 struct mapping {
662 const string name;
663 uint64_t* value_p;
664 bool found;
665 } map[] =
666 { { .name = "pgmajfault",
667 .value_p = &record->page_faults_,
668 .found = false },
669 { .name = "pswpin",
670 .value_p = &record->swap_in_,
671 .found = false },
672 { .name = "pswpout",
673 .value_p = &record->swap_out_,
674 .found = false }, };
675
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700676 // Each line in the file has the form
677 // <ID> <VALUE>
678 // for instance:
679 // nr_free_pages 213427
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700680 vector<string> lines;
681 Tokenize(stats, "\n", &lines);
682 for (vector<string>::iterator it = lines.begin();
683 it != lines.end(); ++it) {
684 vector<string> tokens;
685 base::SplitString(*it, ' ', &tokens);
686 if (tokens.size() == 2) {
687 for (unsigned int i = 0; i < sizeof(map)/sizeof(struct mapping); i++) {
688 if (!tokens[0].compare(map[i].name)) {
689 if (!base::StringToUint64(tokens[1], map[i].value_p))
690 return false;
691 map[i].found = true;
692 }
693 }
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700694 } else {
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700695 LOG(WARNING) << "unexpected vmstat format";
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700696 }
697 }
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700698 // make sure we got all the stats
699 for (unsigned i = 0; i < sizeof(map)/sizeof(struct mapping); i++) {
700 if (map[i].found == false) {
701 LOG(WARNING) << "vmstat missing " << map[i].name;
702 return false;
703 }
704 }
705 return true;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700706}
707
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700708bool MetricsDaemon::VmStatsReadStats(struct VmstatRecord* stats) {
709 string value_string;
710 FilePath* path = new FilePath(vmstats_path_);
Ben Chan2e6543d2014-02-05 23:26:25 -0800711 if (!base::ReadFileToString(*path, &value_string)) {
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700712 delete path;
713 LOG(WARNING) << "cannot read " << vmstats_path_;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700714 return false;
715 }
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700716 delete path;
717 return VmStatsParseStats(value_string.c_str(), stats);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800718}
719
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700720bool MetricsDaemon::ReadFreqToInt(const string& sysfs_file_name, int* value) {
Luigi Semenzatod92d18c2013-06-04 13:24:21 -0700721 const FilePath sysfs_path(sysfs_file_name);
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700722 string value_string;
Ben Chan2e6543d2014-02-05 23:26:25 -0800723 if (!base::ReadFileToString(sysfs_path, &value_string)) {
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700724 LOG(WARNING) << "cannot read " << sysfs_path.value().c_str();
725 return false;
726 }
Ben Chan2e6543d2014-02-05 23:26:25 -0800727 if (!base::RemoveChars(value_string, "\n", &value_string)) {
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700728 LOG(WARNING) << "no newline in " << value_string;
729 // Continue even though the lack of newline is suspicious.
730 }
731 if (!base::StringToInt(value_string, value)) {
732 LOG(WARNING) << "cannot convert " << value_string << " to int";
733 return false;
734 }
735 return true;
736}
737
738void MetricsDaemon::SendCpuThrottleMetrics() {
739 // |max_freq| is 0 only the first time through.
740 static int max_freq = 0;
741 if (max_freq == -1)
742 // Give up, as sysfs did not report max_freq correctly.
743 return;
744 if (max_freq == 0 || testing_) {
745 // One-time initialization of max_freq. (Every time when testing.)
746 if (!ReadFreqToInt(cpuinfo_max_freq_path_, &max_freq)) {
747 max_freq = -1;
748 return;
749 }
750 if (max_freq == 0) {
751 LOG(WARNING) << "sysfs reports 0 max CPU frequency\n";
752 max_freq = -1;
753 return;
754 }
755 if (max_freq % 10000 == 1000) {
756 // Special case: system has turbo mode, and max non-turbo frequency is
757 // max_freq - 1000. This relies on "normal" (non-turbo) frequencies
758 // being multiples of (at least) 10 MHz. Although there is no guarantee
759 // of this, it seems a fairly reasonable assumption. Otherwise we should
760 // read scaling_available_frequencies, sort the frequencies, compare the
761 // two highest ones, and check if they differ by 1000 (kHz) (and that's a
762 // hack too, no telling when it will change).
763 max_freq -= 1000;
764 }
765 }
766 int scaled_freq = 0;
767 if (!ReadFreqToInt(scaling_max_freq_path_, &scaled_freq))
768 return;
769 // Frequencies are in kHz. If scaled_freq > max_freq, turbo is on, but
770 // scaled_freq is not the actual turbo frequency. We indicate this situation
771 // with a 101% value.
772 int percent = scaled_freq > max_freq ? 101 : scaled_freq / (max_freq / 100);
773 SendLinearMetric(kMetricScaledCpuFrequencyName, percent, 101, 102);
774}
775
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800776// static
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700777gboolean MetricsDaemon::StatsCallbackStatic(void* handle) {
778 (static_cast<MetricsDaemon*>(handle))->StatsCallback();
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800779 return false; // one-time callback
780}
781
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700782// Collects disk and vm stats alternating over a short and a long interval.
Luigi Semenzato8accd332011-05-17 16:37:18 -0700783
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700784void MetricsDaemon::StatsCallback() {
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700785 long int read_sectors_now, write_sectors_now;
786 struct VmstatRecord vmstats_now;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700787 double time_now = GetActiveTime();
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700788 double delta_time = time_now - stats_initial_time_;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700789 if (testing_) {
790 // Fake the time when testing.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700791 delta_time = stats_state_ == kStatsShort ?
792 kMetricStatsShortInterval : kMetricStatsLongInterval;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700793 }
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700794 bool diskstats_success = DiskStatsReadStats(&read_sectors_now,
795 &write_sectors_now);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700796 int delta_read = read_sectors_now - read_sectors_;
797 int delta_write = write_sectors_now - write_sectors_;
798 int read_sectors_per_second = delta_read / delta_time;
799 int write_sectors_per_second = delta_write / delta_time;
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700800 bool vmstats_success = VmStatsReadStats(&vmstats_now);
801 uint64_t delta_faults = vmstats_now.page_faults_ - vmstats_.page_faults_;
802 uint64_t delta_swap_in = vmstats_now.swap_in_ - vmstats_.swap_in_;
803 uint64_t delta_swap_out = vmstats_now.swap_out_ - vmstats_.swap_out_;
804 uint64_t page_faults_per_second = delta_faults / delta_time;
805 uint64_t swap_in_per_second = delta_swap_in / delta_time;
806 uint64_t swap_out_per_second = delta_swap_out / delta_time;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800807
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700808 switch (stats_state_) {
809 case kStatsShort:
810 if (diskstats_success) {
811 SendMetric(kMetricReadSectorsShortName,
812 read_sectors_per_second,
813 1,
814 kMetricSectorsIOMax,
815 kMetricSectorsBuckets);
816 SendMetric(kMetricWriteSectorsShortName,
817 write_sectors_per_second,
818 1,
819 kMetricSectorsIOMax,
820 kMetricSectorsBuckets);
821 }
822 if (vmstats_success) {
823 SendMetric(kMetricPageFaultsShortName,
824 page_faults_per_second,
825 1,
826 kMetricPageFaultsMax,
827 kMetricPageFaultsBuckets);
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700828 SendMetric(kMetricSwapInShortName,
829 swap_in_per_second,
830 1,
831 kMetricPageFaultsMax,
832 kMetricPageFaultsBuckets);
833 SendMetric(kMetricSwapOutShortName,
834 swap_out_per_second,
835 1,
836 kMetricPageFaultsMax,
837 kMetricPageFaultsBuckets);
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700838 }
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800839 // Schedule long callback.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700840 stats_state_ = kStatsLong;
841 ScheduleStatsCallback(kMetricStatsLongInterval -
842 kMetricStatsShortInterval);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800843 break;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700844 case kStatsLong:
845 if (diskstats_success) {
846 SendMetric(kMetricReadSectorsLongName,
847 read_sectors_per_second,
848 1,
849 kMetricSectorsIOMax,
850 kMetricSectorsBuckets);
851 SendMetric(kMetricWriteSectorsLongName,
852 write_sectors_per_second,
853 1,
854 kMetricSectorsIOMax,
855 kMetricSectorsBuckets);
856 // Reset sector counters.
857 read_sectors_ = read_sectors_now;
858 write_sectors_ = write_sectors_now;
859 }
860 if (vmstats_success) {
861 SendMetric(kMetricPageFaultsLongName,
862 page_faults_per_second,
863 1,
864 kMetricPageFaultsMax,
865 kMetricPageFaultsBuckets);
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700866 SendMetric(kMetricSwapInLongName,
867 swap_in_per_second,
868 1,
869 kMetricPageFaultsMax,
870 kMetricPageFaultsBuckets);
871 SendMetric(kMetricSwapOutLongName,
872 swap_out_per_second,
873 1,
874 kMetricPageFaultsMax,
875 kMetricPageFaultsBuckets);
876
877 vmstats_ = vmstats_now;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700878 }
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700879 SendCpuThrottleMetrics();
Luigi Semenzato8accd332011-05-17 16:37:18 -0700880 // Set start time for new cycle.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700881 stats_initial_time_ = time_now;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800882 // Schedule short callback.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700883 stats_state_ = kStatsShort;
884 ScheduleStatsCallback(kMetricStatsShortInterval);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800885 break;
886 default:
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700887 LOG(FATAL) << "Invalid stats state";
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800888 }
889}
890
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700891void MetricsDaemon::ScheduleMeminfoCallback(int wait) {
892 if (testing_) {
893 return;
894 }
895 g_timeout_add_seconds(wait, MeminfoCallbackStatic, this);
896}
897
898// static
899gboolean MetricsDaemon::MeminfoCallbackStatic(void* handle) {
900 return (static_cast<MetricsDaemon*>(handle))->MeminfoCallback();
901}
902
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700903bool MetricsDaemon::MeminfoCallback() {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700904 string meminfo_raw;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700905 const FilePath meminfo_path("/proc/meminfo");
Ben Chan2e6543d2014-02-05 23:26:25 -0800906 if (!base::ReadFileToString(meminfo_path, &meminfo_raw)) {
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700907 LOG(WARNING) << "cannot read " << meminfo_path.value().c_str();
908 return false;
909 }
Luigi Semenzato8accd332011-05-17 16:37:18 -0700910 return ProcessMeminfo(meminfo_raw);
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700911}
912
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700913bool MetricsDaemon::ProcessMeminfo(const string& meminfo_raw) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700914 static const MeminfoRecord fields_array[] = {
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700915 { "MemTotal", "MemTotal" }, // SPECIAL CASE: total system memory
916 { "MemFree", "MemFree" },
917 { "Buffers", "Buffers" },
918 { "Cached", "Cached" },
919 // { "SwapCached", "SwapCached" },
920 { "Active", "Active" },
921 { "Inactive", "Inactive" },
922 { "ActiveAnon", "Active(anon)" },
923 { "InactiveAnon", "Inactive(anon)" },
924 { "ActiveFile" , "Active(file)" },
925 { "InactiveFile", "Inactive(file)" },
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800926 { "Unevictable", "Unevictable", kMeminfoOp_HistLog },
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700927 // { "Mlocked", "Mlocked" },
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800928 { "SwapTotal", "SwapTotal", kMeminfoOp_SwapTotal },
929 { "SwapFree", "SwapFree", kMeminfoOp_SwapFree },
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700930 // { "Dirty", "Dirty" },
931 // { "Writeback", "Writeback" },
932 { "AnonPages", "AnonPages" },
933 { "Mapped", "Mapped" },
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800934 { "Shmem", "Shmem", kMeminfoOp_HistLog },
935 { "Slab", "Slab", kMeminfoOp_HistLog },
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700936 // { "SReclaimable", "SReclaimable" },
937 // { "SUnreclaim", "SUnreclaim" },
938 };
Luigi Semenzato8accd332011-05-17 16:37:18 -0700939 vector<MeminfoRecord> fields(fields_array,
940 fields_array + arraysize(fields_array));
941 if (!FillMeminfo(meminfo_raw, &fields)) {
942 return false;
943 }
944 int total_memory = fields[0].value;
945 if (total_memory == 0) {
946 // this "cannot happen"
947 LOG(WARNING) << "borked meminfo parser";
948 return false;
949 }
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800950 int swap_total = 0;
951 int swap_free = 0;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700952 // Send all fields retrieved, except total memory.
953 for (unsigned int i = 1; i < fields.size(); i++) {
954 string metrics_name = StringPrintf("Platform.Meminfo%s", fields[i].name);
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800955 int percent;
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800956 switch (fields[i].op) {
957 case kMeminfoOp_HistPercent:
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800958 // report value as percent of total memory
959 percent = fields[i].value * 100 / total_memory;
960 SendLinearMetric(metrics_name, percent, 100, 101);
961 break;
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800962 case kMeminfoOp_HistLog:
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800963 // report value in kbytes, log scale, 4Gb max
964 SendMetric(metrics_name, fields[i].value, 1, 4 * 1000 * 1000, 100);
965 break;
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800966 case kMeminfoOp_SwapTotal:
967 swap_total = fields[i].value;
968 case kMeminfoOp_SwapFree:
969 swap_free = fields[i].value;
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800970 break;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700971 }
972 }
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800973 if (swap_total > 0) {
974 int swap_used = swap_total - swap_free;
975 int swap_used_percent = swap_used * 100 / swap_total;
976 SendMetric("Platform.MeminfoSwapUsed", swap_used, 1, 8 * 1000 * 1000, 100);
977 SendLinearMetric("Platform.MeminfoSwapUsedPercent", swap_used_percent,
978 100, 101);
979 }
Luigi Semenzato8accd332011-05-17 16:37:18 -0700980 return true;
981}
982
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700983bool MetricsDaemon::FillMeminfo(const string& meminfo_raw,
984 vector<MeminfoRecord>* fields) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700985 vector<string> lines;
986 unsigned int nlines = Tokenize(meminfo_raw, "\n", &lines);
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700987
988 // Scan meminfo output and collect field values. Each field name has to
989 // match a meminfo entry (case insensitive) after removing non-alpha
990 // characters from the entry.
Luigi Semenzato8accd332011-05-17 16:37:18 -0700991 unsigned int ifield = 0;
992 for (unsigned int iline = 0;
993 iline < nlines && ifield < fields->size();
994 iline++) {
995 vector<string> tokens;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700996 Tokenize(lines[iline], ": ", &tokens);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700997 if (strcmp((*fields)[ifield].match, tokens[0].c_str()) == 0) {
998 // Name matches. Parse value and save.
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700999 char* rest;
Luigi Semenzato8accd332011-05-17 16:37:18 -07001000 (*fields)[ifield].value =
1001 static_cast<int>(strtol(tokens[1].c_str(), &rest, 10));
Luigi Semenzato29c7ef92011-04-12 14:12:35 -07001002 if (*rest != '\0') {
1003 LOG(WARNING) << "missing meminfo value";
1004 return false;
1005 }
Luigi Semenzato8accd332011-05-17 16:37:18 -07001006 ifield++;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -07001007 }
Luigi Semenzato29c7ef92011-04-12 14:12:35 -07001008 }
Luigi Semenzato8accd332011-05-17 16:37:18 -07001009 if (ifield < fields->size()) {
1010 // End of input reached while scanning.
1011 LOG(WARNING) << "cannot find field " << (*fields)[ifield].match
1012 << " and following";
1013 return false;
1014 }
1015 return true;
1016}
1017
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -08001018void MetricsDaemon::ScheduleMemuseCallback(double interval) {
Luigi Semenzato8accd332011-05-17 16:37:18 -07001019 if (testing_) {
1020 return;
1021 }
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -08001022 g_timeout_add_seconds(interval, MemuseCallbackStatic, this);
Luigi Semenzato8accd332011-05-17 16:37:18 -07001023}
1024
1025// static
1026gboolean MetricsDaemon::MemuseCallbackStatic(void* handle) {
1027 MetricsDaemon* daemon = static_cast<MetricsDaemon*>(handle);
1028 daemon->MemuseCallback();
1029 return false;
1030}
1031
1032void MetricsDaemon::MemuseCallback() {
1033 // Since we only care about active time (i.e. uptime minus sleep time) but
1034 // the callbacks are driven by real time (uptime), we check if we should
1035 // reschedule this callback due to intervening sleep periods.
1036 double now = GetActiveTime();
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -08001037 // Avoid intervals of less than one second.
1038 double remaining_time = ceil(memuse_final_time_ - now);
1039 if (remaining_time > 0) {
1040 ScheduleMemuseCallback(remaining_time);
Luigi Semenzato8accd332011-05-17 16:37:18 -07001041 } else {
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -08001042 // Report stats and advance the measurement interval unless there are
1043 // errors or we've completed the last interval.
Luigi Semenzato8accd332011-05-17 16:37:18 -07001044 if (MemuseCallbackWork() &&
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -08001045 memuse_interval_index_ < arraysize(kMemuseIntervals)) {
1046 double interval = kMemuseIntervals[memuse_interval_index_++];
1047 memuse_final_time_ = now + interval;
1048 ScheduleMemuseCallback(interval);
Luigi Semenzato8accd332011-05-17 16:37:18 -07001049 }
1050 }
1051}
1052
Luigi Semenzato5bd764f2011-10-14 12:03:35 -07001053bool MetricsDaemon::MemuseCallbackWork() {
Luigi Semenzato8accd332011-05-17 16:37:18 -07001054 string meminfo_raw;
1055 const FilePath meminfo_path("/proc/meminfo");
Ben Chan2e6543d2014-02-05 23:26:25 -08001056 if (!base::ReadFileToString(meminfo_path, &meminfo_raw)) {
Luigi Semenzato8accd332011-05-17 16:37:18 -07001057 LOG(WARNING) << "cannot read " << meminfo_path.value().c_str();
1058 return false;
1059 }
1060 return ProcessMemuse(meminfo_raw);
1061}
1062
Luigi Semenzato5bd764f2011-10-14 12:03:35 -07001063bool MetricsDaemon::ProcessMemuse(const string& meminfo_raw) {
Luigi Semenzato8accd332011-05-17 16:37:18 -07001064 static const MeminfoRecord fields_array[] = {
1065 { "MemTotal", "MemTotal" }, // SPECIAL CASE: total system memory
1066 { "ActiveAnon", "Active(anon)" },
1067 { "InactiveAnon", "Inactive(anon)" },
1068 };
1069 vector<MeminfoRecord> fields(fields_array,
1070 fields_array + arraysize(fields_array));
1071 if (!FillMeminfo(meminfo_raw, &fields)) {
1072 return false;
1073 }
1074 int total = fields[0].value;
1075 int active_anon = fields[1].value;
1076 int inactive_anon = fields[2].value;
1077 if (total == 0) {
1078 // this "cannot happen"
1079 LOG(WARNING) << "borked meminfo parser";
1080 return false;
1081 }
1082 string metrics_name = StringPrintf("Platform.MemuseAnon%d",
1083 memuse_interval_index_);
1084 SendLinearMetric(metrics_name, (active_anon + inactive_anon) * 100 / total,
1085 100, 101);
1086 return true;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -07001087}
1088
Darin Petkovf1e85e42010-06-10 15:59:53 -07001089// static
Ken Mixterccd84c02010-08-16 19:57:13 -07001090void MetricsDaemon::ReportDailyUse(void* handle, int tag, int count) {
Darin Petkov1bb904e2010-06-16 15:58:06 -07001091 if (count <= 0)
1092 return;
1093
Darin Petkovf1e85e42010-06-10 15:59:53 -07001094 MetricsDaemon* daemon = static_cast<MetricsDaemon*>(handle);
1095 int minutes = (count + kSecondsPerMinute / 2) / kSecondsPerMinute;
1096 daemon->SendMetric(kMetricDailyUseTimeName, minutes,
1097 kMetricDailyUseTimeMin,
1098 kMetricDailyUseTimeMax,
1099 kMetricDailyUseTimeBuckets);
1100}
1101
Darin Petkov38d5cb02010-06-24 12:10:26 -07001102void MetricsDaemon::SendMetric(const string& name, int sample,
Darin Petkov11b8eb32010-05-18 11:00:59 -07001103 int min, int max, int nbuckets) {
Darin Petkovfc91b422010-05-12 13:05:45 -07001104 DLOG(INFO) << "received metric: " << name << " " << sample << " "
1105 << min << " " << max << " " << nbuckets;
1106 metrics_lib_->SendToUMA(name, sample, min, max, nbuckets);
Darin Petkov65b01462010-04-14 13:32:20 -07001107}
Luigi Semenzato29c7ef92011-04-12 14:12:35 -07001108
1109void MetricsDaemon::SendLinearMetric(const string& name, int sample,
1110 int max, int nbuckets) {
1111 DLOG(INFO) << "received linear metric: " << name << " " << sample << " "
1112 << max << " " << nbuckets;
1113 // TODO(semenzato): add a proper linear histogram to the Chrome external
1114 // metrics API.
1115 LOG_IF(FATAL, nbuckets != max + 1) << "unsupported histogram scale";
1116 metrics_lib_->SendEnumToUMA(name, sample, max);
1117}