1/*
2 * Copyright (C) 2017 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License"); you may not
5 * use this file except in compliance with the License. You may obtain a copy
6 * of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
12 * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
13 * License for the specific language governing permissions and limitations
14 * under the License.
15 */
16package com.android.server.am;
17
18import android.annotation.Nullable;
19import android.bluetooth.BluetoothActivityEnergyInfo;
20import android.bluetooth.BluetoothAdapter;
21import android.content.Context;
22import android.net.wifi.IWifiManager;
23import android.net.wifi.WifiActivityEnergyInfo;
24import android.os.BatteryStats;
25import android.os.Parcelable;
26import android.os.RemoteException;
27import android.os.ServiceManager;
28import android.os.SynchronousResultReceiver;
29import android.os.SystemClock;
30import android.telephony.ModemActivityInfo;
31import android.telephony.TelephonyManager;
32import android.util.IntArray;
33import android.util.Slog;
34import android.util.TimeUtils;
35
36import com.android.internal.annotations.GuardedBy;
37import com.android.internal.os.BatteryStatsImpl;
38import com.android.internal.util.function.pooled.PooledLambda;
39
40import libcore.util.EmptyArray;
41
42import java.util.concurrent.CompletableFuture;
43import java.util.concurrent.ExecutorService;
44import java.util.concurrent.Executors;
45import java.util.concurrent.Future;
46import java.util.concurrent.ScheduledExecutorService;
47import java.util.concurrent.ScheduledFuture;
48import java.util.concurrent.ThreadFactory;
49import java.util.concurrent.TimeUnit;
50import java.util.concurrent.TimeoutException;
51
52/**
53 * A Worker that fetches data from external sources (WiFi controller, bluetooth chipset) on a
54 * dedicated thread and updates BatteryStatsImpl with that information.
55 *
56 * As much work as possible is done without holding the BatteryStatsImpl lock, and only the
57 * readily available data is pushed into BatteryStatsImpl with the lock held.
58 */
59class BatteryExternalStatsWorker implements BatteryStatsImpl.ExternalStatsSync {
60    private static final String TAG = "BatteryExternalStatsWorker";
61    private static final boolean DEBUG = false;
62
63    /**
64     * How long to wait on an individual subsystem to return its stats.
65     */
66    private static final long EXTERNAL_STATS_SYNC_TIMEOUT_MILLIS = 2000;
67
68    // There is some accuracy error in wifi reports so allow some slop in the results.
69    private static final long MAX_WIFI_STATS_SAMPLE_ERROR_MILLIS = 750;
70
71    private final ScheduledExecutorService mExecutorService =
72            Executors.newSingleThreadScheduledExecutor(
73                    (ThreadFactory) r -> {
74                        Thread t = new Thread(r, "batterystats-worker");
75                        t.setPriority(Thread.NORM_PRIORITY);
76                        return t;
77                    });
78
79    private final Context mContext;
80    private final BatteryStatsImpl mStats;
81
82    @GuardedBy("this")
83    private int mUpdateFlags = 0;
84
85    @GuardedBy("this")
86    private Future<?> mCurrentFuture = null;
87
88    @GuardedBy("this")
89    private String mCurrentReason = null;
90
91    @GuardedBy("this")
92    private boolean mOnBattery;
93
94    @GuardedBy("this")
95    private boolean mOnBatteryScreenOff;
96
97    @GuardedBy("this")
98    private boolean mUseLatestStates = true;
99
100    @GuardedBy("this")
101    private final IntArray mUidsToRemove = new IntArray();
102
103    @GuardedBy("this")
104    private Future<?> mWakelockChangesUpdate;
105
106    @GuardedBy("this")
107    private Future<?> mBatteryLevelSync;
108
109    private final Object mWorkerLock = new Object();
110
111    @GuardedBy("mWorkerLock")
112    private IWifiManager mWifiManager = null;
113
114    @GuardedBy("mWorkerLock")
115    private TelephonyManager mTelephony = null;
116
117    // WiFi keeps an accumulated total of stats, unlike Bluetooth.
118    // Keep the last WiFi stats so we can compute a delta.
119    @GuardedBy("mWorkerLock")
120    private WifiActivityEnergyInfo mLastInfo =
121            new WifiActivityEnergyInfo(0, 0, 0, new long[]{0}, 0, 0, 0, 0);
122
123    /**
124     * Timestamp at which all external stats were last collected in
125     * {@link SystemClock#elapsedRealtime()} time base.
126     */
127    @GuardedBy("this")
128    private long mLastCollectionTimeStamp;
129
130    BatteryExternalStatsWorker(Context context, BatteryStatsImpl stats) {
131        mContext = context;
132        mStats = stats;
133    }
134
135    @Override
136    public synchronized Future<?> scheduleSync(String reason, int flags) {
137        return scheduleSyncLocked(reason, flags);
138    }
139
140    @Override
141    public synchronized Future<?> scheduleCpuSyncDueToRemovedUid(int uid) {
142        mUidsToRemove.add(uid);
143        return scheduleSyncLocked("remove-uid", UPDATE_CPU);
144    }
145
146    @Override
147    public synchronized Future<?> scheduleCpuSyncDueToSettingChange() {
148        return scheduleSyncLocked("setting-change", UPDATE_CPU);
149    }
150
151    @Override
152    public Future<?> scheduleReadProcStateCpuTimes(
153            boolean onBattery, boolean onBatteryScreenOff, long delayMillis) {
154        synchronized (mStats) {
155            if (!mStats.trackPerProcStateCpuTimes()) {
156                return null;
157            }
158        }
159        synchronized (BatteryExternalStatsWorker.this) {
160            if (!mExecutorService.isShutdown()) {
161                return mExecutorService.schedule(PooledLambda.obtainRunnable(
162                        BatteryStatsImpl::updateProcStateCpuTimes,
163                        mStats, onBattery, onBatteryScreenOff).recycleOnUse(),
164                        delayMillis, TimeUnit.MILLISECONDS);
165            }
166        }
167        return null;
168    }
169
170    @Override
171    public Future<?> scheduleCopyFromAllUidsCpuTimes(
172            boolean onBattery, boolean onBatteryScreenOff) {
173        synchronized (mStats) {
174            if (!mStats.trackPerProcStateCpuTimes()) {
175                return null;
176            }
177        }
178        synchronized (BatteryExternalStatsWorker.this) {
179            if (!mExecutorService.isShutdown()) {
180                return mExecutorService.submit(PooledLambda.obtainRunnable(
181                        BatteryStatsImpl::copyFromAllUidsCpuTimes,
182                        mStats, onBattery, onBatteryScreenOff).recycleOnUse());
183            }
184        }
185        return null;
186    }
187
188    @Override
189    public Future<?> scheduleCpuSyncDueToScreenStateChange(
190            boolean onBattery, boolean onBatteryScreenOff) {
191        synchronized (BatteryExternalStatsWorker.this) {
192            if (mCurrentFuture == null || (mUpdateFlags & UPDATE_CPU) == 0) {
193                mOnBattery = onBattery;
194                mOnBatteryScreenOff = onBatteryScreenOff;
195                mUseLatestStates = false;
196            }
197            return scheduleSyncLocked("screen-state", UPDATE_CPU);
198        }
199    }
200
201    @Override
202    public Future<?> scheduleCpuSyncDueToWakelockChange(long delayMillis) {
203        synchronized (BatteryExternalStatsWorker.this) {
204            mWakelockChangesUpdate = scheduleDelayedSyncLocked(mWakelockChangesUpdate,
205                    () -> {
206                        scheduleSync("wakelock-change", UPDATE_CPU);
207                        scheduleRunnable(() -> mStats.postBatteryNeedsCpuUpdateMsg());
208                    },
209                    delayMillis);
210            return mWakelockChangesUpdate;
211        }
212    }
213
214    @Override
215    public void cancelCpuSyncDueToWakelockChange() {
216        synchronized (BatteryExternalStatsWorker.this) {
217            if (mWakelockChangesUpdate != null) {
218                mWakelockChangesUpdate.cancel(false);
219                mWakelockChangesUpdate = null;
220            }
221        }
222    }
223
224    @Override
225    public Future<?> scheduleSyncDueToBatteryLevelChange(long delayMillis) {
226        synchronized (BatteryExternalStatsWorker.this) {
227            mBatteryLevelSync = scheduleDelayedSyncLocked(mBatteryLevelSync,
228                    () -> scheduleSync("battery-level", UPDATE_ALL),
229                    delayMillis);
230            return mBatteryLevelSync;
231        }
232    }
233
234    @GuardedBy("this")
235    private void cancelSyncDueToBatteryLevelChangeLocked() {
236        if (mBatteryLevelSync != null) {
237            mBatteryLevelSync.cancel(false);
238            mBatteryLevelSync = null;
239        }
240    }
241
242    /**
243     * Schedule a sync {@param syncRunnable} with a delay. If there's already a scheduled sync, a
244     * new sync won't be scheduled unless it is being scheduled to run immediately (delayMillis=0).
245     *
246     * @param lastScheduledSync the task which was earlier scheduled to run
247     * @param syncRunnable the task that needs to be scheduled to run
248     * @param delayMillis time after which {@param syncRunnable} needs to be scheduled
249     * @return scheduled {@link Future} which can be used to check if task is completed or to
250     *         cancel it if needed
251     */
252    @GuardedBy("this")
253    private Future<?> scheduleDelayedSyncLocked(Future<?> lastScheduledSync, Runnable syncRunnable,
254            long delayMillis) {
255        if (mExecutorService.isShutdown()) {
256            return CompletableFuture.failedFuture(new IllegalStateException("worker shutdown"));
257        }
258
259        if (lastScheduledSync != null) {
260            // If there's already a scheduled task, leave it as is if we're trying to
261            // re-schedule it again with a delay, otherwise cancel and re-schedule it.
262            if (delayMillis == 0) {
263                lastScheduledSync.cancel(false);
264            } else {
265                return lastScheduledSync;
266            }
267        }
268
269        return mExecutorService.schedule(syncRunnable, delayMillis, TimeUnit.MILLISECONDS);
270    }
271
272    public synchronized Future<?> scheduleWrite() {
273        if (mExecutorService.isShutdown()) {
274            return CompletableFuture.failedFuture(new IllegalStateException("worker shutdown"));
275        }
276
277        scheduleSyncLocked("write", UPDATE_ALL);
278        // Since we use a single threaded executor, we can assume the next scheduled task's
279        // Future finishes after the sync.
280        return mExecutorService.submit(mWriteTask);
281    }
282
283    /**
284     * Schedules a task to run on the BatteryExternalStatsWorker thread. If scheduling more work
285     * within the task, never wait on the resulting Future. This will result in a deadlock.
286     */
287    public synchronized void scheduleRunnable(Runnable runnable) {
288        if (!mExecutorService.isShutdown()) {
289            mExecutorService.submit(runnable);
290        }
291    }
292
293    public void shutdown() {
294        mExecutorService.shutdownNow();
295    }
296
297    @GuardedBy("this")
298    private Future<?> scheduleSyncLocked(String reason, int flags) {
299        if (mExecutorService.isShutdown()) {
300            return CompletableFuture.failedFuture(new IllegalStateException("worker shutdown"));
301        }
302
303        if (mCurrentFuture == null) {
304            mUpdateFlags = flags;
305            mCurrentReason = reason;
306            mCurrentFuture = mExecutorService.submit(mSyncTask);
307        }
308        mUpdateFlags |= flags;
309        return mCurrentFuture;
310    }
311
312    long getLastCollectionTimeStamp() {
313        synchronized (this) {
314            return mLastCollectionTimeStamp;
315        }
316    }
317
318    private final Runnable mSyncTask = new Runnable() {
319        @Override
320        public void run() {
321            // Capture a snapshot of the state we are meant to process.
322            final int updateFlags;
323            final String reason;
324            final int[] uidsToRemove;
325            final boolean onBattery;
326            final boolean onBatteryScreenOff;
327            final boolean useLatestStates;
328            synchronized (BatteryExternalStatsWorker.this) {
329                updateFlags = mUpdateFlags;
330                reason = mCurrentReason;
331                uidsToRemove = mUidsToRemove.size() > 0 ? mUidsToRemove.toArray() : EmptyArray.INT;
332                onBattery = mOnBattery;
333                onBatteryScreenOff = mOnBatteryScreenOff;
334                useLatestStates = mUseLatestStates;
335                mUpdateFlags = 0;
336                mCurrentReason = null;
337                mUidsToRemove.clear();
338                mCurrentFuture = null;
339                mUseLatestStates = true;
340                if ((updateFlags & UPDATE_ALL) != 0) {
341                    cancelSyncDueToBatteryLevelChangeLocked();
342                }
343                if ((updateFlags & UPDATE_CPU) != 0) {
344                    cancelCpuSyncDueToWakelockChange();
345                }
346            }
347
348            try {
349                synchronized (mWorkerLock) {
350                    if (DEBUG) {
351                        Slog.d(TAG, "begin updateExternalStatsSync reason=" + reason);
352                    }
353                    try {
354                        updateExternalStatsLocked(reason, updateFlags, onBattery,
355                                onBatteryScreenOff, useLatestStates);
356                    } finally {
357                        if (DEBUG) {
358                            Slog.d(TAG, "end updateExternalStatsSync");
359                        }
360                    }
361                }
362
363                if ((updateFlags & UPDATE_CPU) != 0) {
364                    mStats.copyFromAllUidsCpuTimes();
365                }
366
367                // Clean up any UIDs if necessary.
368                synchronized (mStats) {
369                    for (int uid : uidsToRemove) {
370                        mStats.removeIsolatedUidLocked(uid);
371                    }
372                    mStats.clearPendingRemovedUids();
373                }
374            } catch (Exception e) {
375                Slog.wtf(TAG, "Error updating external stats: ", e);
376            }
377
378            synchronized (BatteryExternalStatsWorker.this) {
379                mLastCollectionTimeStamp = SystemClock.elapsedRealtime();
380            }
381        }
382    };
383
384    private final Runnable mWriteTask = new Runnable() {
385        @Override
386        public void run() {
387            synchronized (mStats) {
388                mStats.writeAsyncLocked();
389            }
390        }
391    };
392
393    @GuardedBy("mWorkerLock")
394    private void updateExternalStatsLocked(final String reason, int updateFlags,
395            boolean onBattery, boolean onBatteryScreenOff, boolean useLatestStates) {
396        // We will request data from external processes asynchronously, and wait on a timeout.
397        SynchronousResultReceiver wifiReceiver = null;
398        SynchronousResultReceiver bluetoothReceiver = null;
399        SynchronousResultReceiver modemReceiver = null;
400
401        if ((updateFlags & BatteryStatsImpl.ExternalStatsSync.UPDATE_WIFI) != 0) {
402            // We were asked to fetch WiFi data.
403            if (mWifiManager == null) {
404                mWifiManager = IWifiManager.Stub.asInterface(ServiceManager.getService(
405                        Context.WIFI_SERVICE));
406            }
407
408            if (mWifiManager != null) {
409                try {
410                    wifiReceiver = new SynchronousResultReceiver("wifi");
411                    mWifiManager.requestActivityInfo(wifiReceiver);
412                } catch (RemoteException e) {
413                    // Oh well.
414                }
415            }
416        }
417
418        if ((updateFlags & BatteryStatsImpl.ExternalStatsSync.UPDATE_BT) != 0) {
419            // We were asked to fetch Bluetooth data.
420            final BluetoothAdapter adapter = BluetoothAdapter.getDefaultAdapter();
421            if (adapter != null) {
422                bluetoothReceiver = new SynchronousResultReceiver("bluetooth");
423                adapter.requestControllerActivityEnergyInfo(bluetoothReceiver);
424            }
425        }
426
427        if ((updateFlags & BatteryStatsImpl.ExternalStatsSync.UPDATE_RADIO) != 0) {
428            // We were asked to fetch Telephony data.
429            if (mTelephony == null) {
430                mTelephony = TelephonyManager.from(mContext);
431            }
432
433            if (mTelephony != null) {
434                modemReceiver = new SynchronousResultReceiver("telephony");
435                mTelephony.requestModemActivityInfo(modemReceiver);
436            }
437        }
438
439        final WifiActivityEnergyInfo wifiInfo = awaitControllerInfo(wifiReceiver);
440        final BluetoothActivityEnergyInfo bluetoothInfo = awaitControllerInfo(bluetoothReceiver);
441        final ModemActivityInfo modemInfo = awaitControllerInfo(modemReceiver);
442
443        synchronized (mStats) {
444            mStats.addHistoryEventLocked(
445                    SystemClock.elapsedRealtime(),
446                    SystemClock.uptimeMillis(),
447                    BatteryStats.HistoryItem.EVENT_COLLECT_EXTERNAL_STATS,
448                    reason, 0);
449
450            if ((updateFlags & UPDATE_CPU) != 0) {
451                if (useLatestStates) {
452                    onBattery = mStats.isOnBatteryLocked();
453                    onBatteryScreenOff = mStats.isOnBatteryScreenOffLocked();
454                }
455                mStats.updateCpuTimeLocked(onBattery, onBatteryScreenOff);
456            }
457
458            if ((updateFlags & UPDATE_ALL) != 0) {
459                mStats.updateKernelWakelocksLocked();
460                mStats.updateKernelMemoryBandwidthLocked();
461            }
462
463            if ((updateFlags & UPDATE_RPM) != 0) {
464                mStats.updateRpmStatsLocked();
465            }
466
467            if (bluetoothInfo != null) {
468                if (bluetoothInfo.isValid()) {
469                    mStats.updateBluetoothStateLocked(bluetoothInfo);
470                } else {
471                    Slog.w(TAG, "bluetooth info is invalid: " + bluetoothInfo);
472                }
473            }
474        }
475
476        // WiFi and Modem state are updated without the mStats lock held, because they
477        // do some network stats retrieval before internally grabbing the mStats lock.
478
479        if (wifiInfo != null) {
480            if (wifiInfo.isValid()) {
481                mStats.updateWifiState(extractDeltaLocked(wifiInfo));
482            } else {
483                Slog.w(TAG, "wifi info is invalid: " + wifiInfo);
484            }
485        }
486
487        if (modemInfo != null) {
488            if (modemInfo.isValid()) {
489                mStats.updateMobileRadioState(modemInfo);
490            } else {
491                Slog.w(TAG, "modem info is invalid: " + modemInfo);
492            }
493        }
494    }
495
496    /**
497     * Helper method to extract the Parcelable controller info from a
498     * SynchronousResultReceiver.
499     */
500    private static <T extends Parcelable> T awaitControllerInfo(
501            @Nullable SynchronousResultReceiver receiver) {
502        if (receiver == null) {
503            return null;
504        }
505
506        try {
507            final SynchronousResultReceiver.Result result =
508                    receiver.awaitResult(EXTERNAL_STATS_SYNC_TIMEOUT_MILLIS);
509            if (result.bundle != null) {
510                // This is the final destination for the Bundle.
511                result.bundle.setDefusable(true);
512
513                final T data = result.bundle.getParcelable(
514                        BatteryStats.RESULT_RECEIVER_CONTROLLER_KEY);
515                if (data != null) {
516                    return data;
517                }
518            }
519            Slog.e(TAG, "no controller energy info supplied for " + receiver.getName());
520        } catch (TimeoutException e) {
521            Slog.w(TAG, "timeout reading " + receiver.getName() + " stats");
522        }
523        return null;
524    }
525
526    @GuardedBy("mWorkerLock")
527    private WifiActivityEnergyInfo extractDeltaLocked(WifiActivityEnergyInfo latest) {
528        final long timePeriodMs = latest.mTimestamp - mLastInfo.mTimestamp;
529        final long lastScanMs = mLastInfo.mControllerScanTimeMs;
530        final long lastIdleMs = mLastInfo.mControllerIdleTimeMs;
531        final long lastTxMs = mLastInfo.mControllerTxTimeMs;
532        final long lastRxMs = mLastInfo.mControllerRxTimeMs;
533        final long lastEnergy = mLastInfo.mControllerEnergyUsed;
534
535        // We will modify the last info object to be the delta, and store the new
536        // WifiActivityEnergyInfo object as our last one.
537        final WifiActivityEnergyInfo delta = mLastInfo;
538        delta.mTimestamp = latest.getTimeStamp();
539        delta.mStackState = latest.getStackState();
540
541        final long txTimeMs = latest.mControllerTxTimeMs - lastTxMs;
542        final long rxTimeMs = latest.mControllerRxTimeMs - lastRxMs;
543        final long idleTimeMs = latest.mControllerIdleTimeMs - lastIdleMs;
544        final long scanTimeMs = latest.mControllerScanTimeMs - lastScanMs;
545
546        if (txTimeMs < 0 || rxTimeMs < 0 || scanTimeMs < 0) {
547            // The stats were reset by the WiFi system (which is why our delta is negative).
548            // Returns the unaltered stats.
549            delta.mControllerEnergyUsed = latest.mControllerEnergyUsed;
550            delta.mControllerRxTimeMs = latest.mControllerRxTimeMs;
551            delta.mControllerTxTimeMs = latest.mControllerTxTimeMs;
552            delta.mControllerIdleTimeMs = latest.mControllerIdleTimeMs;
553            delta.mControllerScanTimeMs = latest.mControllerScanTimeMs;
554            Slog.v(TAG, "WiFi energy data was reset, new WiFi energy data is " + delta);
555        } else {
556            final long totalActiveTimeMs = txTimeMs + rxTimeMs;
557            long maxExpectedIdleTimeMs;
558            if (totalActiveTimeMs > timePeriodMs) {
559                // Cap the max idle time at zero since the active time consumed the whole time
560                maxExpectedIdleTimeMs = 0;
561                if (totalActiveTimeMs > timePeriodMs + MAX_WIFI_STATS_SAMPLE_ERROR_MILLIS) {
562                    StringBuilder sb = new StringBuilder();
563                    sb.append("Total Active time ");
564                    TimeUtils.formatDuration(totalActiveTimeMs, sb);
565                    sb.append(" is longer than sample period ");
566                    TimeUtils.formatDuration(timePeriodMs, sb);
567                    sb.append(".\n");
568                    sb.append("Previous WiFi snapshot: ").append("idle=");
569                    TimeUtils.formatDuration(lastIdleMs, sb);
570                    sb.append(" rx=");
571                    TimeUtils.formatDuration(lastRxMs, sb);
572                    sb.append(" tx=");
573                    TimeUtils.formatDuration(lastTxMs, sb);
574                    sb.append(" e=").append(lastEnergy);
575                    sb.append("\n");
576                    sb.append("Current WiFi snapshot: ").append("idle=");
577                    TimeUtils.formatDuration(latest.mControllerIdleTimeMs, sb);
578                    sb.append(" rx=");
579                    TimeUtils.formatDuration(latest.mControllerRxTimeMs, sb);
580                    sb.append(" tx=");
581                    TimeUtils.formatDuration(latest.mControllerTxTimeMs, sb);
582                    sb.append(" e=").append(latest.mControllerEnergyUsed);
583                    Slog.wtf(TAG, sb.toString());
584                }
585            } else {
586                maxExpectedIdleTimeMs = timePeriodMs - totalActiveTimeMs;
587            }
588            // These times seem to be the most reliable.
589            delta.mControllerTxTimeMs = txTimeMs;
590            delta.mControllerRxTimeMs = rxTimeMs;
591            delta.mControllerScanTimeMs = scanTimeMs;
592            // WiFi calculates the idle time as a difference from the on time and the various
593            // Rx + Tx times. There seems to be some missing time there because this sometimes
594            // becomes negative. Just cap it at 0 and ensure that it is less than the expected idle
595            // time from the difference in timestamps.
596            // b/21613534
597            delta.mControllerIdleTimeMs = Math.min(maxExpectedIdleTimeMs, Math.max(0, idleTimeMs));
598            delta.mControllerEnergyUsed = Math.max(0, latest.mControllerEnergyUsed - lastEnergy);
599        }
600
601        mLastInfo = latest;
602        return delta;
603    }
604}
605