Update NTP outside locks, log large trim events.

Move NTP updates outside locks to avoid blocking ShutdownThread.  Add
logging around trim events that remove substantial history.  Include
history start in sample events.

Bug: 5627247, 5584564
Change-Id: If9bbd93842c710efcdec94e68da87e9e42a5f961

3 files changed, 64 insertions, 19 deletions

diff --git a/services/java/com/android/server/EventLogTags.logtags b/services/java/com/android/server/EventLogTags.logtags
index a7eff93..5408436 100644
--- a/services/java/com/android/server/EventLogTags.logtags
+++ b/services/java/com/android/server/EventLogTags.logtags
@@ -142,5 +142,5 @@ option java_package com.android.server
 # ---------------------------
 # NetworkStatsService.java
 # ---------------------------
-51100 netstats_mobile_sample (dev_rx_bytes|2|2),(dev_tx_bytes|2|2),(dev_rx_pkts|2|1),(dev_tx_pkts|2|1),(xt_rx_bytes|2|2),(xt_tx_bytes|2|2),(xt_rx_pkts|2|1),(xt_tx_pkts|2|1),(uid_rx_bytes|2|2),(uid_tx_bytes|2|2),(uid_rx_pkts|2|1),(uid_tx_pkts|2|1),(trusted_time|2|3)
-51101 netstats_wifi_sample (dev_rx_bytes|2|2),(dev_tx_bytes|2|2),(dev_rx_pkts|2|1),(dev_tx_pkts|2|1),(xt_rx_bytes|2|2),(xt_tx_bytes|2|2),(xt_rx_pkts|2|1),(xt_tx_pkts|2|1),(uid_rx_bytes|2|2),(uid_tx_bytes|2|2),(uid_rx_pkts|2|1),(uid_tx_pkts|2|1),(trusted_time|2|3)
+51100 netstats_mobile_sample (dev_rx_bytes|2|2),(dev_tx_bytes|2|2),(dev_rx_pkts|2|1),(dev_tx_pkts|2|1),(xt_rx_bytes|2|2),(xt_tx_bytes|2|2),(xt_rx_pkts|2|1),(xt_tx_pkts|2|1),(uid_rx_bytes|2|2),(uid_tx_bytes|2|2),(uid_rx_pkts|2|1),(uid_tx_pkts|2|1),(trusted_time|2|3),(dev_history_start|2|3)
+51101 netstats_wifi_sample (dev_rx_bytes|2|2),(dev_tx_bytes|2|2),(dev_rx_pkts|2|1),(dev_tx_pkts|2|1),(xt_rx_bytes|2|2),(xt_tx_bytes|2|2),(xt_rx_pkts|2|1),(xt_tx_pkts|2|1),(uid_rx_bytes|2|2),(uid_tx_bytes|2|2),(uid_rx_pkts|2|1),(uid_tx_pkts|2|1),(trusted_time|2|3),(dev_history_start|2|3)
diff --git a/services/java/com/android/server/net/NetworkPolicyManagerService.java b/services/java/com/android/server/net/NetworkPolicyManagerService.java
index 2a1b1db..8c0f1e0 100644
--- a/services/java/com/android/server/net/NetworkPolicyManagerService.java
+++ b/services/java/com/android/server/net/NetworkPolicyManagerService.java
@@ -393,6 +393,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
             // on background handler thread, and verified
             // READ_NETWORK_USAGE_HISTORY permission above.
 
+            maybeRefreshTrustedTime();
             synchronized (mRulesLock) {
                 updateNetworkEnabledLocked();
                 updateNotificationsLocked();
@@ -445,7 +446,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
         // cycle boundary to recompute notifications.
 
         // examine stats for each active policy
-        final long currentTime = currentTimeMillis(true);
+        final long currentTime = currentTimeMillis();
         for (NetworkPolicy policy : mNetworkPolicy.values()) {
             // ignore policies that aren't relevant to user
             if (!isTemplateRelevant(policy.template)) continue;
@@ -683,6 +684,8 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
         public void onReceive(Context context, Intent intent) {
             // on background handler thread, and verified CONNECTIVITY_INTERNAL
             // permission above.
+
+            maybeRefreshTrustedTime();
             synchronized (mRulesLock) {
                 ensureActiveMobilePolicyLocked();
                 updateNetworkEnabledLocked();
@@ -702,7 +705,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
         // TODO: reset any policy-disabled networks when any policy is removed
         // completely, which is currently rare case.
 
-        final long currentTime = currentTimeMillis(true);
+        final long currentTime = currentTimeMillis();
         for (NetworkPolicy policy : mNetworkPolicy.values()) {
             // shortcut when policy has no limit
             if (policy.limitBytes == LIMIT_DISABLED) {
@@ -802,7 +805,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
 
         // apply each policy that we found ifaces for; compute remaining data
         // based on current cycle and historical stats, and push to kernel.
-        final long currentTime = currentTimeMillis(true);
+        final long currentTime = currentTimeMillis();
         for (NetworkPolicy policy : mNetworkRules.keySet()) {
             final String[] ifaces = mNetworkRules.get(policy);
 
@@ -1092,6 +1095,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
     public void setNetworkPolicies(NetworkPolicy[] policies) {
         mContext.enforceCallingOrSelfPermission(MANAGE_NETWORK_POLICY, TAG);
 
+        maybeRefreshTrustedTime();
         synchronized (mRulesLock) {
             mNetworkPolicy.clear();
             for (NetworkPolicy policy : policies) {
@@ -1119,7 +1123,8 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
     public void snoozePolicy(NetworkTemplate template) {
         mContext.enforceCallingOrSelfPermission(MANAGE_NETWORK_POLICY, TAG);
 
-        final long currentTime = currentTimeMillis(true);
+        maybeRefreshTrustedTime();
+        final long currentTime = currentTimeMillis();
         synchronized (mRulesLock) {
             // find and snooze local policy that matches
             final NetworkPolicy policy = mNetworkPolicy.get(template);
@@ -1140,6 +1145,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
     public void setRestrictBackground(boolean restrictBackground) {
         mContext.enforceCallingOrSelfPermission(MANAGE_NETWORK_POLICY, TAG);
 
+        maybeRefreshTrustedTime();
         synchronized (mRulesLock) {
             mRestrictBackground = restrictBackground;
             updateRulesForRestrictBackgroundLocked();
@@ -1193,7 +1199,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
             return null;
         }
 
-        final long currentTime = currentTimeMillis(false);
+        final long currentTime = currentTimeMillis();
 
         // find total bytes used under policy
         final long start = computeLastCycleBoundary(currentTime, policy);
@@ -1472,6 +1478,7 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
                 case MSG_LIMIT_REACHED: {
                     final String iface = (String) msg.obj;
 
+                    maybeRefreshTrustedTime();
                     synchronized (mRulesLock) {
                         if (mMeteredIfaces.contains(iface)) {
                             try {
@@ -1551,12 +1558,16 @@ public class NetworkPolicyManagerService extends INetworkPolicyManager.Stub {
         }
     }
 
-    private long currentTimeMillis(boolean allowRefresh) {
-        // try refreshing time source when stale
-        if (mTime.getCacheAge() > TIME_CACHE_MAX_AGE && allowRefresh) {
+    /**
+     * Try refreshing {@link #mTime} when stale.
+     */
+    private void maybeRefreshTrustedTime() {
+        if (mTime.getCacheAge() > TIME_CACHE_MAX_AGE) {
             mTime.forceRefresh();
         }
+    }
 
+    private long currentTimeMillis() {
         return mTime.hasCache() ? mTime.currentTimeMillis() : System.currentTimeMillis();
     }
 
diff --git a/services/java/com/android/server/net/NetworkStatsService.java b/services/java/com/android/server/net/NetworkStatsService.java
index 28cb983..b77e67e 100644
--- a/services/java/com/android/server/net/NetworkStatsService.java
+++ b/services/java/com/android/server/net/NetworkStatsService.java
@@ -472,6 +472,18 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
         }
     }
 
+    private long getHistoryStartLocked(
+            NetworkTemplate template, HashMap<NetworkIdentitySet, NetworkStatsHistory> source) {
+        long start = Long.MAX_VALUE;
+        for (NetworkIdentitySet ident : source.keySet()) {
+            if (templateMatches(template, ident)) {
+                final NetworkStatsHistory history = source.get(ident);
+                start = Math.min(start, history.getStart());
+            }
+        }
+        return start;
+    }
+
     @Override
     public NetworkStats getSummaryForAllUid(
             NetworkTemplate template, long start, long end, boolean includeTags) {
@@ -771,6 +783,12 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
     private void performPoll(int flags) {
         synchronized (mStatsLock) {
             mWakeLock.acquire();
+
+            // try refreshing time source when stale
+            if (mTime.getCacheAge() > mSettings.getTimeCacheMaxAge()) {
+                mTime.forceRefresh();
+            }
+
             try {
                 performPollLocked(flags);
             } finally {
@@ -791,11 +809,6 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
         final boolean persistUid = (flags & FLAG_PERSIST_UID) != 0;
         final boolean persistForce = (flags & FLAG_PERSIST_FORCE) != 0;
 
-        // try refreshing time source when stale
-        if (mTime.getCacheAge() > mSettings.getTimeCacheMaxAge()) {
-            mTime.forceRefresh();
-        }
-
         // TODO: consider marking "untrusted" times in historical stats
         final long currentTime = mTime.hasCache() ? mTime.currentTimeMillis()
                 : System.currentTimeMillis();
@@ -981,6 +994,7 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
         final long start = end - largestBucketSize;
 
         final long trustedTime = mTime.hasCache() ? mTime.currentTimeMillis() : -1;
+        long devHistoryStart = Long.MAX_VALUE;
 
         NetworkTemplate template = null;
         NetworkStats.Entry devTotal = null;
@@ -990,24 +1004,27 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
         // collect mobile sample
         template = buildTemplateMobileAll(getActiveSubscriberId(mContext));
         devTotal = getSummaryForNetworkDev(template, start, end).getTotal(devTotal);
+        devHistoryStart = getHistoryStartLocked(template, mNetworkDevStats);
         xtTotal = getSummaryForNetworkXt(template, start, end).getTotal(xtTotal);
         uidTotal = getSummaryForAllUid(template, start, end, false).getTotal(uidTotal);
+
         EventLogTags.writeNetstatsMobileSample(
                 devTotal.rxBytes, devTotal.rxPackets, devTotal.txBytes, devTotal.txPackets,
                 xtTotal.rxBytes, xtTotal.rxPackets, xtTotal.txBytes, xtTotal.txPackets,
                 uidTotal.rxBytes, uidTotal.rxPackets, uidTotal.txBytes, uidTotal.txPackets,
-                trustedTime);
+                trustedTime, devHistoryStart);
 
         // collect wifi sample
         template = buildTemplateWifi();
         devTotal = getSummaryForNetworkDev(template, start, end).getTotal(devTotal);
+        devHistoryStart = getHistoryStartLocked(template, mNetworkDevStats);
         xtTotal = getSummaryForNetworkXt(template, start, end).getTotal(xtTotal);
         uidTotal = getSummaryForAllUid(template, start, end, false).getTotal(uidTotal);
         EventLogTags.writeNetstatsWifiSample(
                 devTotal.rxBytes, devTotal.rxPackets, devTotal.txBytes, devTotal.txPackets,
                 xtTotal.rxBytes, xtTotal.rxPackets, xtTotal.txBytes, xtTotal.txPackets,
                 uidTotal.rxBytes, uidTotal.rxPackets, uidTotal.txBytes, uidTotal.txPackets,
-                trustedTime);
+                trustedTime, devHistoryStart);
     }
 
     /**
@@ -1243,11 +1260,28 @@ public class NetworkStatsService extends INetworkStatsService.Stub {
 
         // trim any history beyond max
         if (mTime.hasCache()) {
-            final long currentTime = Math.min(
-                    System.currentTimeMillis(), mTime.currentTimeMillis());
+            final long systemCurrentTime = System.currentTimeMillis();
+            final long trustedCurrentTime = mTime.currentTimeMillis();
+
+            final long currentTime = Math.min(systemCurrentTime, trustedCurrentTime);
             final long maxHistory = mSettings.getNetworkMaxHistory();
+
             for (NetworkStatsHistory history : input.values()) {
+                final int beforeSize = history.size();
                 history.removeBucketsBefore(currentTime - maxHistory);
+                final int afterSize = history.size();
+
+                if (beforeSize > 24 && afterSize < beforeSize / 2) {
+                    // yikes, dropping more than half of significant history
+                    final StringBuilder builder = new StringBuilder();
+                    builder.append("yikes, dropping more than half of history").append('\n');
+                    builder.append("systemCurrentTime=").append(systemCurrentTime).append('\n');
+                    builder.append("trustedCurrentTime=").append(trustedCurrentTime).append('\n');
+                    builder.append("maxHistory=").append(maxHistory).append('\n');
+                    builder.append("beforeSize=").append(beforeSize).append('\n');
+                    builder.append("afterSize=").append(afterSize).append('\n');
+                    mDropBox.addText(TAG_NETSTATS_ERROR, builder.toString());
+                }
             }
         }