blob: c0c77faeafd86eb1c79c33dfa99de89085f6de71 [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
Luigi Semenzato4a6c9422014-06-30 18:12:28 -07005// For PRIu64 in inttypes.h, used by scanf. TODO(semenzato): replace
6// with libchromeos methods.
7#define __STDC_FORMAT_MACROS
8
9#include "metrics/metrics_daemon.h"
Darin Petkov65b01462010-04-14 13:32:20 -070010
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -080011#include <fcntl.h>
Luigi Semenzato4a6c9422014-06-30 18:12:28 -070012#include <inttypes.h>
Luigi Semenzato8accd332011-05-17 16:37:18 -070013#include <math.h>
Ken Mixter4c5daa42010-08-26 18:35:06 -070014#include <string.h>
Luigi Semenzato8accd332011-05-17 16:37:18 -070015#include <time.h>
Darin Petkov65b01462010-04-14 13:32:20 -070016
Luigi Semenzato859b3f02014-02-05 15:33:19 -080017#include <base/files/file_path.h>
Ben Chan51bf92a2014-09-05 08:21:06 -070018#include <base/files/file_util.h>
Luigi Semenzato859b3f02014-02-05 15:33:19 -080019#include <base/hash.h>
Darin Petkov65b01462010-04-14 13:32:20 -070020#include <base/logging.h>
Ben Chan2e6543d2014-02-05 23:26:25 -080021#include <base/strings/string_number_conversions.h>
22#include <base/strings/string_split.h>
23#include <base/strings/string_util.h>
24#include <base/strings/stringprintf.h>
Luigi Semenzato859b3f02014-02-05 15:33:19 -080025#include <base/sys_info.h>
Darin Petkov40f25732013-04-29 15:07:31 +020026#include <chromeos/dbus/service_constants.h>
Ken Mixter4c5daa42010-08-26 18:35:06 -070027#include <dbus/dbus-glib-lowlevel.h>
Bertrand SIMONNET46b49da2014-06-25 14:38:07 -070028#include "uploader/upload_service.h"
Darin Petkov65b01462010-04-14 13:32:20 -070029
Ben Chan2e6543d2014-02-05 23:26:25 -080030using base::FilePath;
31using base::StringPrintf;
Darin Petkovf27f0362010-06-04 13:14:19 -070032using base::Time;
33using base::TimeDelta;
34using base::TimeTicks;
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -080035using chromeos_metrics::PersistentInteger;
Luigi Semenzato8accd332011-05-17 16:37:18 -070036using std::map;
Darin Petkov38d5cb02010-06-24 12:10:26 -070037using std::string;
Luigi Semenzato8accd332011-05-17 16:37:18 -070038using std::vector;
39
Daniel Eratc83975a2014-04-04 08:53:44 -070040namespace {
Darin Petkovf27f0362010-06-04 13:14:19 -070041
Darin Petkov703ec972010-04-27 11:02:18 -070042#define SAFE_MESSAGE(e) (e.message ? e.message : "unknown error")
Darin Petkov40f25732013-04-29 15:07:31 +020043
Daniel Eratc83975a2014-04-04 08:53:44 -070044const char kCrashReporterInterface[] = "org.chromium.CrashReporter";
45const char kCrashReporterUserCrashSignal[] = "UserCrash";
Darin Petkov41e06232010-05-03 16:45:37 -070046
Daniel Eratc83975a2014-04-04 08:53:44 -070047const int kSecondsPerMinute = 60;
48const int kMinutesPerHour = 60;
49const int kHoursPerDay = 24;
50const int kMinutesPerDay = kHoursPerDay * kMinutesPerHour;
51const int kSecondsPerDay = kSecondsPerMinute * kMinutesPerDay;
52const int kDaysPerWeek = 7;
53const int kSecondsPerWeek = kSecondsPerDay * kDaysPerWeek;
Darin Petkov41e06232010-05-03 16:45:37 -070054
Daniel Eratc83975a2014-04-04 08:53:44 -070055// Interval between calls to UpdateStats().
56const guint kUpdateStatsIntervalMs = 300000;
Darin Petkov65b01462010-04-14 13:32:20 -070057
Luigi Semenzatoc5a92342014-02-14 15:05:51 -080058const char kKernelCrashDetectedFile[] = "/var/run/kernel-crash-detected";
Daniel Eratc83975a2014-04-04 08:53:44 -070059const char kUncleanShutdownDetectedFile[] =
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -080060 "/var/run/unclean-shutdown-detected";
Ken Mixterccd84c02010-08-16 19:57:13 -070061
Daniel Eratc83975a2014-04-04 08:53:44 -070062} // namespace
63
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -080064// disk stats metrics
65
66// The {Read,Write}Sectors numbers are in sectors/second.
67// A sector is usually 512 bytes.
68
69const char MetricsDaemon::kMetricReadSectorsLongName[] =
70 "Platform.ReadSectorsLong";
71const char MetricsDaemon::kMetricWriteSectorsLongName[] =
72 "Platform.WriteSectorsLong";
73const char MetricsDaemon::kMetricReadSectorsShortName[] =
74 "Platform.ReadSectorsShort";
75const char MetricsDaemon::kMetricWriteSectorsShortName[] =
76 "Platform.WriteSectorsShort";
77
Luigi Semenzato5bd764f2011-10-14 12:03:35 -070078const int MetricsDaemon::kMetricStatsShortInterval = 1; // seconds
79const int MetricsDaemon::kMetricStatsLongInterval = 30; // seconds
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -080080
Luigi Semenzato29c7ef92011-04-12 14:12:35 -070081const int MetricsDaemon::kMetricMeminfoInterval = 30; // seconds
82
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -080083// Assume a max rate of 250Mb/s for reads (worse for writes) and 512 byte
84// sectors.
85const int MetricsDaemon::kMetricSectorsIOMax = 500000; // sectors/second
86const int MetricsDaemon::kMetricSectorsBuckets = 50; // buckets
Luigi Semenzato5bd764f2011-10-14 12:03:35 -070087// Page size is 4k, sector size is 0.5k. We're not interested in page fault
88// rates that the disk cannot sustain.
89const int MetricsDaemon::kMetricPageFaultsMax = kMetricSectorsIOMax / 8;
90const int MetricsDaemon::kMetricPageFaultsBuckets = 50;
91
92// Major page faults, i.e. the ones that require data to be read from disk.
93
94const char MetricsDaemon::kMetricPageFaultsLongName[] =
95 "Platform.PageFaultsLong";
96const char MetricsDaemon::kMetricPageFaultsShortName[] =
97 "Platform.PageFaultsShort";
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -080098
Sonny Rao4b8aebb2013-07-31 23:18:31 -070099// Swap in and Swap out
100
101const char MetricsDaemon::kMetricSwapInLongName[] =
102 "Platform.SwapInLong";
103const char MetricsDaemon::kMetricSwapInShortName[] =
104 "Platform.SwapInShort";
105
106const char MetricsDaemon::kMetricSwapOutLongName[] =
107 "Platform.SwapOutLong";
108const char MetricsDaemon::kMetricSwapOutShortName[] =
109 "Platform.SwapOutShort";
110
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700111const char MetricsDaemon::kMetricsProcStatFileName[] = "/proc/stat";
112const int MetricsDaemon::kMetricsProcStatFirstLineItemsCount = 11;
113
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700114// Thermal CPU throttling.
115
116const char MetricsDaemon::kMetricScaledCpuFrequencyName[] =
117 "Platform.CpuFrequencyThermalScaling";
118
Luigi Semenzato96360192014-06-04 10:53:35 -0700119// Zram sysfs entries.
120
121const char MetricsDaemon::kComprDataSizeName[] = "compr_data_size";
122const char MetricsDaemon::kOrigDataSizeName[] = "orig_data_size";
123const char MetricsDaemon::kZeroPagesName[] = "zero_pages";
124
Luigi Semenzato8accd332011-05-17 16:37:18 -0700125// Memory use stats collection intervals. We collect some memory use interval
126// at these intervals after boot, and we stop collecting after the last one,
127// with the assumption that in most cases the memory use won't change much
128// after that.
129static const int kMemuseIntervals[] = {
130 1 * kSecondsPerMinute, // 1 minute mark
131 4 * kSecondsPerMinute, // 5 minute mark
132 25 * kSecondsPerMinute, // 0.5 hour mark
133 120 * kSecondsPerMinute, // 2.5 hour mark
134 600 * kSecondsPerMinute, // 12.5 hour mark
135};
136
Darin Petkovf1e85e42010-06-10 15:59:53 -0700137MetricsDaemon::MetricsDaemon()
Daniel Eratc83975a2014-04-04 08:53:44 -0700138 : update_stats_timeout_id_(-1),
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800139 memuse_final_time_(0),
Luigi Semenzato8accd332011-05-17 16:37:18 -0700140 memuse_interval_index_(0),
141 read_sectors_(0),
142 write_sectors_(0),
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700143 vmstats_(),
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700144 stats_state_(kStatsShort),
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700145 stats_initial_time_(0),
146 ticks_per_second_(0),
147 latest_cpu_use_ticks_(0) {}
Darin Petkovf1e85e42010-06-10 15:59:53 -0700148
Ken Mixter4c5daa42010-08-26 18:35:06 -0700149MetricsDaemon::~MetricsDaemon() {
Daniel Eratc83975a2014-04-04 08:53:44 -0700150 if (update_stats_timeout_id_ > -1)
151 g_source_remove(update_stats_timeout_id_);
Ken Mixter4c5daa42010-08-26 18:35:06 -0700152}
153
Luigi Semenzato8accd332011-05-17 16:37:18 -0700154double MetricsDaemon::GetActiveTime() {
155 struct timespec ts;
156 int r = clock_gettime(CLOCK_MONOTONIC, &ts);
157 if (r < 0) {
158 PLOG(WARNING) << "clock_gettime(CLOCK_MONOTONIC) failed";
159 return 0;
160 } else {
Luigi Semenzato4a6c9422014-06-30 18:12:28 -0700161 return ts.tv_sec + static_cast<double>(ts.tv_nsec) / (1000 * 1000 * 1000);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700162 }
163}
164
Darin Petkov2ccef012010-05-05 16:06:37 -0700165void MetricsDaemon::Run(bool run_as_daemon) {
Darin Petkov38d5cb02010-06-24 12:10:26 -0700166 if (run_as_daemon && daemon(0, 0) != 0)
167 return;
168
Ken Mixterccd84c02010-08-16 19:57:13 -0700169 if (CheckSystemCrash(kKernelCrashDetectedFile)) {
170 ProcessKernelCrash();
171 }
172
173 if (CheckSystemCrash(kUncleanShutdownDetectedFile)) {
174 ProcessUncleanShutdown();
175 }
176
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800177 // On OS version change, clear version stats (which are reported daily).
Ben Chanf05ab402014-08-07 00:54:59 -0700178 int32_t version = GetOsVersionHash();
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800179 if (version_cycle_->Get() != version) {
180 version_cycle_->Set(version);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800181 kernel_crashes_version_count_->Set(0);
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -0700182 version_cumulative_active_use_->Set(0);
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700183 version_cumulative_cpu_use_->Set(0);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800184 }
185
Darin Petkov38d5cb02010-06-24 12:10:26 -0700186 Loop();
Darin Petkov65b01462010-04-14 13:32:20 -0700187}
188
Bertrand SIMONNET46b49da2014-06-25 14:38:07 -0700189void MetricsDaemon::RunUploaderTest() {
Bertrand SIMONNETeb815be2014-09-11 07:38:17 -0700190 upload_service_.reset(new UploadService(testing_));
191 upload_service_->Init();
Bertrand SIMONNET46b49da2014-06-25 14:38:07 -0700192 upload_service_->UploadEvent();
193}
194
Ben Chanf05ab402014-08-07 00:54:59 -0700195uint32_t MetricsDaemon::GetOsVersionHash() {
196 static uint32_t cached_version_hash = 0;
Luigi Semenzato859b3f02014-02-05 15:33:19 -0800197 static bool version_hash_is_cached = false;
198 if (version_hash_is_cached)
199 return cached_version_hash;
200 version_hash_is_cached = true;
201 std::string version;
202 if (base::SysInfo::GetLsbReleaseValue("CHROMEOS_RELEASE_VERSION", &version)) {
203 cached_version_hash = base::Hash(version);
204 } else if (testing_) {
205 cached_version_hash = 42; // return any plausible value for the hash
206 } else {
207 LOG(FATAL) << "could not find CHROMEOS_RELEASE_VERSION";
208 }
209 return cached_version_hash;
210}
211
Bertrand SIMONNET46b49da2014-06-25 14:38:07 -0700212void MetricsDaemon::Init(bool testing,
213 bool uploader_active,
214 MetricsLibraryInterface* metrics_lib,
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700215 const string& diskstats_path,
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700216 const string& vmstats_path,
217 const string& scaling_max_freq_path,
Daniel Eratc83975a2014-04-04 08:53:44 -0700218 const string& cpuinfo_max_freq_path) {
Darin Petkov65b01462010-04-14 13:32:20 -0700219 testing_ = testing;
Alex Vakulenko14595032014-08-28 14:59:56 -0700220 DCHECK(metrics_lib != nullptr);
Darin Petkovfc91b422010-05-12 13:05:45 -0700221 metrics_lib_ = metrics_lib;
Darin Petkov38d5cb02010-06-24 12:10:26 -0700222
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700223 // Get ticks per second (HZ) on this system.
224 // Sysconf cannot fail, so no sanity checks are needed.
225 ticks_per_second_ = sysconf(_SC_CLK_TCK);
226
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -0700227 daily_active_use_.reset(
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800228 new PersistentInteger("Logging.DailyUseTime"));
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -0700229 version_cumulative_active_use_.reset(
230 new PersistentInteger("Logging.CumulativeDailyUseTime"));
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700231 version_cumulative_cpu_use_.reset(
232 new PersistentInteger("Logging.CumulativeCpuTime"));
Darin Petkov38d5cb02010-06-24 12:10:26 -0700233
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800234 kernel_crash_interval_.reset(
235 new PersistentInteger("Logging.KernelCrashInterval"));
236 unclean_shutdown_interval_.reset(
237 new PersistentInteger("Logging.UncleanShutdownInterval"));
238 user_crash_interval_.reset(
239 new PersistentInteger("Logging.UserCrashInterval"));
Darin Petkov2ccef012010-05-05 16:06:37 -0700240
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800241 any_crashes_daily_count_.reset(
242 new PersistentInteger("Logging.AnyCrashesDaily"));
243 any_crashes_weekly_count_.reset(
244 new PersistentInteger("Logging.AnyCrashesWeekly"));
245 user_crashes_daily_count_.reset(
246 new PersistentInteger("Logging.UserCrashesDaily"));
247 user_crashes_weekly_count_.reset(
248 new PersistentInteger("Logging.UserCrashesWeekly"));
249 kernel_crashes_daily_count_.reset(
250 new PersistentInteger("Logging.KernelCrashesDaily"));
251 kernel_crashes_weekly_count_.reset(
252 new PersistentInteger("Logging.KernelCrashesWeekly"));
253 kernel_crashes_version_count_.reset(
254 new PersistentInteger("Logging.KernelCrashesSinceUpdate"));
255 unclean_shutdowns_daily_count_.reset(
256 new PersistentInteger("Logging.UncleanShutdownsDaily"));
257 unclean_shutdowns_weekly_count_.reset(
258 new PersistentInteger("Logging.UncleanShutdownsWeekly"));
Darin Petkov38d5cb02010-06-24 12:10:26 -0700259
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800260 daily_cycle_.reset(new PersistentInteger("daily.cycle"));
261 weekly_cycle_.reset(new PersistentInteger("weekly.cycle"));
262 version_cycle_.reset(new PersistentInteger("version.cycle"));
Luigi Semenzato859b3f02014-02-05 15:33:19 -0800263
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700264 diskstats_path_ = diskstats_path;
265 vmstats_path_ = vmstats_path;
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700266 scaling_max_freq_path_ = scaling_max_freq_path;
267 cpuinfo_max_freq_path_ = cpuinfo_max_freq_path;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700268 StatsReporterInit();
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800269
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700270 // Start collecting meminfo stats.
271 ScheduleMeminfoCallback(kMetricMeminfoInterval);
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800272 memuse_final_time_ = GetActiveTime() + kMemuseIntervals[0];
273 ScheduleMemuseCallback(kMemuseIntervals[0]);
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700274
Darin Petkov2ccef012010-05-05 16:06:37 -0700275 // Don't setup D-Bus and GLib in test mode.
276 if (testing)
277 return;
Darin Petkov65b01462010-04-14 13:32:20 -0700278
Darin Petkov703ec972010-04-27 11:02:18 -0700279 g_type_init();
Ben Chan6f598422013-06-22 06:29:36 -0700280 dbus_threads_init_default();
Darin Petkov65b01462010-04-14 13:32:20 -0700281
Darin Petkov703ec972010-04-27 11:02:18 -0700282 DBusError error;
283 dbus_error_init(&error);
Darin Petkov65b01462010-04-14 13:32:20 -0700284
David James3b3add52010-06-04 15:01:19 -0700285 DBusConnection* connection = dbus_bus_get(DBUS_BUS_SYSTEM, &error);
Darin Petkov703ec972010-04-27 11:02:18 -0700286 LOG_IF(FATAL, dbus_error_is_set(&error)) <<
287 "No D-Bus connection: " << SAFE_MESSAGE(error);
Darin Petkov65b01462010-04-14 13:32:20 -0700288
Alex Vakulenko14595032014-08-28 14:59:56 -0700289 dbus_connection_setup_with_g_main(connection, nullptr);
Darin Petkov65b01462010-04-14 13:32:20 -0700290
Darin Petkov40f25732013-04-29 15:07:31 +0200291 vector<string> matches;
292 matches.push_back(
Luigi Semenzato859b3f02014-02-05 15:33:19 -0800293 base::StringPrintf("type='signal',interface='%s',path='/',member='%s'",
294 kCrashReporterInterface,
295 kCrashReporterUserCrashSignal));
Darin Petkov40f25732013-04-29 15:07:31 +0200296
Darin Petkov703ec972010-04-27 11:02:18 -0700297 // Registers D-Bus matches for the signals we would like to catch.
Darin Petkov40f25732013-04-29 15:07:31 +0200298 for (vector<string>::const_iterator it = matches.begin();
299 it != matches.end(); ++it) {
300 const char* match = it->c_str();
Darin Petkov41e06232010-05-03 16:45:37 -0700301 DLOG(INFO) << "adding dbus match: " << match;
Darin Petkov703ec972010-04-27 11:02:18 -0700302 dbus_bus_add_match(connection, match, &error);
303 LOG_IF(FATAL, dbus_error_is_set(&error)) <<
304 "unable to add a match: " << SAFE_MESSAGE(error);
305 }
306
307 // Adds the D-Bus filter routine to be called back whenever one of
308 // the registered D-Bus matches is successful. The daemon is not
309 // activated for D-Bus messages that don't match.
Alex Vakulenko14595032014-08-28 14:59:56 -0700310 CHECK(dbus_connection_add_filter(connection, MessageFilter, this, nullptr));
Daniel Eratc83975a2014-04-04 08:53:44 -0700311
312 update_stats_timeout_id_ =
313 g_timeout_add(kUpdateStatsIntervalMs, &HandleUpdateStatsTimeout, this);
Bertrand SIMONNET46b49da2014-06-25 14:38:07 -0700314
315 if (uploader_active) {
Bertrand SIMONNETeb815be2014-09-11 07:38:17 -0700316 upload_service_.reset(new UploadService(testing_));
Bertrand SIMONNET46b49da2014-06-25 14:38:07 -0700317 upload_service_->Init();
318 }
Darin Petkov65b01462010-04-14 13:32:20 -0700319}
320
321void MetricsDaemon::Loop() {
Alex Vakulenko14595032014-08-28 14:59:56 -0700322 GMainLoop* loop = g_main_loop_new(nullptr, false);
Darin Petkov703ec972010-04-27 11:02:18 -0700323 g_main_loop_run(loop);
Darin Petkov65b01462010-04-14 13:32:20 -0700324}
325
Darin Petkov703ec972010-04-27 11:02:18 -0700326// static
327DBusHandlerResult MetricsDaemon::MessageFilter(DBusConnection* connection,
328 DBusMessage* message,
329 void* user_data) {
Darin Petkov703ec972010-04-27 11:02:18 -0700330 int message_type = dbus_message_get_type(message);
331 if (message_type != DBUS_MESSAGE_TYPE_SIGNAL) {
Darin Petkov41e06232010-05-03 16:45:37 -0700332 DLOG(WARNING) << "unexpected message type " << message_type;
Darin Petkov703ec972010-04-27 11:02:18 -0700333 return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
334 }
335
336 // Signal messages always have interfaces.
Daniel Eratc83975a2014-04-04 08:53:44 -0700337 const std::string interface(dbus_message_get_interface(message));
338 const std::string member(dbus_message_get_member(message));
339 DLOG(INFO) << "Got " << interface << "." << member << " D-Bus signal";
Darin Petkov703ec972010-04-27 11:02:18 -0700340
341 MetricsDaemon* daemon = static_cast<MetricsDaemon*>(user_data);
342
343 DBusMessageIter iter;
344 dbus_message_iter_init(message, &iter);
Daniel Eratc83975a2014-04-04 08:53:44 -0700345 if (interface == kCrashReporterInterface) {
346 CHECK_EQ(member, kCrashReporterUserCrashSignal);
Darin Petkov1bb904e2010-06-16 15:58:06 -0700347 daemon->ProcessUserCrash();
Darin Petkov703ec972010-04-27 11:02:18 -0700348 } else {
Daniel Eratc83975a2014-04-04 08:53:44 -0700349 // Ignore messages from the bus itself.
Darin Petkov703ec972010-04-27 11:02:18 -0700350 return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
351 }
352
353 return DBUS_HANDLER_RESULT_HANDLED;
Darin Petkov65b01462010-04-14 13:32:20 -0700354}
355
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700356// One might argue that parts of this should go into
357// chromium/src/base/sys_info_chromeos.c instead, but put it here for now.
358
359TimeDelta MetricsDaemon::GetIncrementalCpuUse() {
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700360 FilePath proc_stat_path = FilePath(kMetricsProcStatFileName);
361 std::string proc_stat_string;
362 if (!base::ReadFileToString(proc_stat_path, &proc_stat_string)) {
363 LOG(WARNING) << "cannot open " << kMetricsProcStatFileName;
364 return TimeDelta();
365 }
366
367 std::vector<std::string> proc_stat_lines;
368 base::SplitString(proc_stat_string, '\n', &proc_stat_lines);
369 if (proc_stat_lines.empty()) {
370 LOG(WARNING) << "cannot parse " << kMetricsProcStatFileName
371 << ": " << proc_stat_string;
372 return TimeDelta();
373 }
374 std::vector<std::string> proc_stat_totals;
375 base::SplitStringAlongWhitespace(proc_stat_lines[0], &proc_stat_totals);
376
Ben Chanf05ab402014-08-07 00:54:59 -0700377 uint64_t user_ticks, user_nice_ticks, system_ticks;
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700378 if (proc_stat_totals.size() != kMetricsProcStatFirstLineItemsCount ||
379 proc_stat_totals[0] != "cpu" ||
380 !base::StringToUint64(proc_stat_totals[1], &user_ticks) ||
381 !base::StringToUint64(proc_stat_totals[2], &user_nice_ticks) ||
382 !base::StringToUint64(proc_stat_totals[3], &system_ticks)) {
383 LOG(WARNING) << "cannot parse first line: " << proc_stat_lines[0];
384 return TimeDelta(base::TimeDelta::FromSeconds(0));
385 }
386
Ben Chanf05ab402014-08-07 00:54:59 -0700387 uint64_t total_cpu_use_ticks = user_ticks + user_nice_ticks + system_ticks;
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700388
389 // Sanity check.
390 if (total_cpu_use_ticks < latest_cpu_use_ticks_) {
391 LOG(WARNING) << "CPU time decreasing from " << latest_cpu_use_ticks_
392 << " to " << total_cpu_use_ticks;
393 return TimeDelta();
394 }
395
Ben Chanf05ab402014-08-07 00:54:59 -0700396 uint64_t diff = total_cpu_use_ticks - latest_cpu_use_ticks_;
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -0700397 latest_cpu_use_ticks_ = total_cpu_use_ticks;
398 // Use microseconds to avoid significant truncations.
399 return base::TimeDelta::FromMicroseconds(
400 diff * 1000 * 1000 / ticks_per_second_);
401}
402
Darin Petkov1bb904e2010-06-16 15:58:06 -0700403void MetricsDaemon::ProcessUserCrash() {
Daniel Eratc83975a2014-04-04 08:53:44 -0700404 // Counts the active time up to now.
405 UpdateStats(TimeTicks::Now(), Time::Now());
Darin Petkov1bb904e2010-06-16 15:58:06 -0700406
407 // Reports the active use time since the last crash and resets it.
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800408 SendCrashIntervalSample(user_crash_interval_);
Ken Mixterccd84c02010-08-16 19:57:13 -0700409
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800410 any_crashes_daily_count_->Add(1);
411 any_crashes_weekly_count_->Add(1);
412 user_crashes_daily_count_->Add(1);
413 user_crashes_weekly_count_->Add(1);
Darin Petkov1bb904e2010-06-16 15:58:06 -0700414}
415
Darin Petkov38d5cb02010-06-24 12:10:26 -0700416void MetricsDaemon::ProcessKernelCrash() {
Daniel Eratc83975a2014-04-04 08:53:44 -0700417 // Counts the active time up to now.
418 UpdateStats(TimeTicks::Now(), Time::Now());
Darin Petkov38d5cb02010-06-24 12:10:26 -0700419
420 // Reports the active use time since the last crash and resets it.
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800421 SendCrashIntervalSample(kernel_crash_interval_);
Ken Mixterccd84c02010-08-16 19:57:13 -0700422
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800423 any_crashes_daily_count_->Add(1);
424 any_crashes_weekly_count_->Add(1);
425 kernel_crashes_daily_count_->Add(1);
426 kernel_crashes_weekly_count_->Add(1);
Luigi Semenzato859b3f02014-02-05 15:33:19 -0800427
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800428 kernel_crashes_version_count_->Add(1);
Darin Petkov38d5cb02010-06-24 12:10:26 -0700429}
430
Ken Mixterccd84c02010-08-16 19:57:13 -0700431void MetricsDaemon::ProcessUncleanShutdown() {
Daniel Eratc83975a2014-04-04 08:53:44 -0700432 // Counts the active time up to now.
433 UpdateStats(TimeTicks::Now(), Time::Now());
Ken Mixterccd84c02010-08-16 19:57:13 -0700434
435 // Reports the active use time since the last crash and resets it.
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800436 SendCrashIntervalSample(unclean_shutdown_interval_);
Ken Mixterccd84c02010-08-16 19:57:13 -0700437
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800438 unclean_shutdowns_daily_count_->Add(1);
439 unclean_shutdowns_weekly_count_->Add(1);
440 any_crashes_daily_count_->Add(1);
441 any_crashes_weekly_count_->Add(1);
Ken Mixterccd84c02010-08-16 19:57:13 -0700442}
443
Luigi Semenzato8accd332011-05-17 16:37:18 -0700444bool MetricsDaemon::CheckSystemCrash(const string& crash_file) {
Darin Petkov38d5cb02010-06-24 12:10:26 -0700445 FilePath crash_detected(crash_file);
Ben Chan2e6543d2014-02-05 23:26:25 -0800446 if (!base::PathExists(crash_detected))
Ken Mixterccd84c02010-08-16 19:57:13 -0700447 return false;
Darin Petkov38d5cb02010-06-24 12:10:26 -0700448
449 // Deletes the crash-detected file so that the daemon doesn't report
450 // another kernel crash in case it's restarted.
Luigi Semenzato859b3f02014-02-05 15:33:19 -0800451 base::DeleteFile(crash_detected, false); // not recursive
Ken Mixterccd84c02010-08-16 19:57:13 -0700452 return true;
Darin Petkov38d5cb02010-06-24 12:10:26 -0700453}
454
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700455void MetricsDaemon::StatsReporterInit() {
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800456 DiskStatsReadStats(&read_sectors_, &write_sectors_);
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700457 VmStatsReadStats(&vmstats_);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800458 // The first time around just run the long stat, so we don't delay boot.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700459 stats_state_ = kStatsLong;
460 stats_initial_time_ = GetActiveTime();
461 if (stats_initial_time_ < 0) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700462 LOG(WARNING) << "not collecting disk stats";
463 } else {
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700464 ScheduleStatsCallback(kMetricStatsLongInterval);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700465 }
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800466}
467
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700468void MetricsDaemon::ScheduleStatsCallback(int wait) {
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800469 if (testing_) {
470 return;
471 }
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700472 g_timeout_add_seconds(wait, StatsCallbackStatic, this);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800473}
474
Ben Chanf05ab402014-08-07 00:54:59 -0700475bool MetricsDaemon::DiskStatsReadStats(uint64_t* read_sectors,
476 uint64_t* write_sectors) {
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800477 int nchars;
478 int nitems;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700479 bool success = false;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800480 char line[200];
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700481 if (diskstats_path_.empty()) {
482 return false;
483 }
Luigi Semenzato0f132bb2011-02-28 11:17:43 -0800484 int file = HANDLE_EINTR(open(diskstats_path_.c_str(), O_RDONLY));
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800485 if (file < 0) {
486 PLOG(WARNING) << "cannot open " << diskstats_path_;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700487 return false;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800488 }
489 nchars = HANDLE_EINTR(read(file, line, sizeof(line)));
490 if (nchars < 0) {
491 PLOG(WARNING) << "cannot read from " << diskstats_path_;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700492 return false;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800493 } else {
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700494 LOG_IF(WARNING, nchars == sizeof(line))
495 << "line too long in " << diskstats_path_;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800496 line[nchars] = '\0';
Luigi Semenzato4a6c9422014-06-30 18:12:28 -0700497 nitems = sscanf(line, "%*d %*d %" PRIu64 "d %*d %*d %*d %" PRIu64 "d",
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800498 read_sectors, write_sectors);
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700499 if (nitems == 2) {
500 success = true;
501 } else {
502 LOG(WARNING) << "found " << nitems << " items in "
503 << diskstats_path_ << ", expected 2";
504 }
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800505 }
Mike Frysinger3e8a8512014-05-14 16:14:37 -0400506 IGNORE_EINTR(close(file));
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700507 return success;
508}
509
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700510bool MetricsDaemon::VmStatsParseStats(const char* stats,
511 struct VmstatRecord* record) {
512 // a mapping of string name to field in VmstatRecord and whether we found it
513 struct mapping {
514 const string name;
515 uint64_t* value_p;
516 bool found;
517 } map[] =
518 { { .name = "pgmajfault",
519 .value_p = &record->page_faults_,
520 .found = false },
521 { .name = "pswpin",
522 .value_p = &record->swap_in_,
523 .found = false },
524 { .name = "pswpout",
525 .value_p = &record->swap_out_,
526 .found = false }, };
527
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700528 // Each line in the file has the form
529 // <ID> <VALUE>
530 // for instance:
531 // nr_free_pages 213427
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700532 vector<string> lines;
533 Tokenize(stats, "\n", &lines);
534 for (vector<string>::iterator it = lines.begin();
535 it != lines.end(); ++it) {
536 vector<string> tokens;
537 base::SplitString(*it, ' ', &tokens);
538 if (tokens.size() == 2) {
539 for (unsigned int i = 0; i < sizeof(map)/sizeof(struct mapping); i++) {
540 if (!tokens[0].compare(map[i].name)) {
541 if (!base::StringToUint64(tokens[1], map[i].value_p))
542 return false;
543 map[i].found = true;
544 }
545 }
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700546 } else {
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700547 LOG(WARNING) << "unexpected vmstat format";
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700548 }
549 }
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700550 // make sure we got all the stats
551 for (unsigned i = 0; i < sizeof(map)/sizeof(struct mapping); i++) {
552 if (map[i].found == false) {
553 LOG(WARNING) << "vmstat missing " << map[i].name;
554 return false;
555 }
556 }
557 return true;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700558}
559
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700560bool MetricsDaemon::VmStatsReadStats(struct VmstatRecord* stats) {
561 string value_string;
562 FilePath* path = new FilePath(vmstats_path_);
Ben Chan2e6543d2014-02-05 23:26:25 -0800563 if (!base::ReadFileToString(*path, &value_string)) {
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700564 delete path;
565 LOG(WARNING) << "cannot read " << vmstats_path_;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700566 return false;
567 }
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700568 delete path;
569 return VmStatsParseStats(value_string.c_str(), stats);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800570}
571
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700572bool MetricsDaemon::ReadFreqToInt(const string& sysfs_file_name, int* value) {
Luigi Semenzatod92d18c2013-06-04 13:24:21 -0700573 const FilePath sysfs_path(sysfs_file_name);
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700574 string value_string;
Ben Chan2e6543d2014-02-05 23:26:25 -0800575 if (!base::ReadFileToString(sysfs_path, &value_string)) {
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700576 LOG(WARNING) << "cannot read " << sysfs_path.value().c_str();
577 return false;
578 }
Ben Chan2e6543d2014-02-05 23:26:25 -0800579 if (!base::RemoveChars(value_string, "\n", &value_string)) {
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700580 LOG(WARNING) << "no newline in " << value_string;
581 // Continue even though the lack of newline is suspicious.
582 }
583 if (!base::StringToInt(value_string, value)) {
584 LOG(WARNING) << "cannot convert " << value_string << " to int";
585 return false;
586 }
587 return true;
588}
589
590void MetricsDaemon::SendCpuThrottleMetrics() {
591 // |max_freq| is 0 only the first time through.
592 static int max_freq = 0;
593 if (max_freq == -1)
594 // Give up, as sysfs did not report max_freq correctly.
595 return;
596 if (max_freq == 0 || testing_) {
597 // One-time initialization of max_freq. (Every time when testing.)
598 if (!ReadFreqToInt(cpuinfo_max_freq_path_, &max_freq)) {
599 max_freq = -1;
600 return;
601 }
602 if (max_freq == 0) {
603 LOG(WARNING) << "sysfs reports 0 max CPU frequency\n";
604 max_freq = -1;
605 return;
606 }
607 if (max_freq % 10000 == 1000) {
608 // Special case: system has turbo mode, and max non-turbo frequency is
609 // max_freq - 1000. This relies on "normal" (non-turbo) frequencies
610 // being multiples of (at least) 10 MHz. Although there is no guarantee
611 // of this, it seems a fairly reasonable assumption. Otherwise we should
612 // read scaling_available_frequencies, sort the frequencies, compare the
613 // two highest ones, and check if they differ by 1000 (kHz) (and that's a
614 // hack too, no telling when it will change).
615 max_freq -= 1000;
616 }
617 }
618 int scaled_freq = 0;
619 if (!ReadFreqToInt(scaling_max_freq_path_, &scaled_freq))
620 return;
621 // Frequencies are in kHz. If scaled_freq > max_freq, turbo is on, but
622 // scaled_freq is not the actual turbo frequency. We indicate this situation
623 // with a 101% value.
624 int percent = scaled_freq > max_freq ? 101 : scaled_freq / (max_freq / 100);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800625 SendLinearSample(kMetricScaledCpuFrequencyName, percent, 101, 102);
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700626}
627
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800628// static
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700629gboolean MetricsDaemon::StatsCallbackStatic(void* handle) {
630 (static_cast<MetricsDaemon*>(handle))->StatsCallback();
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800631 return false; // one-time callback
632}
633
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700634// Collects disk and vm stats alternating over a short and a long interval.
Luigi Semenzato8accd332011-05-17 16:37:18 -0700635
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700636void MetricsDaemon::StatsCallback() {
Ben Chanf05ab402014-08-07 00:54:59 -0700637 uint64_t read_sectors_now, write_sectors_now;
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700638 struct VmstatRecord vmstats_now;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700639 double time_now = GetActiveTime();
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700640 double delta_time = time_now - stats_initial_time_;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700641 if (testing_) {
642 // Fake the time when testing.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700643 delta_time = stats_state_ == kStatsShort ?
644 kMetricStatsShortInterval : kMetricStatsLongInterval;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700645 }
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700646 bool diskstats_success = DiskStatsReadStats(&read_sectors_now,
647 &write_sectors_now);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700648 int delta_read = read_sectors_now - read_sectors_;
649 int delta_write = write_sectors_now - write_sectors_;
650 int read_sectors_per_second = delta_read / delta_time;
651 int write_sectors_per_second = delta_write / delta_time;
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700652 bool vmstats_success = VmStatsReadStats(&vmstats_now);
653 uint64_t delta_faults = vmstats_now.page_faults_ - vmstats_.page_faults_;
654 uint64_t delta_swap_in = vmstats_now.swap_in_ - vmstats_.swap_in_;
655 uint64_t delta_swap_out = vmstats_now.swap_out_ - vmstats_.swap_out_;
656 uint64_t page_faults_per_second = delta_faults / delta_time;
657 uint64_t swap_in_per_second = delta_swap_in / delta_time;
658 uint64_t swap_out_per_second = delta_swap_out / delta_time;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800659
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700660 switch (stats_state_) {
661 case kStatsShort:
662 if (diskstats_success) {
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800663 SendSample(kMetricReadSectorsShortName,
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700664 read_sectors_per_second,
665 1,
666 kMetricSectorsIOMax,
667 kMetricSectorsBuckets);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800668 SendSample(kMetricWriteSectorsShortName,
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700669 write_sectors_per_second,
670 1,
671 kMetricSectorsIOMax,
672 kMetricSectorsBuckets);
673 }
674 if (vmstats_success) {
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800675 SendSample(kMetricPageFaultsShortName,
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700676 page_faults_per_second,
677 1,
678 kMetricPageFaultsMax,
679 kMetricPageFaultsBuckets);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800680 SendSample(kMetricSwapInShortName,
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700681 swap_in_per_second,
682 1,
683 kMetricPageFaultsMax,
684 kMetricPageFaultsBuckets);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800685 SendSample(kMetricSwapOutShortName,
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700686 swap_out_per_second,
687 1,
688 kMetricPageFaultsMax,
689 kMetricPageFaultsBuckets);
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700690 }
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800691 // Schedule long callback.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700692 stats_state_ = kStatsLong;
693 ScheduleStatsCallback(kMetricStatsLongInterval -
694 kMetricStatsShortInterval);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800695 break;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700696 case kStatsLong:
697 if (diskstats_success) {
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800698 SendSample(kMetricReadSectorsLongName,
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700699 read_sectors_per_second,
700 1,
701 kMetricSectorsIOMax,
702 kMetricSectorsBuckets);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800703 SendSample(kMetricWriteSectorsLongName,
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700704 write_sectors_per_second,
705 1,
706 kMetricSectorsIOMax,
707 kMetricSectorsBuckets);
708 // Reset sector counters.
709 read_sectors_ = read_sectors_now;
710 write_sectors_ = write_sectors_now;
711 }
712 if (vmstats_success) {
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800713 SendSample(kMetricPageFaultsLongName,
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700714 page_faults_per_second,
715 1,
716 kMetricPageFaultsMax,
717 kMetricPageFaultsBuckets);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800718 SendSample(kMetricSwapInLongName,
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700719 swap_in_per_second,
720 1,
721 kMetricPageFaultsMax,
722 kMetricPageFaultsBuckets);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800723 SendSample(kMetricSwapOutLongName,
Sonny Rao4b8aebb2013-07-31 23:18:31 -0700724 swap_out_per_second,
725 1,
726 kMetricPageFaultsMax,
727 kMetricPageFaultsBuckets);
728
729 vmstats_ = vmstats_now;
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700730 }
Luigi Semenzatofb3a8212013-05-07 16:55:00 -0700731 SendCpuThrottleMetrics();
Luigi Semenzato8accd332011-05-17 16:37:18 -0700732 // Set start time for new cycle.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700733 stats_initial_time_ = time_now;
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800734 // Schedule short callback.
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700735 stats_state_ = kStatsShort;
736 ScheduleStatsCallback(kMetricStatsShortInterval);
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800737 break;
738 default:
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700739 LOG(FATAL) << "Invalid stats state";
Luigi Semenzatoc88e42d2011-02-17 10:21:16 -0800740 }
741}
742
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700743void MetricsDaemon::ScheduleMeminfoCallback(int wait) {
744 if (testing_) {
745 return;
746 }
747 g_timeout_add_seconds(wait, MeminfoCallbackStatic, this);
748}
749
750// static
751gboolean MetricsDaemon::MeminfoCallbackStatic(void* handle) {
752 return (static_cast<MetricsDaemon*>(handle))->MeminfoCallback();
753}
754
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700755bool MetricsDaemon::MeminfoCallback() {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700756 string meminfo_raw;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700757 const FilePath meminfo_path("/proc/meminfo");
Ben Chan2e6543d2014-02-05 23:26:25 -0800758 if (!base::ReadFileToString(meminfo_path, &meminfo_raw)) {
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700759 LOG(WARNING) << "cannot read " << meminfo_path.value().c_str();
760 return false;
761 }
Luigi Semenzato96360192014-06-04 10:53:35 -0700762 // Make both calls even if the first one fails.
763 bool success = ProcessMeminfo(meminfo_raw);
764 return ReportZram(base::FilePath(FILE_PATH_LITERAL("/sys/block/zram0"))) &&
765 success;
766}
767
768// static
769bool MetricsDaemon::ReadFileToUint64(const base::FilePath& path,
Ben Chanf05ab402014-08-07 00:54:59 -0700770 uint64_t* value) {
Luigi Semenzato96360192014-06-04 10:53:35 -0700771 std::string content;
772 if (!base::ReadFileToString(path, &content)) {
773 PLOG(WARNING) << "cannot read " << path.MaybeAsASCII();
774 return false;
775 }
Luigi Semenzato4a6c9422014-06-30 18:12:28 -0700776 // Remove final newline.
777 base::TrimWhitespaceASCII(content, base::TRIM_TRAILING, &content);
Luigi Semenzato96360192014-06-04 10:53:35 -0700778 if (!base::StringToUint64(content, value)) {
779 LOG(WARNING) << "invalid integer: " << content;
780 return false;
781 }
782 return true;
783}
784
785bool MetricsDaemon::ReportZram(const base::FilePath& zram_dir) {
786 // Data sizes are in bytes. |zero_pages| is in number of pages.
Ben Chanf05ab402014-08-07 00:54:59 -0700787 uint64_t compr_data_size, orig_data_size, zero_pages;
Luigi Semenzato96360192014-06-04 10:53:35 -0700788 const size_t page_size = 4096;
789
790 if (!ReadFileToUint64(zram_dir.Append(kComprDataSizeName),
791 &compr_data_size) ||
792 !ReadFileToUint64(zram_dir.Append(kOrigDataSizeName), &orig_data_size) ||
793 !ReadFileToUint64(zram_dir.Append(kZeroPagesName), &zero_pages)) {
794 return false;
795 }
796
797 // |orig_data_size| does not include zero-filled pages.
798 orig_data_size += zero_pages * page_size;
799
800 const int compr_data_size_mb = compr_data_size >> 20;
801 const int savings_mb = (orig_data_size - compr_data_size) >> 20;
802 const int zero_ratio_percent = zero_pages * page_size * 100 / orig_data_size;
803
804 // Report compressed size in megabytes. 100 MB or less has little impact.
805 SendSample("Platform.ZramCompressedSize", compr_data_size_mb, 100, 4000, 50);
806 SendSample("Platform.ZramSavings", savings_mb, 100, 4000, 50);
807 // The compression ratio is multiplied by 100 for better resolution. The
808 // ratios of interest are between 1 and 6 (100% and 600% as reported). We
809 // don't want samples when very little memory is being compressed.
810 if (compr_data_size_mb >= 1) {
811 SendSample("Platform.ZramCompressionRatioPercent",
812 orig_data_size * 100 / compr_data_size, 100, 600, 50);
813 }
814 // The values of interest for zero_pages are between 1MB and 1GB. The units
815 // are number of pages.
816 SendSample("Platform.ZramZeroPages", zero_pages, 256, 256 * 1024, 50);
817 SendSample("Platform.ZramZeroRatioPercent", zero_ratio_percent, 1, 50, 50);
818
819 return true;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700820}
821
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700822bool MetricsDaemon::ProcessMeminfo(const string& meminfo_raw) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700823 static const MeminfoRecord fields_array[] = {
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700824 { "MemTotal", "MemTotal" }, // SPECIAL CASE: total system memory
825 { "MemFree", "MemFree" },
826 { "Buffers", "Buffers" },
827 { "Cached", "Cached" },
828 // { "SwapCached", "SwapCached" },
829 { "Active", "Active" },
830 { "Inactive", "Inactive" },
831 { "ActiveAnon", "Active(anon)" },
832 { "InactiveAnon", "Inactive(anon)" },
833 { "ActiveFile" , "Active(file)" },
834 { "InactiveFile", "Inactive(file)" },
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800835 { "Unevictable", "Unevictable", kMeminfoOp_HistLog },
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700836 // { "Mlocked", "Mlocked" },
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800837 { "SwapTotal", "SwapTotal", kMeminfoOp_SwapTotal },
838 { "SwapFree", "SwapFree", kMeminfoOp_SwapFree },
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700839 // { "Dirty", "Dirty" },
840 // { "Writeback", "Writeback" },
841 { "AnonPages", "AnonPages" },
842 { "Mapped", "Mapped" },
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800843 { "Shmem", "Shmem", kMeminfoOp_HistLog },
844 { "Slab", "Slab", kMeminfoOp_HistLog },
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700845 // { "SReclaimable", "SReclaimable" },
846 // { "SUnreclaim", "SUnreclaim" },
847 };
Luigi Semenzato8accd332011-05-17 16:37:18 -0700848 vector<MeminfoRecord> fields(fields_array,
849 fields_array + arraysize(fields_array));
850 if (!FillMeminfo(meminfo_raw, &fields)) {
851 return false;
852 }
853 int total_memory = fields[0].value;
854 if (total_memory == 0) {
855 // this "cannot happen"
856 LOG(WARNING) << "borked meminfo parser";
857 return false;
858 }
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800859 int swap_total = 0;
860 int swap_free = 0;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700861 // Send all fields retrieved, except total memory.
862 for (unsigned int i = 1; i < fields.size(); i++) {
Luigi Semenzato859b3f02014-02-05 15:33:19 -0800863 string metrics_name = base::StringPrintf("Platform.Meminfo%s",
864 fields[i].name);
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800865 int percent;
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800866 switch (fields[i].op) {
867 case kMeminfoOp_HistPercent:
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800868 // report value as percent of total memory
869 percent = fields[i].value * 100 / total_memory;
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800870 SendLinearSample(metrics_name, percent, 100, 101);
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800871 break;
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800872 case kMeminfoOp_HistLog:
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800873 // report value in kbytes, log scale, 4Gb max
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800874 SendSample(metrics_name, fields[i].value, 1, 4 * 1000 * 1000, 100);
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800875 break;
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800876 case kMeminfoOp_SwapTotal:
877 swap_total = fields[i].value;
878 case kMeminfoOp_SwapFree:
879 swap_free = fields[i].value;
Luigi Semenzato3ccca062013-02-04 19:50:45 -0800880 break;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700881 }
882 }
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800883 if (swap_total > 0) {
884 int swap_used = swap_total - swap_free;
885 int swap_used_percent = swap_used * 100 / swap_total;
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800886 SendSample("Platform.MeminfoSwapUsed", swap_used, 1, 8 * 1000 * 1000, 100);
887 SendLinearSample("Platform.MeminfoSwapUsedPercent", swap_used_percent,
Luigi Semenzato942cbab2013-02-12 13:17:07 -0800888 100, 101);
889 }
Luigi Semenzato8accd332011-05-17 16:37:18 -0700890 return true;
891}
892
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700893bool MetricsDaemon::FillMeminfo(const string& meminfo_raw,
894 vector<MeminfoRecord>* fields) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700895 vector<string> lines;
896 unsigned int nlines = Tokenize(meminfo_raw, "\n", &lines);
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700897
898 // Scan meminfo output and collect field values. Each field name has to
899 // match a meminfo entry (case insensitive) after removing non-alpha
900 // characters from the entry.
Luigi Semenzato8accd332011-05-17 16:37:18 -0700901 unsigned int ifield = 0;
902 for (unsigned int iline = 0;
903 iline < nlines && ifield < fields->size();
904 iline++) {
905 vector<string> tokens;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700906 Tokenize(lines[iline], ": ", &tokens);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700907 if (strcmp((*fields)[ifield].match, tokens[0].c_str()) == 0) {
908 // Name matches. Parse value and save.
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700909 char* rest;
Luigi Semenzato8accd332011-05-17 16:37:18 -0700910 (*fields)[ifield].value =
911 static_cast<int>(strtol(tokens[1].c_str(), &rest, 10));
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700912 if (*rest != '\0') {
913 LOG(WARNING) << "missing meminfo value";
914 return false;
915 }
Luigi Semenzato8accd332011-05-17 16:37:18 -0700916 ifield++;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700917 }
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700918 }
Luigi Semenzato8accd332011-05-17 16:37:18 -0700919 if (ifield < fields->size()) {
920 // End of input reached while scanning.
921 LOG(WARNING) << "cannot find field " << (*fields)[ifield].match
922 << " and following";
923 return false;
924 }
925 return true;
926}
927
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800928void MetricsDaemon::ScheduleMemuseCallback(double interval) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700929 if (testing_) {
930 return;
931 }
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800932 g_timeout_add_seconds(interval, MemuseCallbackStatic, this);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700933}
934
935// static
936gboolean MetricsDaemon::MemuseCallbackStatic(void* handle) {
937 MetricsDaemon* daemon = static_cast<MetricsDaemon*>(handle);
938 daemon->MemuseCallback();
939 return false;
940}
941
942void MetricsDaemon::MemuseCallback() {
943 // Since we only care about active time (i.e. uptime minus sleep time) but
944 // the callbacks are driven by real time (uptime), we check if we should
945 // reschedule this callback due to intervening sleep periods.
946 double now = GetActiveTime();
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800947 // Avoid intervals of less than one second.
948 double remaining_time = ceil(memuse_final_time_ - now);
949 if (remaining_time > 0) {
950 ScheduleMemuseCallback(remaining_time);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700951 } else {
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800952 // Report stats and advance the measurement interval unless there are
953 // errors or we've completed the last interval.
Luigi Semenzato8accd332011-05-17 16:37:18 -0700954 if (MemuseCallbackWork() &&
Luigi Semenzato0d9a9c92013-12-05 15:55:12 -0800955 memuse_interval_index_ < arraysize(kMemuseIntervals)) {
956 double interval = kMemuseIntervals[memuse_interval_index_++];
957 memuse_final_time_ = now + interval;
958 ScheduleMemuseCallback(interval);
Luigi Semenzato8accd332011-05-17 16:37:18 -0700959 }
960 }
961}
962
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700963bool MetricsDaemon::MemuseCallbackWork() {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700964 string meminfo_raw;
965 const FilePath meminfo_path("/proc/meminfo");
Ben Chan2e6543d2014-02-05 23:26:25 -0800966 if (!base::ReadFileToString(meminfo_path, &meminfo_raw)) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700967 LOG(WARNING) << "cannot read " << meminfo_path.value().c_str();
968 return false;
969 }
970 return ProcessMemuse(meminfo_raw);
971}
972
Luigi Semenzato5bd764f2011-10-14 12:03:35 -0700973bool MetricsDaemon::ProcessMemuse(const string& meminfo_raw) {
Luigi Semenzato8accd332011-05-17 16:37:18 -0700974 static const MeminfoRecord fields_array[] = {
975 { "MemTotal", "MemTotal" }, // SPECIAL CASE: total system memory
976 { "ActiveAnon", "Active(anon)" },
977 { "InactiveAnon", "Inactive(anon)" },
978 };
979 vector<MeminfoRecord> fields(fields_array,
980 fields_array + arraysize(fields_array));
981 if (!FillMeminfo(meminfo_raw, &fields)) {
982 return false;
983 }
984 int total = fields[0].value;
985 int active_anon = fields[1].value;
986 int inactive_anon = fields[2].value;
987 if (total == 0) {
988 // this "cannot happen"
989 LOG(WARNING) << "borked meminfo parser";
990 return false;
991 }
Luigi Semenzato859b3f02014-02-05 15:33:19 -0800992 string metrics_name = base::StringPrintf("Platform.MemuseAnon%d",
993 memuse_interval_index_);
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -0800994 SendLinearSample(metrics_name, (active_anon + inactive_anon) * 100 / total,
Luigi Semenzato8accd332011-05-17 16:37:18 -0700995 100, 101);
996 return true;
Luigi Semenzato29c7ef92011-04-12 14:12:35 -0700997}
998
Luigi Semenzato5ef2e392014-04-15 15:15:02 -0700999void MetricsDaemon::ReportDailyUse(int use_seconds) {
1000 if (use_seconds <= 0)
Darin Petkov1bb904e2010-06-16 15:58:06 -07001001 return;
1002
Luigi Semenzato5ef2e392014-04-15 15:15:02 -07001003 int minutes = (use_seconds + kSecondsPerMinute / 2) / kSecondsPerMinute;
1004 SendSample("Logging.DailyUseTime",
1005 minutes,
1006 1,
1007 kMinutesPerDay * 30 * 2, // cumulative---two months worth
1008 50);
Darin Petkovf1e85e42010-06-10 15:59:53 -07001009}
1010
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -08001011void MetricsDaemon::SendSample(const string& name, int sample,
Darin Petkov11b8eb32010-05-18 11:00:59 -07001012 int min, int max, int nbuckets) {
Darin Petkovfc91b422010-05-12 13:05:45 -07001013 metrics_lib_->SendToUMA(name, sample, min, max, nbuckets);
Darin Petkov65b01462010-04-14 13:32:20 -07001014}
Luigi Semenzato29c7ef92011-04-12 14:12:35 -07001015
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -07001016void MetricsDaemon::SendKernelCrashesCumulativeCountStats() {
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -08001017 // Report the number of crashes for this OS version, but don't clear the
1018 // counter. It is cleared elsewhere on version change.
Ben Chanf05ab402014-08-07 00:54:59 -07001019 int64_t crashes_count = kernel_crashes_version_count_->Get();
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -08001020 SendSample(kernel_crashes_version_count_->Name(),
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -07001021 crashes_count,
1022 1, // value of first bucket
1023 500, // value of last bucket
1024 100); // number of buckets
1025
1026
Ben Chanf05ab402014-08-07 00:54:59 -07001027 int64_t cpu_use_ms = version_cumulative_cpu_use_->Get();
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -07001028 SendSample(version_cumulative_cpu_use_->Name(),
1029 cpu_use_ms / 1000, // stat is in seconds
1030 1, // device may be used very little...
1031 8 * 1000 * 1000, // ... or a lot (a little over 90 days)
1032 100);
1033
1034 // On the first run after an autoupdate, cpu_use_ms and active_use_seconds
1035 // can be zero. Avoid division by zero.
1036 if (cpu_use_ms > 0) {
1037 // Send the crash frequency since update in number of crashes per CPU year.
1038 SendSample("Logging.KernelCrashesPerCpuYear",
1039 crashes_count * kSecondsPerDay * 365 * 1000 / cpu_use_ms,
1040 1,
1041 1000 * 1000, // about one crash every 30s of CPU time
1042 100);
1043 }
1044
Ben Chanf05ab402014-08-07 00:54:59 -07001045 int64_t active_use_seconds = version_cumulative_active_use_->Get();
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -07001046 if (active_use_seconds > 0) {
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -07001047 SendSample(version_cumulative_active_use_->Name(),
1048 active_use_seconds / 1000, // stat is in seconds
1049 1, // device may be used very little...
1050 8 * 1000 * 1000, // ... or a lot (about 90 days)
1051 100);
Luigi Semenzatoba0c65d2014-03-17 12:28:38 -07001052 // Same as above, but per year of active time.
1053 SendSample("Logging.KernelCrashesPerActiveYear",
1054 crashes_count * kSecondsPerDay * 365 / active_use_seconds,
1055 1,
1056 1000 * 1000, // about one crash every 30s of active time
1057 100);
1058 }
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -08001059}
1060
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -07001061void MetricsDaemon::SendDailyUseSample(
1062 const scoped_ptr<PersistentInteger>& use) {
1063 SendSample(use->Name(),
1064 use->GetAndClear(),
1065 1, // value of first bucket
1066 kSecondsPerDay, // value of last bucket
1067 50); // number of buckets
1068}
1069
Luigi Semenzato2fd51cc2014-02-26 11:53:16 -08001070void MetricsDaemon::SendCrashIntervalSample(
1071 const scoped_ptr<PersistentInteger>& interval) {
1072 SendSample(interval->Name(),
1073 interval->GetAndClear(),
1074 1, // value of first bucket
1075 4 * kSecondsPerWeek, // value of last bucket
1076 50); // number of buckets
1077}
1078
1079void MetricsDaemon::SendCrashFrequencySample(
1080 const scoped_ptr<PersistentInteger>& frequency) {
1081 SendSample(frequency->Name(),
1082 frequency->GetAndClear(),
1083 1, // value of first bucket
1084 100, // value of last bucket
1085 50); // number of buckets
1086}
1087
1088void MetricsDaemon::SendLinearSample(const string& name, int sample,
Luigi Semenzato29c7ef92011-04-12 14:12:35 -07001089 int max, int nbuckets) {
Luigi Semenzato29c7ef92011-04-12 14:12:35 -07001090 // TODO(semenzato): add a proper linear histogram to the Chrome external
1091 // metrics API.
1092 LOG_IF(FATAL, nbuckets != max + 1) << "unsupported histogram scale";
1093 metrics_lib_->SendEnumToUMA(name, sample, max);
1094}
Daniel Eratc83975a2014-04-04 08:53:44 -07001095
1096void MetricsDaemon::UpdateStats(TimeTicks now_ticks,
1097 Time now_wall_time) {
1098 const int elapsed_seconds = (now_ticks - last_update_stats_time_).InSeconds();
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -07001099 daily_active_use_->Add(elapsed_seconds);
1100 version_cumulative_active_use_->Add(elapsed_seconds);
Daniel Eratc83975a2014-04-04 08:53:44 -07001101 user_crash_interval_->Add(elapsed_seconds);
1102 kernel_crash_interval_->Add(elapsed_seconds);
1103 version_cumulative_cpu_use_->Add(GetIncrementalCpuUse().InMilliseconds());
1104 last_update_stats_time_ = now_ticks;
1105
1106 const TimeDelta since_epoch = now_wall_time - Time::UnixEpoch();
1107 const int day = since_epoch.InDays();
1108 const int week = day / 7;
1109
1110 if (daily_cycle_->Get() != day) {
1111 daily_cycle_->Set(day);
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -07001112 SendDailyUseSample(daily_active_use_);
1113 SendDailyUseSample(version_cumulative_active_use_);
Daniel Eratc83975a2014-04-04 08:53:44 -07001114 SendCrashFrequencySample(any_crashes_daily_count_);
1115 SendCrashFrequencySample(user_crashes_daily_count_);
1116 SendCrashFrequencySample(kernel_crashes_daily_count_);
1117 SendCrashFrequencySample(unclean_shutdowns_daily_count_);
Luigi Semenzatoe5883fa2014-04-18 17:00:35 -07001118 SendKernelCrashesCumulativeCountStats();
Daniel Eratc83975a2014-04-04 08:53:44 -07001119 }
1120
1121 if (weekly_cycle_->Get() != week) {
1122 weekly_cycle_->Set(week);
1123 SendCrashFrequencySample(any_crashes_weekly_count_);
1124 SendCrashFrequencySample(user_crashes_weekly_count_);
1125 SendCrashFrequencySample(kernel_crashes_weekly_count_);
1126 SendCrashFrequencySample(unclean_shutdowns_weekly_count_);
1127 }
1128}
1129
1130// static
1131gboolean MetricsDaemon::HandleUpdateStatsTimeout(gpointer data) {
1132 static_cast<MetricsDaemon*>(data)->UpdateStats(TimeTicks::Now(), Time::Now());
1133 return TRUE;
1134}