一天总时间 | 起始时间 | 测试时长(s) | 结束时间 | 平均电流(mA) | 总电量消耗(uAh) | |||||||
86400 | 15:43:49 | 366 | 15:49:55 | 8.6 | 875 | |||||||
波形偏移-Begin | 波形开始 | 波形偏移-End | 波形结束 | 波形持续时长 | 平均电流(mA) | 电量消耗(uAh) | 占总电量 | Kernel层唤醒源 | 联网次数统计 | 应用层唤醒源 | ||
61 | 15:44:50 | 75.5 | 15:45:04 | 14.5 | 107 | 422 | ||||||
124 | 15:45:53 | 155 | 15:46:24 | 0 | 0 | 0 | ||||||
0 | 15:43:49 | 224 | 15:47:33 | 0 | 0 | 0 | ||||||
0 | 15:43:49 | 272 | 15:48:21 | 0 | 0 | 0 | ||||||
0 | 15:43:49 | 328 | 15:49:17 | 0 | 0 | 0 | ||||||
0 | 15:43:49 | 388 | 15:50:17 | 0 | 0 | 0 | ||||||
0 | 15:43:49 | 568 | 15:53:17 | 0 | 0 | 0 |
PowerMonitor唤醒时刻:
波形偏移-Begin 波形开始 波形偏移-End 波形结束 波形持续时长 平均电流(mA) 电量消耗(uAh)
166.5 15:49:18 176 15:49:28 9.5 61 253
Kernel唤醒时间:
<6>[ 682.201183] PM: suspend exit 2019-04-22 07:49:19.840593515 UTC
上层唤醒:
04-22 15:49:19.807 1155 1405 D PowerManagerService: acquireWakeLockInternal: lock=66661536, flags=0x1, tag="*alarm*", ws=WorkSource{1000}, uid=1000, pid=1155, packageName=android
04-22 15:49:29.379 1155 1155 D PowerManagerService: releaseWakeLockInternal: lock=66661536 [*alarm*], flags=0x0, total_time=9572ms, ws/pid/uid=WorkSource{1000}/1155/1000, packageName=android
04-22 15:49:19.807 1155 1431 D PowerManagerService: acquireWakeLockInternal: lock=127480608, flags=0x1, tag="NetworkStats", ws=null, uid=1000, pid=1155, packageName=android
04-22 15:49:19.825 1155 1431 D PowerManagerService: releaseWakeLockInternal: lock=127480608 [NetworkStats], flags=0x0, total_time=18ms, ws/pid/uid=null/1155/1000, packageName=android
12,275: 04-22 15:49:19.810 1155 1405 D fadiPowerImpl: wakeup alarm = Alarm{f6f53ed type 2 when 3938951 android}; listener package = *job.delay*
12,276: 04-22 15:49:19.813 1155 1405 D fadiPowerImpl: wakeup alarm = Alarm{6fc14b3 type 2 when 3998951 android}; listener package = *job.deadline*
MTK
adb shell dumpsys alarm log on
AlarmManagerService.set
12,234: 04-22 15:43:19.038 1593 1593 D DPMJ : |SERVICE| DPM received action android.intent.action.SCREEN_OFF
13,006: 04-22 15:53:19.406 1593 1593 D DPMJ : |SERVICE| DPM received action android.intent.action.SCREEN_ON
/**
50 * This class sets an alarm for the next expiring job, and determines whether a job's minimum
51 * delay has been satisfied.
52 */
53 public final class TimeController extends StateController {
/** Deadline alarm tag for logging purposes */
59 private final String DEADLINE_TAG = "*job.deadline*";
60 /** Delay alarm tag for logging purposes */
61 private final String DELAY_TAG = "*job.delay*";
312 /**
313 * Set an alarm with the {@link android.app.AlarmManager} for the next time at which a job's
314 * delay will expire.
315 * This alarm <b>will</b> wake up the phone.
316 */
317 private void setDelayExpiredAlarmLocked(long alarmTimeElapsedMillis, WorkSource ws) {
318 alarmTimeElapsedMillis = maybeAdjustAlarmTime(alarmTimeElapsedMillis);
319 mNextDelayExpiredElapsedMillis = alarmTimeElapsedMillis;
320 updateAlarmWithListenerLocked(DELAY_TAG, mNextDelayExpiredListener,
321 mNextDelayExpiredElapsedMillis, ws);
322 }
private void updateAlarmWithListenerLocked(String tag, OnAlarmListener listener,
345 long alarmTimeElapsed, WorkSource ws) {
346 ensureAlarmServiceLocked();
347 if (alarmTimeElapsed == Long.MAX_VALUE) {
348 mAlarmService.cancel(listener);
349 } else {
350 if (DEBUG) {
351 Slog.d(TAG, "Setting " + tag + " for: " + alarmTimeElapsed);
352 }
353 mAlarmService.set(AlarmManager.ELAPSED_REALTIME_WAKEUP, alarmTimeElapsed,
354 AlarmManager.WINDOW_HEURISTIC, 0, tag, listener, null, ws);
355 }
356 }
357
17 public void printAlarmWakeLog(int type, String alarm, PendingIntent operation, String listenerTag) {
118 if (type == AlarmManager.RTC_WAKEUP || type == AlarmManager.ELAPSED_REALTIME_WAKEUP) {
119 if (operation == null) {
120 Slog.d(TAG, "wakeup alarm = " + alarm
121 + "; listener package = " + listenerTag);
122 } else {
123 Slog.d(TAG, "wakeup alarm = " + alarm
124 + "; package = " + operation.getTargetPackage());
125 }
126 }
127 }
static final boolean DEBUG_BATCH = localLOGV || false;
1488 void setImpl(int type, long triggerAtTime, long windowLength, long interval,
1489 PendingIntent operation, IAlarmListener directReceiver, String listenerTag,
1490 int flags, WorkSource workSource, AlarmManager.AlarmClockInfo alarmClock,
1491 int callingUid, String callingPackage) {
1552 synchronized (mLock) {
1553 if (DEBUG_BATCH) {
1554 Slog.v(TAG, "set(" + operation + ") : type=" + type
1555 + " triggerAtTime=" + triggerAtTime + " win=" + windowLength
1556 + " tElapsed=" + triggerElapsed + " maxElapsed=" + maxElapsed
1557 + " interval=" + interval + " flags=0x" + Integer.toHexString(flags));
1558 }
1559 setImplLocked(type, triggerAtTime, triggerElapsed, windowLength, maxElapsed,
1560 interval, operation, directReceiver, listenerTag, flags, true, workSource,
1561 alarmClock, callingUid, callingPackage);
1562 }
4月30号晚上复测
一天总时间 | 起始时间 | 测试时长(s) | 结束时间 | 平均电流(mA) | 总电量消耗(uAh) | |||||||
86400 | 20:45:17 | 908 | 21:00:25 | 48.52 | 12345 | |||||||
波形偏移-Begin | 波形开始 | 波形偏移-End | 波形结束 | 波形持续时长 | 平均电流(mA) | 电量消耗(uAh) | 电量占比 | Kernel层唤醒源 | 联网次数统计 | 应用层唤醒源 | ||
26 | 20:45:43 | 287 | 20:50:04 | 261 | 0 | 500 | 4.05% | |||||
0 | 20:45:17 | 155 | 20:47:52 | 0 | 0 | 100 | 0.81% | |||||
0 | 20:45:17 | 224 | 20:49:01 | 0 | 0 | 0 | ||||||
0 | 20:45:17 | 272 | 20:49:49 | 0 | 0 | 0 | ||||||
0 | 20:45:17 | 328 | 20:50:45 | 0 | 0 | 0 | ||||||
0 | 20:45:17 | 388 | 20:51:45 | 0 | 0 | 0 | ||||||
0 | 20:45:17 | 568 | 20:54:45 | 0 | 0 | 0 | ||||||
4月30号晚上复测 | 平均电流 | 基电流 | PowerMonitor时长 | 其他功耗源 | ||||||||
1_O | 6.93 | 6.74 | 9.92分钟 | 20:37:38 电池广播刷新 | ||||||||
1_P | 7.15 | 6.88 | 5.09分钟 | 19:35:43 SmartManager查杀动作0.37秒,56mA,5.68uAh | ||||||||
2_O | 7.13 | 6.61 | 9.91分钟 | |||||||||
2_P | 7.03 | 6.79 | 9.92分钟 | |||||||||
3_O | 6.93 | |||||||||||
3_P | 6.8 | |||||||||||
5号下午测试 | 平均电流 | |||||||||||
1_O | 6.79 | |||||||||||
1_P | 7.26 | |||||||||||
2_O | 6.78 | |||||||||||
2_P | 6.85 | |||||||||||
3_O | 6.75 | |||||||||||
3_P | 6.81 |
5月10号复测(不开数据只开蓝牙)
一天总时间 | 起始时间 | 测试时长(s) | 结束时间 | 平均电流(mA) | 总电量消耗(uAh) | |||||||
86400 | 14:53:03 | 740 | 15:05:23 | 9.28 | 1908 | |||||||
波形偏移-Begin | 波形开始 | 波形偏移-End | 波形结束 | 波形持续时长 | 平均电流(mA) | 电量消耗(uAh) | 电量占比 | Kernel层唤醒源 | 联网次数统计 | 应用层唤醒源 | ||
137 | 14:55:20 | 149 | 14:55:32 | 12 | 137 | 453 | 23.74% | |||||
0 | 14:53:03 | 155 | 14:55:38 | 0 | 0 | 100 | 5.24% | |||||
0 | 14:53:03 | 224 | 14:56:47 | 0 | 0 | 0 | ||||||
0 | 14:53:03 | 272 | 14:57:35 | 0 | 0 | 0 | ||||||
0 | 14:53:03 | 328 | 14:58:31 | 0 | 0 | 0 | ||||||
0 | 14:53:03 | 388 | 14:59:31 | 0 | 0 | 0 | ||||||
0 | 14:53:03 | 568 | 15:02:31 | 0 | 0 | 0 |
一天总时间 起始时间 测试时长(s) 结束时间 平均电流(mA) 总电量消耗(uAh)
86400 14:53:03 740 15:05:23 9.28 1908
波形偏移-Begin 波形开始 波形偏移-End 波形结束 波形持续时长 平均电流(mA) 电量消耗(uAh) 电量占比
137 14:55:20 149 14:55:32 12 137 453 23.74%
PowerMonitor唤醒时刻 14:55:20
由于日志和波形存在时间偏差,故这里唤醒准确时刻是:14:55:26
上层的日志活动
------------------------------------------------------------------------
\\10.92.32.12\RDhzKM\VAL-SW-Share\yanhua.hu\2019-4-30\7638758\5月10号复测(不开数据只开蓝牙)
1.功耗现象:
PowerMonitor 开始第137秒位置即14:55:20(Kenel唤醒时刻14:55:26),出现持续12s,占总电流消耗23.74%的台阶大电流,该时间段平均电流137mA
2.原因分析
com.fadi.logger 日志有 com.fadi.logger.action.upload.check 的行为发生
3.具体日志
3.0 Kenel唤醒时刻
Kenel <6>[ 158.863114] PM: suspend exit 2019-05-10 06:55:26.909040373 UTC
3.1 com.fadi.logger 发上传广播事件
05-10 14:55:26.891 1126 1365 W ActivityManager: Sending non-protected broadcast com.fadi.logger.action.upload.check from system uid 1000 pkg com.fadi.logger
3.2 唤醒日志
05-10 14:55:26.885 1126 1365 D PowerManagerService: acquireWakeLockInternal: lock=29139277, flags=0x40000001, tag="*alarm*", ws=WorkSource{1000}, uid=1000, pid=1126, packageName=android
05-10 14:55:36.404 1126 1126 D PowerManagerService: releaseWakeLockInternal: lock=29139277 [*alarm*], flags=0x0, total_time=9519ms, ws/pid/uid=WorkSource{1000}/1126/1000, packageName=android
4.方案
4.1 需要分析 com.fadi.logger 为什么要发上传相关广播?
4.2 为什么没有直接拦截了 Background execution not allowed
异常日志
10,528: 05-10 14:55:26.891 1126 1365 W ActivityManager: Sending non-protected broadcast com.fadi.logger.action.upload.check from system uid 1000 pkg com.fadi.logger
// 隔了10秒才拦截
10,633: 05-10 14:55:36.400 1126 1142 W BroadcastQueue: Background execution not allowed: receiving Intent { act=com.fadi.logger.action.upload.check flg=0x80000014 (has extras) } to com.fadi.logger/.receiver.StartupIntentReceiver
05-10 14:55:26.885 1126 1365 D PowerManagerService: acquireWakeLockInternal: lock=29139277, flags=0x40000001, tag="*alarm*", ws=WorkSource{1000}, uid=1000, pid=1126, packageName=android
// 其中对应持锁 9519 ms,异常发生
05-10 14:55:32.006 2585 3792 D Feedback_smcd: In shell_cmd_execute line 73, system.command:bugreport | gzip > /sdcard/BugReport/BugReport/Vv2K1J-0_20190510_145212_+0800_bugreport_bugreport.gz,Result:0
05-10 14:55:32.006 2585 3792 D Feedback_smcd: In ctrl_data_write line 75, write response "baCommand success" to socket
05-10 14:55:32.006 2585 3792 E Feedback_smcd: In ctrl_data_write line 78,control data socket read failed, errno=9, Bad file descriptor
05-10 14:55:32.006 2585 3792 E Feedback_smcd: In shell_cmd_execute line 87, control data socket write failed
05-10 14:55:36.404 1126 1126 D PowerManagerService: releaseWakeLockInternal: lock=29139277 [*alarm*], flags=0x0, total_time=9519ms, ws/pid/uid=WorkSource{1000}/1126/1000, packageName=android
正常日志
10,659: 05-10 15:04:40.394 1126 1365 W ActivityManager: Sending non-protected broadcast com.fadi.logger.action.upload.check from system uid 1000 pkg com.fadi.logger
// 实时拦截
10,672: 05-10 15:04:40.394 1126 1177 W BroadcastQueue: Background execution not allowed: receiving Intent { act=com.fadi.logger.action.upload.check flg=0x80000014 (has extras) } to com.fadi.logger/.receiver.StartupIntentReceiver
// 其中对应持锁 24 ms
05-10 15:04:40.391 1126 1365 D PowerManagerService: acquireWakeLockInternal: lock=29139277, flags=0x40000001, tag="*alarm*", ws=WorkSource{1000}, uid=1000, pid=1126, packageName=android
05-10 15:04:40.415 1126 1126 D PowerManagerService: releaseWakeLockInternal: lock=29139277 [*alarm*], flags=0x0, total_time=24ms, ws/pid/uid=WorkSource{1000}/1126/1000, packageName=android
异常原因,系统发生GC内存回收,导致"com.fadi.logger.action.upload.check" 广播过了10秒才被拦截
10,528: 05-10 14:55:26.891 1126 1365 W ActivityManager: Sending non-protected broadcast com.fadi.logger.action.upload.check from system uid 1000 pkg com.fadi.logger
05-10 14:55:27.036 3048 3061 I android.browse: Explicit concurrent copying GC freed 4585(205KB) AllocSpace objects, 3(60KB) LOS objects, 84% free, 1150KB/7MB, paused 96us total 14.793ms
05-10 14:55:27.212 3013 3026 I fadi.setupwizar: Explicit concurrent copying GC freed 4237(189KB) AllocSpace objects, 3(60KB) LOS objects, 85% free, 1026KB/7MB, paused 94us total 12.960ms
05-10 14:55:27.386 2948 2961 I om.fadi.contact: Explicit concurrent copying GC freed 4249(189KB) AllocSpace objects, 3(60KB) LOS objects, 84% free, 1133KB/7MB, paused 94us total 14.457ms
05-10 14:55:27.558 2899 2912 I omm.simcontact: Explicit concurrent copying GC freed 4215(189KB) AllocSpace objects, 3(60KB) LOS objects, 85% free, 1023KB/6MB, paused 99us total 12.062ms
....
10,633: 05-10 14:55:36.400 1126 1142 W BroadcastQueue: Background execution not allowed: receiving Intent { act=com.fadi.logger.action.upload.check flg=0x80000014 (has extras) } to com.fadi.logger/.receiver.StartupIntentReceiver
5月10号复测(开数据开蓝牙)8.93
一天总时间 | 起始时间 | 测试时长(s) | 结束时间 | 平均电流(mA) | 总电量消耗(uAh) | |||||||
86400 | 15:14:07 | 762 | 15:26:49 | 8.93 | 1892 | |||||||
波形偏移-Begin | 波形开始 | 波形偏移-End | 波形结束 | 波形持续时长 | 平均电流(mA) | 电量消耗(uAh) | 电量占比 | Kernel层唤醒源 | 联网次数统计 | 应用层唤醒源 | ||
68 | 15:15:15 | 77 | 15:15:24 | 9 | 121mA | 349 | 18.45% | |||||
0 | 15:14:07 | 155 | 15:16:42 | 0 | 0 | 100 | 5.29% | |||||
0 | 15:14:07 | 224 | 15:17:51 | 0 | 0 | 0 | ||||||
0 | 15:14:07 | 272 | 15:18:39 | 0 | 0 | 0 | ||||||
0 | 15:14:07 | 328 | 15:19:35 | 0 | 0 | 0 | ||||||
0 | 15:14:07 | 388 | 15:20:35 | 0 | 0 | 0 | ||||||
0 | 15:14:07 | 568 | 15:23:35 | 0 | 0 | 0 |
PowerMonitor时间
一天总时间 起始时间 测试时长(s) 结束时间 平均电流(mA) 总电量消耗(uAh)
86400 15:14:07 762 15:26:49 8.93 1892
波形偏移-Begin 波形开始 波形偏移-End 波形结束 波形持续时长 平均电流(mA) 电量消耗(uAh) 电量占比
67 15:15:14 77 15:15:24 10 121mA 349 18.45%
==================================================================================
\\10.92.32.12\RDhzKM\VAL-SW-Share\yanhua.hu\2019-4-30\7638758\5月10号复测(开数据开蓝牙)
1.功耗现象:
PowerMonitor 开始第68秒位置即15:15:15,出现持续10s,占总电流消耗18.45%的台阶大电流,该时间段平均电流121mA
2. 原因分析
根据NetLog 存在 connectivitycheck.gstatic.com 推送消息给手机导致手机唤醒
3. 具体日志
3.1 网络消息推送
NetworkMonitor/NetworkAgentInfo [MOBILE (LTE) - 101]: PROBE_DNS connectivitycheck.gstatic.com 141ms OK 203.208.40.79
107 2019-05-10 15:15:15 203.208.40.79(connectivitycheck.gstatic.com) 10.10.1.91(手机ip地址) TCP 68 [TCP Retransmission] http(80) → 48946 [FIN, ACK] Seq=1 Ack=1 Win=261 Len=0 TSval=1357774000 TSecr=13592
108 2019-05-10 15:15:15 10.10.1.91(手机ip地址) 203.208.40.79(connectivitycheck.gstatic.com) TCP 80 [TCP Dup ACK 104#1] 48946 → http(80) [ACK] Seq=1 Ack=2 Win=172 Len=0 TSval=19133 TSecr=1357774000 SLE=1 SRE=2
3.2 唤醒日志
05-10 15:15:15.398 1126 1365 D PowerManagerService: acquireWakeLockInternal: lock=29139277, flags=0x1, tag="*alarm*", ws=WorkSource{1000}, uid=1000, pid=1126, packageName=android
05-10 15:15:24.938 1126 1126 D PowerManagerService: releaseWakeLockInternal: lock=29139277 [*alarm*], flags=0x0, total_time=9539ms, ws/pid/uid=WorkSource{1000}/1126/1000, packageName=android
4. 方案
需要分析 connectivitycheck.gstatic.com 推送给手机原因