Log time between network drops -- from online to offline. (703ec97b) · Commits · e / os / android_system_core

metrics/Makefile

+6 −19

Original line number	Diff line number	Diff line
		@@ -8,7 +8,7 @@
		CCONFIG = $(shell $(PKG_CONFIG) --cflags dbus-1 glib-2.0 dbus-glib-1)
		LDCONFIG = $(shell $(PKG_CONFIG) --libs dbus-1 glib-2.0 gthread-2.0 dbus-glib-1)

		CFLAGS = -Wall -Werror -I/usr/include -fpic -O2 $(CCONFIG)
		CFLAGS = -Wall -Werror -I/usr/include -fPIC -O2 $(CCONFIG)
		CXXFLAGS = $(CFLAGS) -fno-exceptions

		CLIENT = metrics_client
		@@ -22,11 +22,9 @@ CLIENT_OBJS = \
		LIB_OBJS = \
		metrics_library.o
		DAEMON_OBJS = \
		marshal_void__string_boxed.o \
		metrics_daemon.o \
		metrics_daemon_main.o
		TESTDAEMON_OBJS = \
		marshal_void__string_boxed.o \
		metrics_daemon.o \
		metrics_daemon_unittest.o

		@@ -56,26 +54,16 @@ $(SHAREDLIB): $(LIB_OBJS)
		%.o: %.c
		$(CC) $(CFLAGS) -c $< -o $@

		%.c: %.list
		glib-genmarshal --body --prefix=marshal $< > $@

		%.h: %.list
		glib-genmarshal --header --prefix=marshal $< > $@

		# dependencies in addition to those defined by the rules

		metrics_daemon.o: \
		marshal_void__string_boxed.h \
		metrics_daemon.h \
		network_states.h
		network_states.h \
		power_states.h
		metrics_daemon_unittest.o: \
		marshal_void__string_boxed.h \
		metrics_daemon.h \
		network_states.h
		marshal_void__string_boxed.o: \
		marshal_void__string_boxed.h

		.PRECIOUS: marshal_void__string_boxed.c # keep around for debugging
		network_states.h \
		power_states.h

		install:
		install $(CLIENT) $(DESTDIR)/usr/bin
		@@ -87,5 +75,4 @@ install:
		install omaha_tracker.sh $(DESTDIR)/usr/sbin

		clean:
		rm -f $(CLIENT) $(DAEMON) $(LIB) $(SHAREDLIB) $(TESTDAEMON)
		rm -f *.o marshal_void__string_boxed.[ch]
		rm -f $(CLIENT) $(DAEMON) $(LIB) $(SHAREDLIB) $(TESTDAEMON) *.o

metrics/marshal_void__string_boxed.list

deleted100644 → 0

+0 −1

Original line number	Diff line number	Diff line
		VOID:STRING,BOXED

metrics/metrics_daemon.cc

+141 −96

Original line number	Diff line number	Diff line
		@@ -5,22 +5,43 @@
		#include "metrics_daemon.h"
		#include "metrics_library.h"

		#include <glib-object.h>

		extern "C" {
		#include "marshal_void__string_boxed.h"
		}
		#include <dbus/dbus-glib-lowlevel.h>

		#include <base/logging.h>

		#define SAFE_MESSAGE(e) ((e && e->message) ? e->message : "unknown error")
		#define SAFE_MESSAGE(e) (e.message ? e.message : "unknown error")
		#define DBUS_IFACE_CONNMAN_MANAGER "org.moblin.connman.Manager"
		#define DBUS_IFACE_POWER_MANAGER "org.chromium.Power.Manager"

		// static
		const char*
		MetricsDaemon::dbus_matches_[] = {
		"type='signal',"
		"sender='org.moblin.connman',"
		"interface='" DBUS_IFACE_CONNMAN_MANAGER "',"
		"path='/',"
		"member='StateChanged'",

		"type='signal',"
		"interface='" DBUS_IFACE_POWER_MANAGER "',"
		"path='/',"
		"member='PowerStateChanged'",
		};

		MetricsDaemon::NetworkState
		// static
		const char *
		MetricsDaemon::network_states_[MetricsDaemon::kNumberNetworkStates] = {
		#define STATE(name, capname) { #name, "Network.Connman" # capname },
		#define STATE(name, capname) #name,
		#include "network_states.h"
		};

		// static
		const char *
		MetricsDaemon::power_states_[MetricsDaemon::kNumberPowerStates] = {
		#define STATE(name, capname) #name,
		#include "power_states.h"
		};

		void MetricsDaemon::Run(bool run_as_daemon, bool testing) {
		Init(testing);
		if (!run_as_daemon \|\| daemon(0, 0) == 0) {
		@@ -30,115 +51,139 @@ void MetricsDaemon::Run(bool run_as_daemon, bool testing) {

		void MetricsDaemon::Init(bool testing) {
		testing_ = testing;
		network_state_id_ = kUnknownNetworkStateId;

		::g_thread_init(NULL);
		::g_type_init();
		::dbus_g_thread_init();

		::GError* error = NULL;
		::DBusGConnection* dbc = ::dbus_g_bus_get(DBUS_BUS_SYSTEM, &error);
		// Note that LOG(FATAL) terminates the process; otherwise we'd have to worry
		// about leaking \|error\|.
		LOG_IF(FATAL, dbc == NULL) <<
		"cannot connect to dbus: " << SAFE_MESSAGE(error);

		::DBusGProxy* net_proxy = ::dbus_g_proxy_new_for_name(
		dbc, "org.moblin.connman", "/", "org.moblin.connman.Metrics");
		LOG_IF(FATAL, net_proxy == NULL) << "no dbus proxy for network";

		#if 0
		// Unclear how soon one can call dbus_g_type_get_map(). Doing it before the
		// call to dbus_g_bus_get() results in a (non-fatal) assertion failure.
		// GetProperties returns a hash table.
		hashtable_gtype = ::dbus_g_type_get_map("GHashTable", G_TYPE_STRING,
		G_TYPE_VALUE);
		#endif

		dbus_g_object_register_marshaller(marshal_VOID__STRING_BOXED,
		G_TYPE_NONE,
		G_TYPE_STRING,
		G_TYPE_VALUE,
		G_TYPE_INVALID);
		::dbus_g_proxy_add_signal(net_proxy, "ConnectionStateChanged",
		G_TYPE_STRING, G_TYPE_VALUE, G_TYPE_INVALID);
		::dbus_g_proxy_connect_signal(net_proxy, "ConnectionStateChanged",
		G_CALLBACK(&StaticNetSignalHandler),
		this, NULL);
		network_state_ = kUnknownNetworkState;
		network_state_changed_ = 0;
		power_state_ = kUnknownPowerState;

		g_thread_init(NULL);
		g_type_init();
		dbus_g_thread_init();

		DBusError error;
		dbus_error_init(&error);

		DBusConnection *connection = dbus_bus_get(DBUS_BUS_SYSTEM, &error);
		LOG_IF(FATAL, dbus_error_is_set(&error)) <<
		"No D-Bus connection: " << SAFE_MESSAGE(error);

		dbus_connection_setup_with_g_main(connection, NULL);

		// Registers D-Bus matches for the signals we would like to catch.
		for (unsigned int m = 0; m < sizeof(dbus_matches_) / sizeof(char *); m++) {
		const char* match = dbus_matches_[m];
		LOG(INFO) << "adding dbus match: " << match;
		dbus_bus_add_match(connection, match, &error);
		LOG_IF(FATAL, dbus_error_is_set(&error)) <<
		"unable to add a match: " << SAFE_MESSAGE(error);
		}

		// Adds the D-Bus filter routine to be called back whenever one of
		// the registered D-Bus matches is successful. The daemon is not
		// activated for D-Bus messages that don't match.
		CHECK(dbus_connection_add_filter(connection, MessageFilter, this, NULL));
		}

		void MetricsDaemon::Loop() {
		::GMainLoop* loop = ::g_main_loop_new(NULL, false);
		::g_main_loop_run(loop);
		GMainLoop* loop = g_main_loop_new(NULL, false);
		g_main_loop_run(loop);
		}

		void MetricsDaemon::StaticNetSignalHandler(::DBusGProxy* proxy,
		const char* property,
		const ::GValue* value,
		void *data) {
		(static_cast<MetricsDaemon*>(data))->NetSignalHandler(proxy, property, value);
		// static
		DBusHandlerResult MetricsDaemon::MessageFilter(DBusConnection* connection,
		DBusMessage* message,
		void* user_data) {
		LOG(INFO) << "message filter";

		int message_type = dbus_message_get_type(message);
		if (message_type != DBUS_MESSAGE_TYPE_SIGNAL) {
		LOG(WARNING) << "unexpected message type " << message_type;
		return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
		}

		void MetricsDaemon::NetSignalHandler(::DBusGProxy* proxy,
		const char* property,
		const ::GValue* value) {
		if (strcmp("ConnectionState", property) != 0) {
		return;
		// Signal messages always have interfaces.
		const char* interface = dbus_message_get_interface(message);
		CHECK(interface != NULL);

		MetricsDaemon* daemon = static_cast<MetricsDaemon*>(user_data);

		DBusMessageIter iter;
		dbus_message_iter_init(message, &iter);
		if (strcmp(interface, DBUS_IFACE_CONNMAN_MANAGER) == 0) {
		CHECK(strcmp(dbus_message_get_member(message), "StateChanged") == 0);

		char *state_name;
		dbus_message_iter_get_basic(&iter, &state_name);
		daemon->NetStateChanged(state_name);
		} else if (strcmp(interface, DBUS_IFACE_POWER_MANAGER) == 0) {
		CHECK(strcmp(dbus_message_get_member(message), "PowerStateChanged") == 0);

		char *state_name;
		dbus_message_iter_get_basic(&iter, &state_name);
		daemon->PowerStateChanged(state_name);
		} else {
		LOG(WARNING) << "unexpected interface: " << interface;
		return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
		}

		const char* newstate = static_cast<const char*>(g_value_get_string(value));
		LogNetworkStateChange(newstate);
		return DBUS_HANDLER_RESULT_HANDLED;
		}

		void MetricsDaemon::LogNetworkStateChange(const char* newstate) {
		NetworkStateId new_id = GetNetworkStateId(newstate);
		if (new_id == kUnknownNetworkStateId) {
		LOG(WARNING) << "unknown network connection state " << newstate;
		return;
		void MetricsDaemon::NetStateChanged(const char* state_name) {
		LOG(INFO) << "network state: " << state_name;

		time_t now = time(NULL);
		NetworkState state = LookupNetworkState(state_name);

		// Logs the time in seconds between the network going online to
		// going offline in order to measure the mean time to network
		// dropping. Going offline as part of suspend-to-RAM is not logged
		// as network drop -- the assumption is that the message for
		// suspend-to-RAM comes before the network offline message which
		// seems to and should be the case.
		if (state == kNetworkStateOffline &&
		network_state_ == kNetworkStateOnline &&
		power_state_ != kPowerStateMem) {
		int online_time = static_cast<int>(now - network_state_changed_);
		PublishMetric("Network.TimeToDrop", online_time,
		1, 8 /* hours / 60 * 60, 50);
		}
		NetworkStateId old_id = network_state_id_;
		if (new_id == old_id) { // valid new state and no change
		return;

		network_state_ = state;
		network_state_changed_ = now;
		}
		struct timeval now;
		if (gettimeofday(&now, NULL) != 0) {
		PLOG(WARNING) << "gettimeofday";

		MetricsDaemon::NetworkState
		MetricsDaemon::LookupNetworkState(const char* state_name) {
		for (int i = 0; i < kNumberNetworkStates; i++) {
		if (strcmp(state_name, network_states_[i]) == 0) {
		return static_cast<NetworkState>(i);
		}
		if (old_id != kUnknownNetworkStateId) {
		struct timeval diff;
		timersub(&now, &network_state_start_, &diff);
		int diff_ms = diff.tv_usec / 1000 + diff.tv_sec * 1000;
		// Saturates rather than overflowing. We expect this to be statistically
		// insignificant, since INT_MAX milliseconds is 24.8 days.
		if (diff.tv_sec >= INT_MAX / 1000) {
		diff_ms = INT_MAX;
		}
		PublishMetric(network_states_[old_id].stat_name,
		diff_ms,
		1,
		8 * 60 * 60 * 1000, // 8 hours in milliseconds
		100);
		LOG(WARNING) << "unknown network connection state: " << state_name;
		return kUnknownNetworkState;
		}
		network_state_id_ = new_id;
		network_state_start_ = now;

		void MetricsDaemon::PowerStateChanged(const char* state_name) {
		LOG(INFO) << "power state: " << state_name;
		power_state_ = LookupPowerState(state_name);
		}

		MetricsDaemon::NetworkStateId
		MetricsDaemon::GetNetworkStateId(const char* state_name) {
		for (int i = 0; i < kNumberNetworkStates; i++) {
		if (strcmp(state_name, network_states_[i].name) == 0) {
		return static_cast<NetworkStateId>(i);
		MetricsDaemon::PowerState
		MetricsDaemon::LookupPowerState(const char* state_name) {
		for (int i = 0; i < kNumberPowerStates; i++) {
		if (strcmp(state_name, power_states_[i]) == 0) {
		return static_cast<PowerState>(i);
		}
		}
		return static_cast<NetworkStateId>(-1);
		LOG(WARNING) << "unknown power state: " << state_name;
		return kUnknownPowerState;
		}

		void MetricsDaemon::PublishMetric(const char* name, int sample,
		int min, int max, int nbuckets) {
		if (testing_) {
		LOG(INFO) << "received metric: " << name << " " << sample <<
		" " << min << " " << max << " " << nbuckets;
		} else {
		if (!testing_) {
		MetricsLibrary::SendToChrome(name, sample, min, max, nbuckets);
		}
		}

metrics/metrics_daemon.h

+42 −43

Original line number	Diff line number	Diff line
		@@ -5,40 +5,40 @@
		#ifndef METRICS_DAEMON_H_
		#define METRICS_DAEMON_H_

		#include <dbus/dbus-glib.h>
		#include <sys/time.h>
		#include <dbus/dbus.h>
		#include <time.h>

		class MetricsDaemon {

		public:
		MetricsDaemon()
		: network_state_id_(kUnknownNetworkStateId) {
		}
		: testing_(false),
		network_state_(kUnknownNetworkState),
		network_state_changed_(0),
		power_state_(kUnknownPowerState) {}
		~MetricsDaemon() {}

		// Does all the work. If \|run_as_daemon\| is true, daemonize by forking. If
		// \|testing\| is true, log the stats instead of sending them to Chrome.
		// Does all the work. If \|run_as_daemon\| is true, daemonizes by
		// forking. If \|testing\| is true, logs the stats instead of sending
		// them to Chrome.
		void Run(bool run_as_daemon, bool testing);

		private:
		// Shared with Chrome for transport.
		static const char* kMetricsFilePath;
		static const int kMetricsMessageMaxLength = 4096;

		// The network states. See network_states.h.
		typedef enum {
		// Initial/unknown network state id.
		kUnknownNetworkStateId = -1,
		// The network states (see network_states.h).
		enum NetworkState {
		kUnknownNetworkState = -1, // Initial/unknown network state.
		#define STATE(name, capname) kNetworkState ## capname,
		#include "network_states.h"
		kNumberNetworkStates
		} NetworkStateId;
		};

		typedef struct {
		const char* name;
		const char* stat_name;
		} NetworkState;
		// The power states (see power_states.h).
		enum PowerState {
		kUnknownPowerState = -1, // Initial/unknown power state.
		#define STATE(name, capname) kPowerState ## capname,
		#include "power_states.h"
		kNumberPowerStates
		};

		// Initializes.
		void Init(bool testing);
		@@ -46,22 +46,22 @@ class MetricsDaemon {
		// Creates the event loop and enters it.
		void Loop();

		// Static callback for network events on DBus.
		static void StaticNetSignalHandler(::DBusGProxy* proxy, const char* property,
		const ::GValue* value, void* data);
		// D-Bus filter callback.
		static DBusHandlerResult MessageFilter(DBusConnection* connection,
		DBusMessage* message,
		void* user_data);

		// Processes network state change.
		void NetStateChanged(const char* state_name);

		// Callback for network events on DBus.
		void NetSignalHandler(::DBusGProxy* proxy, const char* property,
		const ::GValue* value);
		// Given the state name, returns the state id.
		NetworkState LookupNetworkState(const char* state_name);

		// This is called at each network state change. The new state is identified
		// by the string @newstate. As a side effect, this method ships to Chrome
		// (or prints to stdout when testing) the name and duration of the state
		// that has ended.
		void LogNetworkStateChange(const char* newstate);
		// Processes power state change.
		void PowerStateChanged(const char* state_name);

		// Given a string with the name of a state, returns the id for the state.
		NetworkStateId GetNetworkStateId(const char* state_name);
		// Given the state name, returns the state id.
		PowerState LookupPowerState(const char* state_name);

		// Sends a stat to Chrome for transport to UMA (or prints it for
		// testing). See MetricsLibrary::SendToChrome in metrics_library.h
		@@ -69,20 +69,19 @@ class MetricsDaemon {
		void PublishMetric(const char* name, int sample,
		int min, int max, int nbuckets);

		#if 0
		// Fetches a name-value hash table from DBus.
		bool GetProperties(::DBusGProxy* proxy, ::GHashTable** table);
		// D-Bus message match strings.
		static const char* dbus_matches_[];

		// The type descriptor for a glib hash table.
		GType hashtable_gtype;
		#endif
		// Array of network states.
		static const char* network_states_[kNumberNetworkStates];

		// Array of network states of interest.
		static NetworkState network_states_[kNumberNetworkStates];
		// Array of power states.
		static const char* power_states_[kNumberPowerStates];

		bool testing_; // just testing
		NetworkStateId network_state_id_; // id of current state
		struct timeval network_state_start_; // when current state was entered
		NetworkState network_state_; // current network state
		time_t network_state_changed_; // timestamp last net state change
		PowerState power_state_; // current power state
		};

		#endif // METRICS_DAEMON_H_

metrics/network_states.h

+1 −7

Original line number	Diff line number	Diff line
		// Copyright (c) 2009 The Chromium OS Authors. All rights reserved.
		// Copyright (c) 2010 The Chromium OS Authors. All rights reserved.
		// Use of this source code is governed by a BSD-style license that can be
		// found in the LICENSE file.

		@@ -22,13 +22,7 @@
		#define STATE(name, capname)
		#endif

		STATE(association, Association)
		STATE(configuration, Configuration)
		STATE(disconnect, Disconnect)
		STATE(failure, Failure)
		STATE(idle, Idle)
		STATE(offline, Offline)
		STATE(online, Online)
		STATE(ready, Ready)

		#undef STATE