| OLD | NEW |
| 1 // Copyright (c) 2010 The Chromium OS Authors. All rights reserved. | 1 // Copyright (c) 2010 The Chromium OS Authors. All rights reserved. |
| 2 // Use of this source code is governed by a BSD-style license that can be | 2 // Use of this source code is governed by a BSD-style license that can be |
| 3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
| 4 | 4 |
| 5 #include "metrics_daemon.h" | 5 #include "metrics_daemon.h" |
| 6 | 6 |
| 7 #include <dbus/dbus-glib-lowlevel.h> | 7 #include <dbus/dbus-glib-lowlevel.h> |
| 8 #include <sys/file.h> | 8 #include <sys/file.h> |
| 9 | 9 |
| 10 #include <base/eintr_wrapper.h> | 10 #include <base/eintr_wrapper.h> |
| 11 #include <base/logging.h> | 11 #include <base/logging.h> |
| 12 | 12 |
| 13 using base::Time; |
| 14 using base::TimeDelta; |
| 15 using base::TimeTicks; |
| 16 |
| 13 #define SAFE_MESSAGE(e) (e.message ? e.message : "unknown error") | 17 #define SAFE_MESSAGE(e) (e.message ? e.message : "unknown error") |
| 14 #define DBUS_IFACE_CONNMAN_MANAGER "org.moblin.connman.Manager" | 18 #define DBUS_IFACE_CONNMAN_MANAGER "org.moblin.connman.Manager" |
| 15 #define DBUS_IFACE_POWER_MANAGER "org.chromium.Power.Manager" | 19 #define DBUS_IFACE_POWER_MANAGER "org.chromium.Power.Manager" |
| 16 #define DBUS_IFACE_SCREENSAVER_MANAGER "org.chromium.ScreenSaver.Manager" | 20 #define DBUS_IFACE_SCREENSAVER_MANAGER "org.chromium.ScreenSaver.Manager" |
| 17 #define DBUS_IFACE_SESSION_MANAGER "org.chromium.SessionManagerInterface" | 21 #define DBUS_IFACE_SESSION_MANAGER "org.chromium.SessionManagerInterface" |
| 18 | 22 |
| 19 // File to aggregate daily usage before sending to UMA. | 23 // File to aggregate daily usage before sending to UMA. |
| 20 // TODO(petkov): This file should probably live in a user-specific stateful | 24 // TODO(petkov): This file should probably live in a user-specific stateful |
| 21 // location, e.g., /home/chronos/user. | 25 // location, e.g., /home/chronos/user. |
| 22 static const char kDailyUseRecordFile[] = "/var/log/metrics/daily-usage"; | 26 static const char kDailyUseRecordFile[] = "/var/log/metrics/daily-usage"; |
| 23 | 27 |
| 24 static const int kSecondsPerMinute = 60; | 28 static const int kSecondsPerMinute = 60; |
| 25 static const int kMinutesPerHour = 60; | 29 static const int kMinutesPerHour = 60; |
| 26 static const int kHoursPerDay = 24; | 30 static const int kHoursPerDay = 24; |
| 27 static const int kMinutesPerDay = kHoursPerDay * kMinutesPerHour; | 31 static const int kMinutesPerDay = kHoursPerDay * kMinutesPerHour; |
| 28 static const int kSecondsPerDay = kMinutesPerDay * kSecondsPerMinute; | |
| 29 | 32 |
| 30 // The daily use monitor is scheduled to a 1-minute interval after | 33 // The daily use monitor is scheduled to a 1-minute interval after |
| 31 // initial user activity and then it's exponentially backed off to | 34 // initial user activity and then it's exponentially backed off to |
| 32 // 10-minute intervals. Although not required, the back off is | 35 // 10-minute intervals. Although not required, the back off is |
| 33 // implemented because the histogram buckets are spaced exponentially | 36 // implemented because the histogram buckets are spaced exponentially |
| 34 // anyway and to avoid too frequent metrics daemon process wake-ups | 37 // anyway and to avoid too frequent metrics daemon process wake-ups |
| 35 // and file I/O. | 38 // and file I/O. |
| 36 static const int kUseMonitorIntervalInit = 1 * kSecondsPerMinute; | 39 static const int kUseMonitorIntervalInit = 1 * kSecondsPerMinute; |
| 37 static const int kUseMonitorIntervalMax = 10 * kSecondsPerMinute; | 40 static const int kUseMonitorIntervalMax = 10 * kSecondsPerMinute; |
| 38 | 41 |
| (...skipping 106 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 145 | 148 |
| 146 void MetricsDaemon::Loop() { | 149 void MetricsDaemon::Loop() { |
| 147 GMainLoop* loop = g_main_loop_new(NULL, false); | 150 GMainLoop* loop = g_main_loop_new(NULL, false); |
| 148 g_main_loop_run(loop); | 151 g_main_loop_run(loop); |
| 149 } | 152 } |
| 150 | 153 |
| 151 // static | 154 // static |
| 152 DBusHandlerResult MetricsDaemon::MessageFilter(DBusConnection* connection, | 155 DBusHandlerResult MetricsDaemon::MessageFilter(DBusConnection* connection, |
| 153 DBusMessage* message, | 156 DBusMessage* message, |
| 154 void* user_data) { | 157 void* user_data) { |
| 155 time_t now = time(NULL); | 158 Time now = Time::Now(); |
| 156 DLOG(INFO) << "message intercepted @ " << now; | 159 TimeTicks ticks = TimeTicks::Now(); |
| 160 DLOG(INFO) << "message intercepted @ " << now.ToInternalValue(); |
| 157 | 161 |
| 158 int message_type = dbus_message_get_type(message); | 162 int message_type = dbus_message_get_type(message); |
| 159 if (message_type != DBUS_MESSAGE_TYPE_SIGNAL) { | 163 if (message_type != DBUS_MESSAGE_TYPE_SIGNAL) { |
| 160 DLOG(WARNING) << "unexpected message type " << message_type; | 164 DLOG(WARNING) << "unexpected message type " << message_type; |
| 161 return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; | 165 return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; |
| 162 } | 166 } |
| 163 | 167 |
| 164 // Signal messages always have interfaces. | 168 // Signal messages always have interfaces. |
| 165 const char* interface = dbus_message_get_interface(message); | 169 const char* interface = dbus_message_get_interface(message); |
| 166 CHECK(interface != NULL); | 170 CHECK(interface != NULL); |
| 167 | 171 |
| 168 MetricsDaemon* daemon = static_cast<MetricsDaemon*>(user_data); | 172 MetricsDaemon* daemon = static_cast<MetricsDaemon*>(user_data); |
| 169 | 173 |
| 170 DBusMessageIter iter; | 174 DBusMessageIter iter; |
| 171 dbus_message_iter_init(message, &iter); | 175 dbus_message_iter_init(message, &iter); |
| 172 if (strcmp(interface, DBUS_IFACE_CONNMAN_MANAGER) == 0) { | 176 if (strcmp(interface, DBUS_IFACE_CONNMAN_MANAGER) == 0) { |
| 173 CHECK(strcmp(dbus_message_get_member(message), | 177 CHECK(strcmp(dbus_message_get_member(message), |
| 174 "StateChanged") == 0); | 178 "StateChanged") == 0); |
| 175 | 179 |
| 176 char *state_name; | 180 char *state_name; |
| 177 dbus_message_iter_get_basic(&iter, &state_name); | 181 dbus_message_iter_get_basic(&iter, &state_name); |
| 178 daemon->NetStateChanged(state_name, now); | 182 daemon->NetStateChanged(state_name, ticks); |
| 179 } else if (strcmp(interface, DBUS_IFACE_POWER_MANAGER) == 0) { | 183 } else if (strcmp(interface, DBUS_IFACE_POWER_MANAGER) == 0) { |
| 180 CHECK(strcmp(dbus_message_get_member(message), | 184 CHECK(strcmp(dbus_message_get_member(message), |
| 181 "PowerStateChanged") == 0); | 185 "PowerStateChanged") == 0); |
| 182 | 186 |
| 183 char *state_name; | 187 char *state_name; |
| 184 dbus_message_iter_get_basic(&iter, &state_name); | 188 dbus_message_iter_get_basic(&iter, &state_name); |
| 185 daemon->PowerStateChanged(state_name, now); | 189 daemon->PowerStateChanged(state_name, now); |
| 186 } else if (strcmp(interface, DBUS_IFACE_SCREENSAVER_MANAGER) == 0) { | 190 } else if (strcmp(interface, DBUS_IFACE_SCREENSAVER_MANAGER) == 0) { |
| 187 CHECK(strcmp(dbus_message_get_member(message), | 191 CHECK(strcmp(dbus_message_get_member(message), |
| 188 "LockStateChanged") == 0); | 192 "LockStateChanged") == 0); |
| 189 | 193 |
| 190 char *state_name; | 194 char *state_name; |
| 191 dbus_message_iter_get_basic(&iter, &state_name); | 195 dbus_message_iter_get_basic(&iter, &state_name); |
| 192 daemon->ScreenSaverStateChanged(state_name, now); | 196 daemon->ScreenSaverStateChanged(state_name, now); |
| 193 } else if (strcmp(interface, DBUS_IFACE_SESSION_MANAGER) == 0) { | 197 } else if (strcmp(interface, DBUS_IFACE_SESSION_MANAGER) == 0) { |
| 194 CHECK(strcmp(dbus_message_get_member(message), | 198 CHECK(strcmp(dbus_message_get_member(message), |
| 195 "SessionStateChanged") == 0); | 199 "SessionStateChanged") == 0); |
| 196 | 200 |
| 197 char *state_name; | 201 char *state_name; |
| 198 dbus_message_iter_get_basic(&iter, &state_name); | 202 dbus_message_iter_get_basic(&iter, &state_name); |
| 199 daemon->SessionStateChanged(state_name, now); | 203 daemon->SessionStateChanged(state_name, now); |
| 200 } else { | 204 } else { |
| 201 DLOG(WARNING) << "unexpected interface: " << interface; | 205 DLOG(WARNING) << "unexpected interface: " << interface; |
| 202 return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; | 206 return DBUS_HANDLER_RESULT_NOT_YET_HANDLED; |
| 203 } | 207 } |
| 204 | 208 |
| 205 return DBUS_HANDLER_RESULT_HANDLED; | 209 return DBUS_HANDLER_RESULT_HANDLED; |
| 206 } | 210 } |
| 207 | 211 |
| 208 void MetricsDaemon::NetStateChanged(const char* state_name, time_t now) { | 212 void MetricsDaemon::NetStateChanged(const char* state_name, TimeTicks ticks) { |
| 209 DLOG(INFO) << "network state: " << state_name; | 213 DLOG(INFO) << "network state: " << state_name; |
| 210 | 214 |
| 211 NetworkState state = LookupNetworkState(state_name); | 215 NetworkState state = LookupNetworkState(state_name); |
| 212 | 216 |
| 213 // Logs the time in seconds between the network going online to | 217 // Logs the time in seconds between the network going online to |
| 214 // going offline (or, more precisely, going not online) in order to | 218 // going offline (or, more precisely, going not online) in order to |
| 215 // measure the mean time to network dropping. Going offline as part | 219 // measure the mean time to network dropping. Going offline as part |
| 216 // of suspend-to-RAM is not logged as network drop -- the assumption | 220 // of suspend-to-RAM is not logged as network drop -- the assumption |
| 217 // is that the message for suspend-to-RAM comes before the network | 221 // is that the message for suspend-to-RAM comes before the network |
| 218 // offline message which seems to and should be the case. | 222 // offline message which seems to and should be the case. |
| 219 if (state != kNetworkStateOnline && | 223 if (state != kNetworkStateOnline && |
| 220 network_state_ == kNetworkStateOnline && | 224 network_state_ == kNetworkStateOnline && |
| 221 power_state_ != kPowerStateMem) { | 225 power_state_ != kPowerStateMem) { |
| 222 int online_time = static_cast<int>(now - network_state_last_); | 226 TimeDelta since_online = ticks - network_state_last_; |
| 227 int online_time = static_cast<int>(since_online.InSeconds()); |
| 223 SendMetric(kMetricTimeToNetworkDropName, online_time, | 228 SendMetric(kMetricTimeToNetworkDropName, online_time, |
| 224 kMetricTimeToNetworkDropMin, | 229 kMetricTimeToNetworkDropMin, |
| 225 kMetricTimeToNetworkDropMax, | 230 kMetricTimeToNetworkDropMax, |
| 226 kMetricTimeToNetworkDropBuckets); | 231 kMetricTimeToNetworkDropBuckets); |
| 227 } | 232 } |
| 228 | 233 |
| 229 network_state_ = state; | 234 network_state_ = state; |
| 230 network_state_last_ = now; | 235 network_state_last_ = ticks; |
| 231 } | 236 } |
| 232 | 237 |
| 233 MetricsDaemon::NetworkState | 238 MetricsDaemon::NetworkState |
| 234 MetricsDaemon::LookupNetworkState(const char* state_name) { | 239 MetricsDaemon::LookupNetworkState(const char* state_name) { |
| 235 for (int i = 0; i < kNumberNetworkStates; i++) { | 240 for (int i = 0; i < kNumberNetworkStates; i++) { |
| 236 if (strcmp(state_name, kNetworkStates_[i]) == 0) { | 241 if (strcmp(state_name, kNetworkStates_[i]) == 0) { |
| 237 return static_cast<NetworkState>(i); | 242 return static_cast<NetworkState>(i); |
| 238 } | 243 } |
| 239 } | 244 } |
| 240 DLOG(WARNING) << "unknown network connection state: " << state_name; | 245 DLOG(WARNING) << "unknown network connection state: " << state_name; |
| 241 return kUnknownNetworkState; | 246 return kUnknownNetworkState; |
| 242 } | 247 } |
| 243 | 248 |
| 244 void MetricsDaemon::PowerStateChanged(const char* state_name, time_t now) { | 249 void MetricsDaemon::PowerStateChanged(const char* state_name, Time now) { |
| 245 DLOG(INFO) << "power state: " << state_name; | 250 DLOG(INFO) << "power state: " << state_name; |
| 246 power_state_ = LookupPowerState(state_name); | 251 power_state_ = LookupPowerState(state_name); |
| 247 | 252 |
| 248 if (power_state_ != kPowerStateOn) | 253 if (power_state_ != kPowerStateOn) |
| 249 SetUserActiveState(false, now); | 254 SetUserActiveState(false, now); |
| 250 } | 255 } |
| 251 | 256 |
| 252 MetricsDaemon::PowerState | 257 MetricsDaemon::PowerState |
| 253 MetricsDaemon::LookupPowerState(const char* state_name) { | 258 MetricsDaemon::LookupPowerState(const char* state_name) { |
| 254 for (int i = 0; i < kNumberPowerStates; i++) { | 259 for (int i = 0; i < kNumberPowerStates; i++) { |
| 255 if (strcmp(state_name, kPowerStates_[i]) == 0) { | 260 if (strcmp(state_name, kPowerStates_[i]) == 0) { |
| 256 return static_cast<PowerState>(i); | 261 return static_cast<PowerState>(i); |
| 257 } | 262 } |
| 258 } | 263 } |
| 259 DLOG(WARNING) << "unknown power state: " << state_name; | 264 DLOG(WARNING) << "unknown power state: " << state_name; |
| 260 return kUnknownPowerState; | 265 return kUnknownPowerState; |
| 261 } | 266 } |
| 262 | 267 |
| 263 void MetricsDaemon::ScreenSaverStateChanged(const char* state_name, | 268 void MetricsDaemon::ScreenSaverStateChanged(const char* state_name, Time now) { |
| 264 time_t now) { | |
| 265 DLOG(INFO) << "screen-saver state: " << state_name; | 269 DLOG(INFO) << "screen-saver state: " << state_name; |
| 266 screensaver_state_ = LookupScreenSaverState(state_name); | 270 screensaver_state_ = LookupScreenSaverState(state_name); |
| 267 SetUserActiveState(screensaver_state_ == kScreenSaverStateUnlocked, now); | 271 SetUserActiveState(screensaver_state_ == kScreenSaverStateUnlocked, now); |
| 268 } | 272 } |
| 269 | 273 |
| 270 MetricsDaemon::ScreenSaverState | 274 MetricsDaemon::ScreenSaverState |
| 271 MetricsDaemon::LookupScreenSaverState(const char* state_name) { | 275 MetricsDaemon::LookupScreenSaverState(const char* state_name) { |
| 272 for (int i = 0; i < kNumberScreenSaverStates; i++) { | 276 for (int i = 0; i < kNumberScreenSaverStates; i++) { |
| 273 if (strcmp(state_name, kScreenSaverStates_[i]) == 0) { | 277 if (strcmp(state_name, kScreenSaverStates_[i]) == 0) { |
| 274 return static_cast<ScreenSaverState>(i); | 278 return static_cast<ScreenSaverState>(i); |
| 275 } | 279 } |
| 276 } | 280 } |
| 277 DLOG(WARNING) << "unknown screen-saver state: " << state_name; | 281 DLOG(WARNING) << "unknown screen-saver state: " << state_name; |
| 278 return kUnknownScreenSaverState; | 282 return kUnknownScreenSaverState; |
| 279 } | 283 } |
| 280 | 284 |
| 281 void MetricsDaemon::SessionStateChanged(const char* state_name, | 285 void MetricsDaemon::SessionStateChanged(const char* state_name, Time now) { |
| 282 time_t now) { | |
| 283 DLOG(INFO) << "user session state: " << state_name; | 286 DLOG(INFO) << "user session state: " << state_name; |
| 284 session_state_ = LookupSessionState(state_name); | 287 session_state_ = LookupSessionState(state_name); |
| 285 SetUserActiveState(session_state_ == kSessionStateStarted, now); | 288 SetUserActiveState(session_state_ == kSessionStateStarted, now); |
| 286 } | 289 } |
| 287 | 290 |
| 288 MetricsDaemon::SessionState | 291 MetricsDaemon::SessionState |
| 289 MetricsDaemon::LookupSessionState(const char* state_name) { | 292 MetricsDaemon::LookupSessionState(const char* state_name) { |
| 290 for (int i = 0; i < kNumberSessionStates; i++) { | 293 for (int i = 0; i < kNumberSessionStates; i++) { |
| 291 if (strcmp(state_name, kSessionStates_[i]) == 0) { | 294 if (strcmp(state_name, kSessionStates_[i]) == 0) { |
| 292 return static_cast<SessionState>(i); | 295 return static_cast<SessionState>(i); |
| 293 } | 296 } |
| 294 } | 297 } |
| 295 DLOG(WARNING) << "unknown user session state: " << state_name; | 298 DLOG(WARNING) << "unknown user session state: " << state_name; |
| 296 return kUnknownSessionState; | 299 return kUnknownSessionState; |
| 297 } | 300 } |
| 298 | 301 |
| 299 void MetricsDaemon::SetUserActiveState(bool active, time_t now) { | 302 void MetricsDaemon::SetUserActiveState(bool active, Time now) { |
| 300 DLOG(INFO) << "user: " << (active ? "active" : "inactive"); | 303 DLOG(INFO) << "user: " << (active ? "active" : "inactive"); |
| 301 | 304 |
| 302 // Calculates the seconds of active use since the last update and | 305 // Calculates the seconds of active use since the last update and |
| 303 // the day since Epoch, and logs the usage data. | 306 // the day since Epoch, and logs the usage data. Guards against the |
| 304 int seconds = user_active_ ? (now - user_active_last_) : 0; | 307 // time jumping back and forth due to the user changing it by |
| 305 int day = now / kSecondsPerDay; | 308 // discarding the new use time. |
| 309 int seconds = 0; |
| 310 if (user_active_ && now > user_active_last_) { |
| 311 TimeDelta since_active = now - user_active_last_; |
| 312 if (since_active < TimeDelta::FromSeconds( |
| 313 kUseMonitorIntervalMax + kSecondsPerMinute)) { |
| 314 seconds = static_cast<int>(since_active.InSeconds()); |
| 315 } |
| 316 } |
| 317 TimeDelta since_epoch = now - Time(); |
| 318 int day = since_epoch.InDays(); |
| 306 LogDailyUseRecord(day, seconds); | 319 LogDailyUseRecord(day, seconds); |
| 307 | 320 |
| 308 // Schedules a use monitor on inactive->active transitions and | 321 // Schedules a use monitor on inactive->active transitions and |
| 309 // unschedules it on active->inactive transitions. | 322 // unschedules it on active->inactive transitions. |
| 310 if (!user_active_ && active) | 323 if (!user_active_ && active) |
| 311 ScheduleUseMonitor(kUseMonitorIntervalInit, /* backoff */ false); | 324 ScheduleUseMonitor(kUseMonitorIntervalInit, /* backoff */ false); |
| 312 else if (user_active_ && !active) | 325 else if (user_active_ && !active) |
| 313 UnscheduleUseMonitor(); | 326 UnscheduleUseMonitor(); |
| 314 | 327 |
| 315 // Remembers the current active state and the time of the last | 328 // Remembers the current active state and the time of the last |
| (...skipping 65 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 381 // overhead. | 394 // overhead. |
| 382 daily_use_day_last_ = day; | 395 daily_use_day_last_ = day; |
| 383 } | 396 } |
| 384 | 397 |
| 385 // static | 398 // static |
| 386 gboolean MetricsDaemon::UseMonitorStatic(gpointer data) { | 399 gboolean MetricsDaemon::UseMonitorStatic(gpointer data) { |
| 387 return static_cast<MetricsDaemon*>(data)->UseMonitor() ? TRUE : FALSE; | 400 return static_cast<MetricsDaemon*>(data)->UseMonitor() ? TRUE : FALSE; |
| 388 } | 401 } |
| 389 | 402 |
| 390 bool MetricsDaemon::UseMonitor() { | 403 bool MetricsDaemon::UseMonitor() { |
| 391 SetUserActiveState(user_active_, time(NULL)); | 404 SetUserActiveState(user_active_, Time::Now()); |
| 392 | 405 |
| 393 // If a new monitor source/instance is scheduled, returns false to | 406 // If a new monitor source/instance is scheduled, returns false to |
| 394 // tell GLib to destroy this monitor source/instance. Returns true | 407 // tell GLib to destroy this monitor source/instance. Returns true |
| 395 // otherwise to keep calling back this monitor. | 408 // otherwise to keep calling back this monitor. |
| 396 return !ScheduleUseMonitor(usemon_interval_ * 2, /* backoff */ true); | 409 return !ScheduleUseMonitor(usemon_interval_ * 2, /* backoff */ true); |
| 397 } | 410 } |
| 398 | 411 |
| 399 bool MetricsDaemon::ScheduleUseMonitor(int interval, bool backoff) | 412 bool MetricsDaemon::ScheduleUseMonitor(int interval, bool backoff) |
| 400 { | 413 { |
| 401 if (testing_) | 414 if (testing_) |
| (...skipping 39 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 441 usemon_source_ = NULL; | 454 usemon_source_ = NULL; |
| 442 usemon_interval_ = 0; | 455 usemon_interval_ = 0; |
| 443 } | 456 } |
| 444 | 457 |
| 445 void MetricsDaemon::SendMetric(const std::string& name, int sample, | 458 void MetricsDaemon::SendMetric(const std::string& name, int sample, |
| 446 int min, int max, int nbuckets) { | 459 int min, int max, int nbuckets) { |
| 447 DLOG(INFO) << "received metric: " << name << " " << sample << " " | 460 DLOG(INFO) << "received metric: " << name << " " << sample << " " |
| 448 << min << " " << max << " " << nbuckets; | 461 << min << " " << max << " " << nbuckets; |
| 449 metrics_lib_->SendToUMA(name, sample, min, max, nbuckets); | 462 metrics_lib_->SendToUMA(name, sample, min, max, nbuckets); |
| 450 } | 463 } |
| OLD | NEW |