From 1ba4d36e2c80d4fad53b7fa4a77ea767b5a581e8 Mon Sep 17 00:00:00 2001
From: Lorenzo Colitti <lorenzo@google.com>
Date: Sun, 10 Apr 2016 15:39:53 +0900
Subject: [PATCH] Improve Tethering and NativeDaemonConnector logging.

1. Deduplicate the Tethering message numbers, and use MessageUtils
   to convert them to strings.
2. Add a warning to NativeDaemonConnector when an unsolicited
   event is more than 500ms late or takes more than 500ms to
   process.

Bug: 27857665
Change-Id: I379aef9257027d1ccf30906e79c6389ef1f95420
---
 .../android/server/NativeDaemonConnector.java | 24 ++++++++++++++++---
 1 file changed, 21 insertions(+), 3 deletions(-)

diff --git a/services/core/java/com/android/server/NativeDaemonConnector.java b/services/core/java/com/android/server/NativeDaemonConnector.java
index d6dbad87b0..7db9be20e9 100644
--- a/services/core/java/com/android/server/NativeDaemonConnector.java
+++ b/services/core/java/com/android/server/NativeDaemonConnector.java
@@ -109,6 +109,14 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
         mDebug = debug;
     }
 
+    /**
+     * Like SystemClock.uptimeMillis, except truncated to an int so it will fit in a message arg.
+     * Inaccurate across 49.7 days of uptime, but only used for debugging.
+     */
+    private int uptimeMillisInt() {
+        return (int) SystemClock.uptimeMillis() & Integer.MAX_VALUE;
+    }
+
     /**
      * Yell loudly if someone tries making future {@link #execute(Command)}
      * calls while holding a lock on the given object.
@@ -134,7 +142,9 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
 
     @Override
     public boolean handleMessage(Message msg) {
-        String event = (String) msg.obj;
+        final String event = (String) msg.obj;
+        final int start = uptimeMillisInt();
+        final int sent = msg.arg1;
         try {
             if (!mCallbacks.onEvent(msg.what, event, NativeDaemonEvent.unescapeArgs(event))) {
                 log(String.format("Unhandled event '%s'", event));
@@ -145,6 +155,13 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
             if (mCallbacks.onCheckHoldWakeLock(msg.what) && mWakeLock != null) {
                 mWakeLock.release();
             }
+            final int end = uptimeMillisInt();
+            if (start > sent && start - sent > WARN_EXECUTE_DELAY_MS) {
+                loge(String.format("NDC event {%s} processed too late: %dms", event, start - sent));
+            }
+            if (end > start && end - start > WARN_EXECUTE_DELAY_MS) {
+                loge(String.format("NDC event {%s} took too long: %dms", event, end - start));
+            }
         }
         return true;
     }
@@ -214,8 +231,9 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
                                     mWakeLock.acquire();
                                     releaseWl = true;
                                 }
-                                if (mCallbackHandler.sendMessage(mCallbackHandler.obtainMessage(
-                                        event.getCode(), event.getRawEvent()))) {
+                                Message msg = mCallbackHandler.obtainMessage(
+                                        event.getCode(), uptimeMillisInt(), 0, event.getRawEvent());
+                                if (mCallbackHandler.sendMessage(msg)) {
                                     releaseWl = false;
                                 }
                             } else {