commit 19ee8a8dd675ecf788a5a527b843b59fbbe3255f
author Lorenzo Colitti <lorenzo@google.com> Thu Feb 02 12:59:05 2017 +0900
committer Lorenzo Colitti <lorenzo@google.com> Thu Feb 02 16:22:08 2017 +0900
tree 3b1231f52de229949760d5cbbb9115837c054064
parent 1ed96e2d3fa89ca4848750a6b3bbbcf677946d27

Add finer-grained logging of netd startup times.

Example output:

02-02 12:57:30.481 10703 10703 I Netd    : Netd 1.0 starting
02-02 12:57:32.593 10703 10703 I Netd    : Creating child chains: 2105.7ms
02-02 12:57:32.594 10703 10703 I Netd    : Setting up OEM hooks: 1.0ms
02-02 12:57:32.703 10703 10703 I Netd    : Setting up FirewallController hooks: 109.5ms
02-02 12:57:32.859 10703 10703 I Netd    : Setting up NatController hooks: 156.0ms
02-02 12:57:32.867 10703 10703 I Netd    : Setting up BandwidthController hooks: 7.7ms
02-02 12:57:32.867 10703 10703 I Netd    : Setting up IdletimerController hooks: 0.1ms
02-02 12:57:32.876 10703 10703 I Netd    : Disabling bandwidth control: 8.9ms
02-02 12:57:32.920 10703 10703 E Netd    : netlink response contains error (File exists)
02-02 12:57:32.920 10703 10703 E Netd    : Can't add IPv4 default route to dummy0: File exists
02-02 12:57:32.921 10703 10703 I Netd    : Initializing RouteController: 44.7ms
02-02 12:57:32.935 10703 10703 I Netd    : Netd started in 2455ms

Test: builds, boots, log messages appear
Bug: 32323979
Change-Id: I54f167b5e9291b888dc72e03714c4f2718b23a8c

server/Controllers.cpp

diff --git a/server/Controllers.cpp b/server/Controllers.cpp
index cdc5dad..85b6b1e 100644
--- a/server/Controllers.cpp
+++ b/server/Controllers.cpp
@@ -14,10 +14,14 @@
  * limitations under the License.
  */
 
+#define LOG_TAG "Netd"
+#include <cutils/log.h>
+
 #include "Controllers.h"
 #include "IdletimerController.h"
 #include "NetworkController.h"
 #include "RouteController.h"
+#include "Stopwatch.h"
 #include "oem_iptables_hook.h"
 
 namespace android {
@@ -119,6 +123,7 @@
      */
 
     // Create chains for children modules
+    Stopwatch s;
     createChildChains(V4V6, "filter", "INPUT", FILTER_INPUT);
     createChildChains(V4V6, "filter", "FORWARD", FILTER_FORWARD);
     createChildChains(V4V6, "filter", "OUTPUT", FILTER_OUTPUT);
@@ -127,34 +132,46 @@
     createChildChains(V4V6, "mangle", "FORWARD", MANGLE_FORWARD);
     createChildChains(V4, "nat", "PREROUTING", NAT_PREROUTING);
     createChildChains(V4, "nat", "POSTROUTING", NAT_POSTROUTING);
+    ALOGI("Creating child chains: %.1fms", s.getTimeAndReset());
 
     // Let each module setup their child chains
     setupOemIptablesHook();
+    ALOGI("Setting up OEM hooks: %.1fms", s.getTimeAndReset());
 
     /* When enabled, DROPs all packets except those matching rules. */
     firewallCtrl.setupIptablesHooks();
+    ALOGI("Setting up FirewallController hooks: %.1fms", s.getTimeAndReset());
 
     /* Does DROPs in FORWARD by default */
     natCtrl.setupIptablesHooks();
+    ALOGI("Setting up NatController hooks: %.1fms", s.getTimeAndReset());
+
     /*
      * Does REJECT in INPUT, OUTPUT. Does counting also.
      * No DROP/REJECT allowed later in netfilter-flow hook order.
      */
     bandwidthCtrl.setupIptablesHooks();
+    ALOGI("Setting up BandwidthController hooks: %.1fms", s.getTimeAndReset());
+
     /*
      * Counts in nat: PREROUTING, POSTROUTING.
      * No DROP/REJECT allowed later in netfilter-flow hook order.
      */
     idletimerCtrl.setupIptablesHooks();
+    ALOGI("Setting up IdletimerController hooks: %.1fms", s.getTimeAndReset());
 }
 
 void Controllers::init() {
     initIptablesRules();
+
+    Stopwatch s;
     bandwidthCtrl.enableBandwidthControl(false);
+    ALOGI("Disabling bandwidth control: %.1fms", s.getTimeAndReset());
 
     if (int ret = RouteController::Init(NetworkController::LOCAL_NET_ID)) {
         ALOGE("failed to initialize RouteController (%s)", strerror(-ret));
     }
+    ALOGI("Initializing RouteController: %.1fms", s.getTimeAndReset());
 }
 
 Controllers* gCtls = nullptr;