Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 00072395 authored by Jeff Sharkey's avatar Jeff Sharkey
Browse files

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
parent 167032ab

services/core/java/com/android/server/net/NetworkPolicyManagerService.java

+9 −0
Original line number Diff line number Diff line
@@ -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);

    }



    /**

services/core/java/com/android/server/net/NetworkStatsService.java

+35 −9
Original line number Diff line number Diff line
@@ -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) {

            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) {

            Trace.traceBegin(TRACE_TAG_NETWORK, "getNetworkUidBytes");

            try {

                return NetworkStatsService.this.getNetworkUidBytes(template, start, end);

            } finally {

                Trace.traceEnd(TRACE_TAG_NETWORK);

            }

        }



        @Override