Add tracing for network statistics and policy.

These trace points surround areas of heavy lifting to help us debug
code that might be taking longer than expected.  (For example, slow
getting data from eBPF, slow recording into data structures, slow
writing to disk, or slow evaluating policy.)

Typical timings on a taimen:

performPollLocked:   25.5ms
snapshotUid:          4.4ms
snapshotXt:           1.4ms
[persisting]:        13.4ms
updateNotifications:  3.3ms

Bug: 77908520, 77808546, 77853238, 77154412
Test: builds, boots
Change-Id: I072bfecffee01eeec7e4cbad439bd1cdc166febc

diff --git a/services/core/java/com/android/server/net/NetworkPolicyManagerService.java b/services/core/java/com/android/server/net/NetworkPolicyManagerService.java
index 6c0a7a7..5b8e8c0 100644 (file)
--- a/services/core/java/com/android/server/net/NetworkPolicyManagerService.java
+++ b/services/core/java/com/android/server/net/NetworkPolicyManagerService.java
@@ -71,6 +71,7 @@ import static android.net.NetworkTemplate.MATCH_MOBILE;
 import static android.net.NetworkTemplate.MATCH_WIFI;
 import static android.net.NetworkTemplate.buildTemplateMobileAll;
 import static android.net.TrafficStats.MB_IN_BYTES;
+import static android.os.Trace.TRACE_TAG_NETWORK;
 import static android.provider.Settings.Global.NETPOLICY_OVERRIDE_ENABLED;
 import static android.provider.Settings.Global.NETPOLICY_QUOTA_ENABLED;
 import static android.provider.Settings.Global.NETPOLICY_QUOTA_FRAC_JOBS;
@@ -1100,6 +1101,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
      */
     void updateNotificationsNL() {
         if (LOGV) Slog.v(TAG, "updateNotificationsNL()");
+        Trace.traceBegin(TRACE_TAG_NETWORK, "updateNotificationsNL");
 
         // keep track of previously active notifications
         final ArraySet<NotificationId> beforeNotifs = new ArraySet<NotificationId>(mActiveNotifs);
@@ -1191,6 +1193,8 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
                 cancelNotification(notificationId);
             }
         }
+
+        Trace.traceEnd(TRACE_TAG_NETWORK);
     }
 
     /**
@@ -1604,6 +1608,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
      */
     void updateNetworkEnabledNL() {
         if (LOGV) Slog.v(TAG, "updateNetworkEnabledNL()");
+        Trace.traceBegin(TRACE_TAG_NETWORK, "updateNetworkEnabledNL");
 
         // TODO: reset any policy-disabled networks when any policy is removed
         // completely, which is currently rare case.
@@ -1633,6 +1638,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
         }
 
         mStatLogger.logDurationStat(Stats.UPDATE_NETWORK_ENABLED, startTime);
+        Trace.traceEnd(TRACE_TAG_NETWORK);
     }
 
     /**
@@ -1693,6 +1699,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
      */
     void updateNetworkRulesNL() {
         if (LOGV) Slog.v(TAG, "updateNetworkRulesNL()");
+        Trace.traceBegin(TRACE_TAG_NETWORK, "updateNetworkRulesNL");
 
         final NetworkState[] states;
         try {
@@ -1866,6 +1873,8 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
         mHandler.obtainMessage(MSG_METERED_IFACES_CHANGED, meteredIfaces).sendToTarget();
 
         mHandler.obtainMessage(MSG_ADVISE_PERSIST_THRESHOLD, lowestRule).sendToTarget();
+
+        Trace.traceEnd(TRACE_TAG_NETWORK);
     }
 
     /**

diff --git a/services/core/java/com/android/server/net/NetworkStatsService.java b/services/core/java/com/android/server/net/NetworkStatsService.java
index e7f92dc..7ee17bc 100644 (file)
--- a/services/core/java/com/android/server/net/NetworkStatsService.java
+++ b/services/core/java/com/android/server/net/NetworkStatsService.java
@@ -43,6 +43,7 @@ import static android.net.NetworkTemplate.buildTemplateMobileWildcard;
 import static android.net.NetworkTemplate.buildTemplateWifiWildcard;
 import static android.net.TrafficStats.KB_IN_BYTES;
 import static android.net.TrafficStats.MB_IN_BYTES;
+import static android.os.Trace.TRACE_TAG_NETWORK;
 import static android.provider.Settings.Global.NETSTATS_AUGMENT_ENABLED;
 import static android.provider.Settings.Global.NETSTATS_DEV_BUCKET_DURATION;
 import static android.provider.Settings.Global.NETSTATS_DEV_DELETE_AGE;
@@ -109,6 +110,7 @@ import android.os.Messenger;
 import android.os.PowerManager;
 import android.os.RemoteException;
 import android.os.SystemClock;
+import android.os.Trace;
 import android.os.UserHandle;
 import android.provider.Settings;
 import android.provider.Settings.Global;
@@ -1190,27 +1192,43 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
     private void recordSnapshotLocked(long currentTime) throws RemoteException {
         // snapshot and record current counters; read UID stats first to
         // avoid over counting dev stats.
+        Trace.traceBegin(TRACE_TAG_NETWORK, "snapshotUid");
         final NetworkStats uidSnapshot = getNetworkStatsUidDetail(INTERFACES_ALL);
+        Trace.traceEnd(TRACE_TAG_NETWORK);
+        Trace.traceBegin(TRACE_TAG_NETWORK, "snapshotXt");
         final NetworkStats xtSnapshot = getNetworkStatsXt();
+        Trace.traceEnd(TRACE_TAG_NETWORK);
+        Trace.traceBegin(TRACE_TAG_NETWORK, "snapshotDev");
         final NetworkStats devSnapshot = mNetworkManager.getNetworkStatsSummaryDev();
+        Trace.traceEnd(TRACE_TAG_NETWORK);
 
         // Tethering snapshot for dev and xt stats. Counts per-interface data from tethering stats
         // providers that isn't already counted by dev and XT stats.
+        Trace.traceBegin(TRACE_TAG_NETWORK, "snapshotTether");
         final NetworkStats tetherSnapshot = getNetworkStatsTethering(STATS_PER_IFACE);
+        Trace.traceEnd(TRACE_TAG_NETWORK);
         xtSnapshot.combineAllValues(tetherSnapshot);
         devSnapshot.combineAllValues(tetherSnapshot);
 
         // For xt/dev, we pass a null VPN array because usage is aggregated by UID, so VPN traffic
         // can't be reattributed to responsible apps.
+        Trace.traceBegin(TRACE_TAG_NETWORK, "recordDev");
         mDevRecorder.recordSnapshotLocked(
                 devSnapshot, mActiveIfaces, null /* vpnArray */, currentTime);
+        Trace.traceEnd(TRACE_TAG_NETWORK);
+        Trace.traceBegin(TRACE_TAG_NETWORK, "recordXt");
         mXtRecorder.recordSnapshotLocked(
                 xtSnapshot, mActiveIfaces, null /* vpnArray */, currentTime);
+        Trace.traceEnd(TRACE_TAG_NETWORK);
 
         // For per-UID stats, pass the VPN info so VPN traffic is reattributed to responsible apps.
         VpnInfo[] vpnArray = mConnManager.getAllVpnInfo();
+        Trace.traceBegin(TRACE_TAG_NETWORK, "recordUid");
         mUidRecorder.recordSnapshotLocked(uidSnapshot, mActiveUidIfaces, vpnArray, currentTime);
+        Trace.traceEnd(TRACE_TAG_NETWORK);
+        Trace.traceBegin(TRACE_TAG_NETWORK, "recordUidTag");
         mUidTagRecorder.recordSnapshotLocked(uidSnapshot, mActiveUidIfaces, vpnArray, currentTime);
+        Trace.traceEnd(TRACE_TAG_NETWORK);
 
         // We need to make copies of member fields that are sent to the observer to avoid
         // a race condition between the service handler thread and the observer's
@@ -1255,8 +1273,7 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
     private void performPollLocked(int flags) {
         if (!mSystemReady) return;
         if (LOGV) Slog.v(TAG, "performPollLocked(flags=0x" + Integer.toHexString(flags) + ")");
-
-        final long startRealtime = SystemClock.elapsedRealtime();
+        Trace.traceBegin(TRACE_TAG_NETWORK, "performPollLocked");
 
         final boolean persistNetwork = (flags & FLAG_PERSIST_NETWORK) != 0;
         final boolean persistUid = (flags & FLAG_PERSIST_UID) != 0;
@@ -1276,6 +1293,7 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
         }
 
         // persist any pending data depending on requested flags
+        Trace.traceBegin(TRACE_TAG_NETWORK, "[persisting]");
         if (persistForce) {
             mDevRecorder.forcePersistLocked(currentTime);
             mXtRecorder.forcePersistLocked(currentTime);
@@ -1291,11 +1309,7 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
                 mUidTagRecorder.maybePersistLocked(currentTime);
             }
         }
-
-        if (LOGV) {
-            final long duration = SystemClock.elapsedRealtime() - startRealtime;
-            Slog.v(TAG, "performPollLocked() took " + duration + "ms");
-        }
+        Trace.traceEnd(TRACE_TAG_NETWORK);
 
         if (mSettings.getSampleEnabled()) {
             // sample stats after each full poll
@@ -1307,6 +1321,8 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
         updatedIntent.setFlags(Intent.FLAG_RECEIVER_REGISTERED_ONLY);
         mContext.sendBroadcastAsUser(updatedIntent, UserHandle.ALL,
                 READ_NETWORK_USAGE_HISTORY);
+
+        Trace.traceEnd(TRACE_TAG_NETWORK);
     }
 
     /**
@@ -1389,12 +1405,22 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
     private class NetworkStatsManagerInternalImpl extends NetworkStatsManagerInternal {
         @Override
         public long getNetworkTotalBytes(NetworkTemplate template, long start, long end) {
-            return NetworkStatsService.this.getNetworkTotalBytes(template, start, end);
+            Trace.traceBegin(TRACE_TAG_NETWORK, "getNetworkTotalBytes");
+            try {
+                return NetworkStatsService.this.getNetworkTotalBytes(template, start, end);
+            } finally {
+                Trace.traceEnd(TRACE_TAG_NETWORK);
+            }
         }
 
         @Override
         public NetworkStats getNetworkUidBytes(NetworkTemplate template, long start, long end) {
-            return NetworkStatsService.this.getNetworkUidBytes(template, start, end);
+            Trace.traceBegin(TRACE_TAG_NETWORK, "getNetworkUidBytes");
+            try {
+                return NetworkStatsService.this.getNetworkUidBytes(template, start, end);
+            } finally {
+                Trace.traceEnd(TRACE_TAG_NETWORK);
+            }
         }
 
         @Override