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 |