Bug #116540

测试 Test-ST #113421: V4.0功能与专项测试

测试 Test-ST #113422: V4.0专项--AF专项--monkey测试

【AF】【EVT3】【Monkey】Monkey测试12小时，出现ANR: com.android.settings & com.hht.lebocast

Added by CD Test赵飞 over 2 years ago. Updated about 2 years ago.

Status:CLOSEDStart date:2023-02-24
Priority:NormalDue date:2023-03-15
Assignee:CD TEST-方永红% Done:

100%

Category:CD-FW
Target version:VC1_FSE_0090_20230411
Need_Info:-- Found Version:FlatBuild_HH_VX1_MCE_FSE.M.R.user.01.00.0077.X101
Resolution:FIXED Degrated:No
Severity:Critical Verified Version:FlatBuild_HH_MCE_FSE.M.R.user.01.00.0100.C103(X103)
Reproducibility:Frequently Fixed Version:2023-04-25
Test Type:Monkey Test Root cause:已修复Monkey产生的Application does not have a focused window类型ANR

Description

【执行命令】

adb shell
monkey --pkg-blacklist-file /sdcard/blacklist.txt --ignore-crashes --ignore-timeouts --ignore-security-exceptions --monitor-native-crashes --ignore-native-crashes -s 20 --throttle 500 --pct-touch 30 --pct-motion 15 --pct-nav 15 --pct-majornav 15 --pct-syskeys 5 --pct-appswitch 10 --pct-anyevent 10 --ignore-crashes -v -v -v 86400 2>/sdcard/error.txt 1>/sdcard/info.txt

【错误信息】

// NOT RESPONDING: com.android.settings (pid 2408)
ANR in com.android.settings (com.android.settings/.homepage.SettingsHomepageActivity)
PID: 2408
Reason: Input dispatching timed out (7a32726 com.android.settings/com.android.settings.homepage.SettingsHomepageActivity (server) is not responding. Waited 5000ms for KeyEvent)
Parent: com.android.settings/.homepage.SettingsHomepageActivity
Frozen: false
Load: 1.69 / 1.58 / 1.48
----- Output from /proc/pressure/memory -----
some avg10=0.00 avg60=0.00 avg300=0.00 total=0
full avg10=0.00 avg60=0.00 avg300=0.00 total=0
----- End output from /proc/pressure/memory -----

CPU usage from 212357ms to 0ms ago (2023-02-23 20:59:36.843 to 2023-02-23 21:03:09.200):
  17% 835/vendor.qti.hardware.display.composer-service: 10% user + 6.4% kernel / faults: 612 minor
  12% 1942/com.android.systemui: 11% user + 1.7% kernel / faults: 69412 minor
  11% 987/surfaceflinger: 7.9% user + 3.7% kernel / faults: 1765 minor
  10% 1532/system_server: 7.1% user + 3.4% kernel / faults: 414614 minor
  7.3% 2408/com.android.settings: 5.7% user + 1.6% kernel / faults: 76871 minor
  3% 3541/com.android.music: 2.3% user + 0.6% kernel / faults: 10640 minor
  2.1% 2582/com.android.launcher3: 1.4% user + 0.6% kernel / faults: 10987 minor
  2.1% 4289/com.android.documentsui: 1.7% user + 0.4% kernel / faults: 14482 minor
  1.2% 750/crtc_commit:125: 0% user + 1.2% kernel
...

// NOT RESPONDING: com.hht.lebocast (pid 2755)
ANR in com.hht.lebocast (com.hht.lebocast/.GuidanceActivity)
PID: 2755
Reason: Input dispatching timed out (Application does not have a focused window)
Parent: com.hht.lebocast/.GuidanceActivity
Frozen: false
Load: 0.0 / 0.0 / 0.0
----- Output from /proc/pressure/memory -----
some avg10=0.00 avg60=0.00 avg300=0.00 total=0
full avg10=0.00 avg60=0.00 avg300=0.00 total=0
----- End output from /proc/pressure/memory -----

CPU usage from 8081ms to 0ms ago (2023-02-24 00:47:03.827 to 2023-02-24 00:47:11.907):
  3.5% 1175/cnss_diag: 3% user + 0.4% kernel
  3.5% 1532/system_server: 2.2% user + 1.3% kernel / faults: 1713 minor
  2.8% 2755/com.hht.lebocast: 1.1% user + 1.7% kernel / faults: 48 minor
  1.6% 8220/kworker/u16:23-memlat_wq: 0% user + 1.6% kernel
  1.6% 12424/kworker/u16:10-kgsl-mementry: 0% user + 1.6% kernel
  0.8% 9365/kworker/u16:25-rq_stats: 0% user + 0.8% kernel
  0.6% 829/android.hardware.wifi@1.0-service: 0.4% user + 0.1% kernel / faults: 44 minor
  0.4% 503/logd: 0.3% user + 0.1% kernel / faults: 15 minor
  0.3% 9/ksoftirqd/0: 0% user + 0.3% kernel
  0.3% 645/vendor.ts.uart@1.0-service: 0.1% user + 0.2% kernel
  0.2% 12500/kworker/0:2-mm_percpu_wq: 0% user + 0.2% kernel
  0.2% 1166/tlog: 0.1% user + 0.1% kernel
...

【日志】
ftp://cdiot@192.168.87.46/Pre_figure/Test_Log/Bug_116540/Tlog.zip

anr_test.mp4 (11.1 MB) CD FW王武军, 2023-03-02 15:16

Related issues

Related to Figure - Bug #115842: 【AF】【EVT2】【Monkey】Monkey测试6小时，出现ANR: com.android.gallery3... CLOSED 2023-02-03 2023-03-15
Related to Figure - Bug #115843: 【AF】【EVT2】【Monkey】Monkey测试6小时，出现ANR：com.android.deskclock（2） CLOSED 2023-02-03 2023-02-28
Related to Figure - Bug #115844: 【AF】【EVT2】【Monkey】Monkey测试6小时，出现ANR：com.android.launcher3（1） CLOSED 2023-02-03 2023-03-15
Related to Figure - Bug #116442: 【AF】【EVT3】【Monkey】Monkey测试12小时，出现ANR: com.android.music（3） CLOSED 2023-02-22 2023-03-15

History

#1 Updated by CD Test赵飞 over 2 years ago

  • Description updated (diff)

#2 Updated by CD FW王武军 over 2 years ago

【】当前状态

确认问题，本地复现现象
下面的这几个票都是同样的ANR错误，可以归结在一起处理：
Bug #115842: 【AF】【EVT2】【Monkey】Monkey测试6小时，出现ANR: com.android.gallery3
Bug #115843: 【AF】【EVT2】【Monkey】Monkey测试6小时，出现ANR：com.android.deskclock
Bug #115844: 【AF】【EVT2】【Monkey】Monkey测试6小时，出现ANR：com.android.launcher3
Bug #116442: 【AF】【EVT3】【Monkey】Monkey测试12小时，出现ANR: com.android.music

【】当前分析
1、
该ANR发生的原因都是：Reason: Input dispatching timed out (Application does not have a focused window)
直接来说就是，在启动或者切换应用时，当前有输入事件发生，对于InputDispatcher来说，分发事件时，存在焦点进程，但是在
焦点进程上并未获取到焦点窗口，进而导致事件无法在当前的通道进行分发，超时出现ANR，另外出现ANR的应用是随机的，
从界面的现象来看就是，应用并未被立刻启动，屏幕可能存在黑屏的情况。

2、
日志的反馈就是，类似如下日志：
02-18 23:03:34.227 1514 1717 E InputDispatcher: Dropping KEY event because there is no focused window
02-18 23:03:34.229 1514 2122 W InputManager: Input event injection from pid 24203 failed.
02-18 23:03:34.229 1514 1717 I WindowManager: ANR in ActivityRecord{9a51e22 u0 com.sohu.inputmethod.sogou.car/.settingsui.SogouSettingsActivity t1401}. Reason: Application does not have a focused window
02-18 23:03:34.229 24203 24203 I Monkey : // Injection Failed
02-18 23:03:34.230 24203 24203 I Monkey : :Sending Key (ACTION_UP): 159 // KEYCODE_NUMPAD_COMMA
02-18 23:03:34.353 1514 1717 W InputDispatcher: Waiting because no window has focus but ActivityRecord{9a51e22 u0 com.sohu.inputmethod.sogou.car/.settingsui.SogouSettingsActivity t1401} may eventually add a window when it finishes starting up. Will wait for 5000ms

3、从逻辑层面的分析
1）
InputDispatcher在分发事件时会检查当前的焦点窗口和焦点进程，如果不匹配那么就会报错，检索的逻辑在
InputDispatcher::findFocusedWindowTargetsLocked中完成。
2）
而焦点窗口数据的来源是通过FocusResolver::getFocusedWindowToken的方法获取，数据是通过map类型的数据结构mFocusedWindowTokenByDisplay
进行存储，map中的值的更新又是通过surfaceflinger触发；
3）
SurfaceFlinger::updateInputFlinger()方法会完成焦点窗口的更新和清理，进而通过InputFlinger->setFocusedWindow更新焦点窗口的数据

从目前的分析情况来看：
如果出现ANR，那么就不会通过InputFlinger->setFocusedWindow更新焦点窗口；
如果不出现ANR，那么InputFlinger->setFocusedWindow会正常更新焦点窗口

【】计划策略

1、既然surfaceflinger触发input焦点窗口数据的更新，
那么就需要寻找为什么在发生ANR时，焦点窗口为什么没有通过surfaceflinger进行更新

#3 Updated by CD APP-王营 over 2 years ago

  • Due date set to 2023-03-15
  • Status changed from New to ASSIGNED
  • Assignee changed from CD APP-王营 to CD FW王武军

#4 Updated by CDTS-TEST 周婷 over 2 years ago

  • Target version set to VX1_MCE_FSE_0082_20230314

#5 Updated by CD FW王武军 over 2 years ago

【】当前状态
1、分析方向
发生ANR的原因是：Application does not have a focused window
正如前面的分析，我从分发input事件时，为什么没有焦点窗口的方向展开。
2、分析小结
1）逻辑点：
在Input分发事件时，会查询当前的焦点窗口，而焦点窗口的数据更新又是通过SurfaceFlinger中的updateInputFlinger方法完成，
updateInputFlinger的执行时机又是SurfaceFlinger通过处理消息来完成SurfaceFlinger::onMessageInvalidate；
具体的窗口数据mInputWindowCommands.focusRequests是通过addClientLayer触发setTransactionState完成，
这里的焦点窗口数据更新的触发同时与UpdateInputWindows触发的updateInputWindows方法有关系。
2）发生ANR时的情况：
DisplayContent.updateFocusedWindowLocked中mCurrentFocus是空的，同时SurfaceFlinger的
mInputWindowCommands.focusRequests不是对应的当前应用所对应的窗口数据，未进行更新。
在经过一段时间后，应用对应的窗口从黑屏中显示出来，也触发了SurfaceFlinger::addClientLayer处理真正的窗口，
此时DisplayContent.updateFocusedWindowLocked中mCurrentFocus是当前window的值，SurfaceFlinger::mInputWindowCommands.focusRequests
也更新为了当前window的值，焦点窗口正常。
从整个流程来看，触发ANR时，被启动的应用会存在黑屏情况。过一段时间界面被完整加载出来。
3）当前难点
已知的：发生ANR时，应用的启动时间明显很长，特别是在构建window对应的Surface时会花费10s以上的时间，
正是因为这个时间引发了ANR的发生。但是目前不能定位为什么触发这次Surface构建会花费这么长的时间，这个时间是
消耗在那个部分？从发生ANR的dump信息来看，系统的整体状态是正常的，没有发现那个进程过度消耗系统性能的地方。

3、思考
从逻辑原理层面，因为启动应用时间过久，窗口界面未绘制出来，这个时候在窗口上输入intput事件，
InputDispatcher分发事件时它必然找不到焦点窗口，没有窗口事件也不知道分发给谁，等待或者超时也就成了必然。
我想如果要找到这个问题的根本原因，可能需要找到为什么应用启动会花费很长的时间，时间是花费在什么地方，是不是系统层面的消耗？是否可以优化？

(tips:出现ANR的应用，在非monkey环境下，正常启动是没有问题的。)
(anr_test.mp4 是发生ANR时，应用的表现情况)

#6 Updated by CD FW王武军 over 2 years ago

#7 Updated by CD TPM-王祥林 over 2 years ago

  • Target version changed from VX1_MCE_FSE_0082_20230314 to VC1_FSE_0082_20230314

#8 Updated by CD FW王武军 over 2 years ago

【】当前状态
从定位应用启动过程耗时的方向，添加了辅助相关的日志：
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/187456
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/native/+/187455

从日志结合逻辑层面来看，出现问题时是应用创建相关靠后的surface时耗了很长时间，而这个逻辑的调起是
在流程中被动调起，可能受到了系统cpu调度的影响，因为在追查时发现出现anr时，系统这个时候有大量关于
audio相关的日志，有日志输出那么必然有相关的逻辑在执行这部分逻辑是否会影响系统的整体性能，从而影响了
系统cup调度执行应用启动的策略，这个是个疑问。从日志信息来看是有问题，截取部分日志如下：

02-17 04:01:44.261 1024 1711 W AudioFlinger: write blocked for 10503 msecs, 3 delayed writes, thread 13
02-17 04:01:44.263 809 1707 D audio_hw_primary: out_set_parameters: enter: usecase(1: low-latency-playback) kvpairs: suspend_playback=true
02-17 04:01:44.263 809 1707 D audio_hw_extn: audio_extn_fm_set_parameters: Enter

02-17 04:01:44.274 809 1707 D audio_hw_primary: out_set_parameters: enter: usecase(1: low-latency-playback) kvpairs: suspend_playback=false
02-17 04:01:44.274 809 1707 D audio_hw_extn: audio_extn_fm_set_parameters: Enter

02-17 04:01:44.980 2582 2582 D RemoteControlService: startVlanDispatchThread
02-17 04:01:45.020 1017 3109 E TaskPersister: File error accessing recents directory (directory doesn't exist?).
02-17 04:01:45.057 501 501 E SELinux : avc: denied { find } for pid=5014 uid=10057 name=media.extractor scontext=u:r:vendor_qsta_app:s0 tcontext=u:object_r:mediaextractor_service:s0 tclass=service_manager permissive=0
02-17 04:01:45.057 501 501 I auditd : avc: denied { find } for pid=5014 u

02-17 04:01:46.058 501 501 E SELinux : avc: denied { find } for pid=5014 uid=10057 name=media.extractor scontext=u:r:vendor_qsta_app:s0 tcontext=u:object_r:mediaextractor_service:s0 tclass=service_manager permissive=0
02-17 04:01:46.058 501 501 I auditd : avc: denied { find } for pid=5014 uid=10057 name=media.extractor scontext=u:r:vendor_qsta_app:s0 tcontext=u:object_r:mediaextractor_service:s0 tclass=service_manager permissive=0

02-17 04:01:46.181 502 502 I hwservicemanager: getTransport: Cannot find entry ::IMapper/default in either framework or device VINTF manifest.

02-17 04:01:46.234 4942 4978 W AudioTrack: set(): notificationFrames=-14 clamped to the range -1 to -8
02-17 04:01:46.238 809 1726 D audio_hw_primary: adev_get_parameters:vr_audio_mode_on
02-17 04:01:46.238 809 1726 I audio_hw_primary: getting vr mode to 0
02-17 04:01:46.238 809 1726 D audio_hw_primary: adev_get_parameters: exit: returns - vr_audio_mode_on=false
02-17 04:01:46.239 1024 4567 D AudioFlinger: Client defaulted notificationFrames to 144 for frameCount 1152
02-17 04:01:46.242 1024 4567 D AF::TrackHandle: OpPlayAudio: track:56 usage:1 not muted
02-17 04:01:46.244 4942 4978 I AudioTrack: createTrack_l(0): AUDIO_OUTPUT_FLAG_FAST successful; frameCount 0 -> 1152
02-17 04:01:46.249 1017 2779 I MicroServiceManager: requestResult(requestAudioFocus) parameters is{"functionInfo":{"IDCM_AudioFocus":"AudioFocus_Media"}}.
02-17 04:01:46.249 2342 2414 E MicroService: Client is not connected.
02-17 04:01:46.249 2342 2414 E MicroService: Client is not connected.
02-17 04:01:46.253 809 1707 I EffectsFactory: EffectCreate() create_effect

02-17 04:01:46.266 809 5063 D audio_hw_primary: start_output_stream: enter: stream(0xea3821a0)usecase(12: audio-ull-playback) devices(0x2) is_haptic_usecase(0)
02-17 04:01:46.267 809 5063 D audio_hw_primary: select_devices for use case (audio-ull-playback)
02-17 04:01:46.267 809 5063 D audio_hw_primary: select_devices: changing use case audio-ull-playback output device from(0: , acdb -1) to (2: speaker, acdb 15)
02-17 04:01:46.267 809 5063 I msm8974_platform: platform_check_and_set_codec_backend_cfg:becf: afe: bitwidth 16, samplerate 48000 channels 2, backend_idx 0 usecase = 12 device (speaker)
02-17 04:01:46.267 809 5063 D msm8974_platform: platform_split_snd_device: snd_device(2) num devices(1) new_snd_devices(0)
02-17 04:01:46.267 809 5063 I msm8974_platform: platform_check_and_set_codec_backend_cfg: new_snd_devices0 is 2
02-17 04:01:46.267 809 5063 I msm8974_platform: platform_check_codec_backend_cfg:becf: afe: bitwidth 16, samplerate 48000 channels 2, backend_idx 0 usecase = 12 device (speaker)
02-17 04:01:46.267 809 5063 D msm8974_platform: platform_check_codec_backend_cfg:napb: (0) - (low-latency-playback)id (1) sr 48000 bw (16) ch (2) device speaker
02-17 04:01:46.269 809 5063 D audio_hw_extn: audio_extn_enable_hifi_filter: mixer_value set 0
02-17 04:01:46.269 809 5063 D msm8974_platform: platform_check_codec_backend_cfg:becf: updated afe: bitwidth 16, samplerate 48000 channels 2,backend_idx 0 usecase = 12 device (speaker)
02-17 04:01:46.269 809 5063 D msm8974_platform: platform_check_codec_backend_cfg:becf: afe: playback on codec device not supporting native playback set default Sample Rate(48k)
02-17 04:01:46.269 809 5063 I msm8974_platform: platform_check_codec_backend_cfg:becf: afe: Codec selected backend: 0 updated bit width: 16 and sample rate: 48000
02-17 04:01:46.269 809 5063 D audio_hw_primary: check_usecases_codec_backend:becf: force routing 0
02-17 04:01:46.269 809 5063 D audio_hw_primary: check_usecases_codec_backend:becf: (78) check_usecases curr device: speaker, usecase device:speaker backends match 1
02-17 04:01:46.269 809 5063 E msm8974_platform: platform_check_backends_match: Invalid snd_device =
02-17 04:01:46.269 809 5063 D audio_hw_primary: check_usecases_codec_backend:becf: (78) check_usecases curr device: speaker, usecase device: backends match 0
02-17 04:01:46.269 809 5063 D audio_hw_primary: check_usecases_codec_backend:becf: check_usecases num.of Usecases to switch 0
01-04 01:26:43.183 0 0 E : [MAX975X:max96755x_init] ERROR begin
02-17 04:01:46.270 809 5063 D hardware_info: hw_info_append_hw_type : device_name = speaker
02-17 04:01:46.270 809 5063 D msm8974_platform: platform_split_snd_device: snd_device(2) num devices(0) new_snd_devices(0)
02-17 04:01:46.270 809 5063 I audio_hw_utils: audio_extn_utils_update_stream_output_app_type_cfg Allowing 24 and above bits playback on speaker ONLY at default sampling rate
02-17 04:01:46.270 809 5063 E soundtrigger: audio_extn_sound_trigger_update_stream_status: invalid input device 0x0, for event 3
02-17 04:01:46.270 809 5063 D soundtrigger: audio_extn_sound_trigger_update_stream_status: uc_info->id 12 of type 0 for Event 3, with Raise=0
02-17 04:01:46.271 809 5063 D audio_hw_utils: audio_extn_utils_send_app_type_cfg: usecase->out_snd_device speaker
02-17 04:01:46.271 809 5063 D msm8974_platform: platform_split_snd_device: snd_device(2) num devices(0) new_snd_devices(0)
02-17 04:01:46.271 809 5063 I audio_hw_utils: ULL doesnt need sending app type cfg, returning
02-17 04:01:46.271 809 5063 D msm8974_platform: platform_split_snd_device: snd_device(2) num devices(1) new_snd_devices(0)
02-17 04:01:46.271 809 5063 D audio_hw_utils: audio_extn_btsco_get_sample_rate:Not a BT SCO device, need not update sampling rate

02-17 04:01:46.275 809 5063 D msm8974_platform: platform_split_snd_device: snd_device(2) num devices(0) new_snd_devices(0)
02-17 04:01:46.275 809 5063 I msm8974_platform: platform_get_custom_mtmx_params: no matching param with id 0 ip_ch 2 op_ch 2 uc_id 12 snd_dev 2
02-17 04:01:46.275 809 5063 D audio_hw_primary: enable_audio_route: apply mixer and update path: audio-ull-playback
02-17 04:01:46.276 809 5063 D audio_route: Apply path: audio-ull-playback
02-17 04:01:46.277 809 5063 D audio_hw_primary: select_devices: done
02-17 04:01:46.277 809 5063 D msm8974_platform: platform_set_channel_map mixer_ctl_name:Playback Channel Map13
02-17 04:01:46.278 809 5063 D msm8974_platform: platform_set_channel_map: set mapping(1 2 0 0 0 0 0 0) for channel:2
02-17 04:01:46.279 809 5063 E msm8974_platform: platform_set_channel_map: Could not set ctl, error:-22 ch_count:2
01-04 01:26:43.202 0 0 I : snd_pcm_hw_constraint_integer failed
01-04 01:26:43.202 0 0 I msm_pcm_open: P buffer bytes minmax constraint ret 1
02-17 04:01:46.298 809 5063 D audio_hw_primary: start_output_stream: exit
02-17 04:01:46.332 809 5063 W audio_hw_primary: out_write: underrun(1) frames_by_time(1637) > out->last_fifo_frames_remaining(672)
01-04 01:26:43.244 0 0 E i2c_geni 980000.i2c: i2c error :-107
02-17 04:01:46.336 809 5063 W audio_hw_primary: out_write: underrun(2) frames_by_time(1809) > out->last_fifo_frames_remaining(816)
01-04 01:26:43.248 0 0 E : [MAX975X:max96755g_read_byte] ERROR Failed to read dev:0x4c addr:0x0013
01-04 01:26:43.258 0 0 E i2c_geni 980000.i2c: i2c error :-107
02-17 04:01:46.338 809 5063 W audio_hw_primary: out_write: underrun(3) frames_by_time(1934) > out->last_fifo_frames_remaining(960)
02-17 04:01:46.342 809 5063 W audio_hw_primary: out_write: underrun(4) frames_by_time(2108) > out->last_fifo_frames_remaining(1104)
02-17 04:01:46.345 809 5063 W audio_hw_primary: out_write: underrun(5) frames_by_time(2231) > out->last_fifo_frames_remaining(1248)
02-17 04:01:46.348 809 5063 W audio_hw_primary: out_write: underrun(6) frames_by_time(2384) > out->last_fifo_frames_remaining(1392)
01-04 01:26:43.262 0 0 E : [MAX975X:max96755g_write_byte] ERROR Failed to write dev:0x4c addr:0x0010 value:0x00
02-17 04:01:46.351 809 5063 W audio_hw_primary: out_write: underrun(7) frames_by_time(2518) > out->last_fifo_frames_remaining(1536)
02-17 04:01:46.353 809 5063 W audio_hw_primary: out_write: underrun(8) frames_by_time(2657) > out->last_fifo_frames_remaining(1680)
02-17 04:01:46.356 809 5063 W audio_hw_primary: out_write: underrun(9) frames_by_time(2800) > out->last_fifo_frames_remaining(1824)
02-17 04:01:46.359 809 5063 W audio_hw_primary: out_write: underrun(10) frames_by_time(2935) > out->last_fifo_frames_remaining(1968)
02-17 04:01:46.362 809 5063 W audio_hw_primary: out_write: underrun(11) frames_by_time(3081) > out->last_fifo_frames_remaining(2112)
02-17 04:01:46.365 809 5063 W audio_hw_primary: out_write: underrun(12) frames_by_time(3222) > out->last_fifo_frames_remaining(2256)

01-04 01:26:43.273 0 0 E i2c_geni 980000.i2c: i2c error :-107
01-04 01:26:43.278 0 0 E : [MAX975X:max96755g_write_byte] ERROR Failed to write dev:0x4c addr:0x0001 value:0x01
01-04 01:26:43.288 0 0 E i2c_geni 980000.i2c: i2c error :-107
02-17 04:01:46.368 809 5063 W audio_hw_primary: out_write: underrun(13) frames_by_time(3374) > out->last_fifo_frames_remaining(2400)
02-17 04:01:46.371 809 5063 W audio_hw_primary: out_write: underrun(14) frames_by_time(3520) > out->last_fifo_frames_remaining(2544)
02-17 04:01:46.375 809 5063 W audio_hw_primary: out_write: underrun(15) frames_by_time(3669) > out->last_fifo_frames_remaining(2688)
02-17 04:01:46.377 809 5063 W audio_hw_primary: out_write: underrun(16) frames_by_time(3801) > out->last_fifo_frames_remaining(2832)
02-17 04:01:46.380 809 5063 W audio_hw_primary: out_write: underrun(17) frames_by_time(3948) > out->last_fifo_frames_remaining(2976)
01-04 01:26:43.293 0 0 E : [MAX975X:max96755g_write_byte] ERROR Failed to write dev:0x4c addr:0x01ce value:0x4f
02-17 04:01:46.384 809 5063 W audio_hw_primary: out_write: underrun(18) frames_by_time(4114) > out->last_fifo_frames_remaining(3120)
02-17 04:01:46.387 809 5063 W audio_hw_primary: out_write: underrun(19) frames_by_time(4247) > out->last_fifo_frames_remaining(3264)
02-17 04:01:46.390 809 5063 W audio_hw_primary: out_write: underrun(20) frames_by_time(4389) > out->last_fifo_frames_remaining(3408)
02-17 04:01:46.392 809 5063 W audio_hw_primary: out_write: underrun(21) frames_by_time(4525) > out->last_fifo_frames_remaining(3552)
02-17 04:01:46.395 809 5063 W audio_hw_primary: out_write: underrun(22) frames_by_time(4667) > out->last_fifo_frames_remaining(3696)
01-04 01:26:43.304 0 0 E i2c_geni 980000.i2c: i2c error :-107
01-04 01:26:43.308 0 0 E : [MAX975X:max96755g_write_byte] ERROR Failed to write dev:0x4c addr:0x0010 value:0x20
02-17 04:01:46.399 809 5063 W audio_hw_primary: out_write: underrun(23) frames_by_time(4825) > out->last_fifo_frames_remaining(3840)
02-17 04:01:46.402 809 5063 W audio_hw_primary: out_write: underrun(24) frames_by_time(4962) > out->last_fifo_frames_remaining(3984)
02-17 04:01:46.404 809 5063 W audio_hw_primary: out_write: underrun(25) frames_by_time(5106) > out->last_fifo_frames_remaining(4128)
02-17 04:01:46.407 809 5063 W audio_hw_primary: out_write: underrun(26) frames_by_time(5242) > out->last_fifo_frames_remaining(4272)
02-17 04:01:46.411 809 5063 W audio_hw_primary: out_write: underrun(27) frames_by_time(5394) > out->last_fifo_frames_remaining(4416)
02-17 04:01:46.413 809 5063 W audio_hw_primary: out_write: underrun(28) frames_by_time(5530) > out->last_fifo_frames_remaining(4560)
02-17 04:01:46.416 809 5063 W audio_hw_primary: out_write: underrun(29) frames_by_time(5681) > out->last_fifo_frames_remaining(4704)
02-17 04:01:46.420 809 5063 W audio_hw_primary: out_write: underrun(30) frames_by_time(5823) > out->last_fifo_frames_remaining(4848)
02-17 04:01:46.422 809 5063 W audio_hw_primary: out_write: underrun(31) frames_by_time(5962) > out->last_fifo_frames_remaining(4992)
02-17 04:01:46.425 809 5063 W audio_hw_primary: out_write: underrun(32) frames_by_time(6104) > out->last_fifo_frames_remaining(5136)
02-17 04:01:46.428 809 5063 W audio_hw_primary: out_write: underrun(33) frames_by_time(6254) > out->last_fifo_frames_remaining(5280)
02-17 04:01:46.431 809 5063 W audio_hw_primary: out_write: underrun(34) frames_by_time(6394) > out->last_fifo_frames_remaining(5424)
02-17 04:01:46.434 809 5063 W audio_hw_primary: out_write: underrun(35) frames_by_time(6539) > out->last_fifo_frames_remaining(5568)
02-17 04:01:46.437 809 5063 W audio_hw_primary: out_write: underrun(36) frames_by_time(6680) > out->last_fifo_frames_remaining(5712)
02-17 04:01:46.440 809 5063 W audio_hw_primary: out_write: underrun(37) frames_by_time(6823) > out->last_fifo_frames_remaining(5856)
02-17 04:01:46.443 809 5063 W audio_hw_primary: out_write: underrun(38) frames_by_time(6967) > out->last_fifo_frames_remaining(6000)
02-17 04:01:46.446 809 5063 W audio_hw_primary: out_write: underrun(39) frames_by_time(7110) > out->last_fifo_frames_remaining(6144)
02-17 04:01:46.449 809 5063 W audio_hw_primary: out_write: underrun(40) frames_by_time(7255) > out->last_fifo_frames_remaining(6288)
02-17 04:01:46.452 809 5063 W audio_hw_primary: out_write: underrun(41) frames_by_time(7398) > out->last_fifo_frames_remaining(6432)
02-17 04:01:46.455 809 5063 W audio_hw_primary: out_write: underrun(42) frames_by_time(7543) > out->last_fifo_frames_remaining(6576)
02-17 04:01:46.458 809 5063 W audio_hw_primary: out_write: underrun(43) frames_by_time(7697) > out->last_fifo_frames_remaining(6720)
02-17 04:01:46.461 809 5063 W audio_hw_primary: out_write: underrun(44) frames_by_time(7833) > out->last_fifo_frames_remaining(6864)
02-17 04:01:46.464 809 5063 W audio_hw_primary: out_write: underrun(45) frames_by_time(7979) > out->last_fifo_frames_remaining(7008)
02-17 04:01:46.467 809 5063 W audio_hw_primary: out_write: underrun(46) frames_by_time(8119) > out->last_fifo_frames_remaining(7152)
02-17 04:01:46.470 809 5063 W audio_hw_primary: out_write: underrun(47) frames_by_time(8268) > out->last_fifo_frames_remaining(7296)
02-17 04:01:46.473 809 5063 W audio_hw_primary: out_write: underrun(48) frames_by_time(8407) > out->last_fifo_frames_remaining(7440)
02-17 04:01:46.476 809 5063 W audio_hw_primary: out_write: underrun(49) frames_by_time(8552) > out->last_fifo_frames_remaining(7584)
02-17 04:01:46.479 809 5063 W audio_hw_primary: out_write: underrun(50) frames_by_time(8696) > out->last_fifo_frames_remaining(7728)
02-17 04:01:46.482 809 5063 W audio_hw_primary: out_write: underrun(51) frames_by_time(8842) > out->last_fifo_frames_remaining(7872)
02-17 04:01:46.485 809 5063 W audio_hw_primary: out_write: underrun(52) frames_by_time(8983) > out->last_fifo_frames_remaining(8016)
02-17 04:01:46.488 809 5063 W audio_hw_primary: out_write: underrun(53) frames_by_time(9127) > out->last_fifo_frames_remaining(8160)
02-17 04:01:46.491 809 5063 W audio_hw_primary: out_write: underrun(54) frames_by_time(9272) > out->last_fifo_frames_remaining(8304)
02-17 04:01:46.494 809 5063 W audio_hw_primary: out_write: underrun(55) frames_by_time(9415) > out->last_fifo_frames_remaining(8448)
02-17 04:01:46.497 809 5063 W audio_hw_primary: out_write: underrun(56) frames_by_time(9559) > out->last_fifo_frames_remaining(8592)
02-17 04:01:46.500 809 5063 W audio_hw_primary: out_write: underrun(57) frames_by_time(9703) > out->last_fifo_frames_remaining(8736)
02-17 04:01:46.503 809 5063 W audio_hw_primary: out_write: underrun(58) frames_by_time(9846) > out->last_fifo_frames_remaining(8880)
02-17 04:01:46.506 809 5063 W audio_hw_primary: out_write: underrun(59) frames_by_time(9998) > out->last_fifo_frames_remaining(9024)
02-17 04:01:46.509 809 5063 W audio_hw_primary: out_write: underrun(60) frames_by_time(10139) > out->last_fifo_frames_remaining(9168)
01-04 01:26:43.420 0 0 E i2c_geni 980000.i2c: i2c error :-107
01-04 01:26:43.425 0 0 E : [MAX975X:max96755g_read_byte] ERROR Failed to read dev:0x4c addr:0x0013
01-04 01:26:43.433 0 0 E : [MAX975X:max96755x_init] ERROR read:752 0x13:00
02-17 04:01:46.512 809 5063 W audio_hw_primary: out_write: underrun(61) frames_by_time(10285) > out->last_fifo_frames_remaining(9312)
02-17 04:01:46.515 809 5063 W audio_hw_primary: out_write: underrun(62) frames_by_time(10424) > out->last_fifo_frames_remaining(9456)
01-04 01:26:43.435 0 0 E DTC_ETH,link_delay_work_func: 3003, SQI=0, link=0
01-04 01:26:43.439 0 0 E : [MAX975X:max96755x_init] ERROR read:755 0x13:02
02-17 04:01:46.518 809 5063 W audio_hw_primary: out_write: underrun(63) frames_by_time(10572) > out->last_fifo_frames_remaining(9600)
02-17 04:01:46.521 809 5063 W audio_hw_primary: out_write: underrun(64) frames_by_time(10708) > out->last_fifo_frames_remaining(9744)
02-17 04:01:46.524 809 5063 W audio_hw_primary: out_write: underrun(65) frames_by_time(10862) > out->last_fifo_frames_remaining(9888)
02-17 04:01:46.528 809 5063 W audio_hw_primary: out_write: underrun(66) frames_by_time(11035) > out->last_fifo_frames_remaining(10032)
01-04 01:26:43.451 0 0 E : [MAX975X:max96755x_init] ERROR done
02-17 04:01:46.531 809 5063 W audio_hw_primary: out_write: underrun(67) frames_by_time(11165) > out->last_fifo_frames_remaining(10176)
02-17 04:01:46.534 809 5063 W audio_hw_primary: out_write: underrun(68) frames_by_time(11300) > out->last_fifo_frames_remaining(10320)
02-17 04:01:46.536 809 5063 W audio_hw_primary: out_write: underrun(69) frames_by_time(11442) > out->last_fifo_frames_remaining(10464)
02-17 04:01:46.539 809 5063 W audio_hw_primary: out_write: underrun(70) frames_by_time(11576) > out->last_fifo_frames_remaining(10608)
02-17 04:01:46.542 809 5063 W audio_hw_primary: out_write: underrun(71) frames_by_time(11720) > out->last_fifo_frames_remaining(10752)
02-17 04:01:46.545 809 5063 W audio_hw_primary: out_write: underrun(72) frames_by_time(11868) > out->last_fifo_frames_remaining(10896)
02-17 04:01:46.548 809 5063 W audio_hw_primary: out_write: underrun(73) frames_by_time(12011) > out->last_fifo_frames_remaining(11040)
02-17 04:01:46.551 809 5063 W audio_hw_primary: out_write: underrun(74) frames_by_time(12157) > out->last_fifo_frames_remaining(11184)
02-17 04:01:46.555 809 5063 W audio_hw_primary: out_write: underrun(75) frames_by_time(12311) > out->last_fifo_frames_remaining(11328)
02-17 04:01:46.557 809 5063 W audio_hw_primary: out_write: underrun(76) frames_by_time(12445) > out->last_fifo_frames_remaining(11472)
02-17 04:01:46.561 809 5063 W audio_hw_primary: out_write: underrun(77) frames_by_time(12597) > out->last_fifo_frames_remaining(11616)
02-17 04:01:46.563 809 5063 W audio_hw_primary: out_write: underrun(78) frames_by_time(12731) > out->last_fifo_frames_remaining(11760)
02-17 04:01:46.566 809 5063 W audio_hw_primary: out_write: underrun(79) frames_by_time(12880) > out->last_fifo_frames_remaining(11904)
02-17 04:01:46.570 809 5063 W audio_hw_primary: out_write: underrun(80) frames_by_time(13029) > out->last_fifo_frames_remaining(12048)
02-17 04:01:46.572 809 5063 W audio_hw_primary: out_write: underrun(81) frames_by_time(13162) > out->last_fifo_frames_remaining(12192)
02-17 04:01:46.575 809 5063 W audio_hw_primary: out_write: underrun(82) frames_by_time(13305) > out->last_fifo_frames_remaining(12336)
02-17 04:01:46.578 809 5063 W audio_hw_primary: out_write: underrun(83) frames_by_time(13447) > out->last_fifo_frames_remaining(12480)
02-17 04:01:46.581 809 5063 W audio_hw_primary: out_write: underrun(84) frames_by_time(13594) > out->last_fifo_frames_remaining(12624)
02-17 04:01:46.584 809 5063 W audio_hw_primary: out_write: underrun(85) frames_by_time(13735) > out->last_fifo_frames_remaining(12768)
02-17 04:01:46.587 809 5063 W audio_hw_primary: out_write: underrun(86) frames_by_time(13883) > out->last_fifo_frames_remaining(12912)
02-17 04:01:46.590 809 5063 W audio_hw_primary: out_write: underrun(87) frames_by_time(14023) > out->last_fifo_frames_remaining(13056)
02-17 04:01:46.593 809 5063 W audio_hw_primary: out_write: underrun(88) frames_by_time(14167) > out->last_fifo_frames_remaining(13200)
02-17 04:01:46.596 809 5063 W audio_hw_primary: out_write: underrun(89) frames_by_time(14315) > out->last_fifo_frames_remaining(13344)
02-17 04:01:46.599 809 5063 W audio_hw_primary: out_write: underrun(90) frames_by_time(14455) > out->last_fifo_frames_remaining(13488)

02-17 04:01:46.601 4942 4942 I wm_on_paused_called: [199789993,com.miHoYo.GetMobileInfo.MainActivity,performPause]
02-17 04:01:46.602 1017 4857 I wm_failed_to_pause: [0,199789993,com.miHoYo.Yuanshen/com.miHoYo.GetMobileInfo.MainActivity,(none)]

02-17 04:01:46.605 809 5063 W audio_hw_primary: out_write: underrun(92) frames_by_time(14750) > out->last_fifo_frames_remaining(13776)
02-17 04:01:46.609 809 5063 W audio_hw_primary: out_write: underrun(93) frames_by_time(14907) > out->last_fifo_frames_remaining(13920)
02-17 04:01:46.612 809 5063 W audio_hw_primary: out_write: underrun(94) frames_by_time(15055) > out->last_fifo_frames_remaining(14064)
02-17 04:01:46.615 809 5063 W audio_hw_primary: out_write: underrun(95) frames_by_time(15189) > out->last_fifo_frames_remaining(14208)
02-17 04:01:46.617 809 5063 W audio_hw_primary: out_write: underrun(96) frames_by_time(15318) > out->last_fifo_frames_remaining(14352)
02-17 04:01:46.620 809 5063 W audio_hw_primary: out_write: underrun(97) frames_by_time(15464) > out->last_fifo_frames_remaining(14496)
02-17 04:01:46.623 809 5063 W audio_hw_primary: out_write: underrun(98) frames_by_time(15609) > out->last_fifo_frames_remaining(14640)
02-17 04:01:46.627 809 5063 W audio_hw_primary: out_write: underrun(99) frames_by_time(15782) > out->last_fifo_frames_remaining(14784)
02-17 04:01:46.630 809 5063 W audio_hw_primary: out_write: underrun(100) frames_by_time(15907) > out->last_fifo_frames_remaining(14928)
02-17 04:01:46.633 809 5063 W audio_hw_primary: out_write: underrun(101) frames_by_time(16061) > out->last_fifo_frames_remaining(15072)
02-17 04:01:46.636 809 5063 W audio_hw_primary: out_write: underrun(102) frames_by_time(16199) > out->last_fifo_frames_remaining(15216)
02-17 04:01:46.638 809 5063 W audio_hw_primary: out_write: underrun(103) frames_by_time(16335) > out->last_fifo_frames_remaining(15360)
02-17 04:01:46.641 809 5063 W audio_hw_primary: out_write: underrun(104) frames_by_time(16472) > out->last_fifo_frames_remaining(15504)
02-17 04:01:46.644 809 5063 W audio_hw_primary: out_write: underrun(105) frames_by_time(16619) > out->last_fifo_frames_remaining(15648)

02-17 04:01:46.648 809 5063 W audio_hw_primary: out_write: underrun(106) frames_by_time(16772) > out->last_fifo_frames_remaining(15792)

02-17 04:01:46.651 809 5063 W audio_hw_primary: out_write: underrun(107) frames_by_time(16938) > out->last_fifo_frames_remaining(15936)
02-17 04:01:46.654 809 5063 W audio_hw_primary: out_write: underrun(108) frames_by_time(17067) > out->last_fifo_frames_remaining(16080)
02-17 04:01:46.656 809 5063 W audio_hw_primary: out_write: underrun(109) frames_by_time(17198) > out->last_fifo_frames_remaining(16224)
02-17 04:01:46.659 809 5063 W audio_hw_primary: out_write: underrun(110) frames_by_time(17335) > out->last_fifo_frames_remaining(16368)
02-17 04:01:46.662 809 5063 W audio_hw_primary: out_write: underrun(111) frames_by_time(17488) > out->last_fifo_frames_remaining(16512)
02-17 04:01:46.665 809 5063 W audio_hw_primary: out_write: underrun(112) frames_by_time(17631) > out->last_fifo_frames_remaining(16656)
02-17 04:01:46.668 809 5063 W audio_hw_primary: out_write: underrun(113) frames_by_time(17776) > out->last_fifo_frames_remaining(16800)
02-17 04:01:46.672 809 5063 W audio_hw_primary: out_write: underrun(114) frames_by_time(17928) > out->last_fifo_frames_remaining(16944)
02-17 04:01:46.674 809 5063 W audio_hw_primary: out_write: underrun(115) frames_by_time(18062) > out->last_fifo_frames_remaining(17088)
02-17 04:01:46.677 809 5063 W audio_hw_primary: out_write: underrun(116) frames_by_time(18209) > out->last_fifo_frames_remaining(17232)
02-17 04:01:46.681 809 5063 W audio_hw_primary: out_write: underrun(117) frames_by_time(18355) > out->last_fifo_frames_remaining(17376)
02-17 04:01:46.684 809 5063 W audio_hw_primary: out_write: underrun(118) frames_by_time(18499) > out->last_fifo_frames_remaining(17520)
02-17 04:01:46.687 809 5063 W audio_hw_primary: out_write: underrun(119) frames_by_time(18650) > out->last_fifo_frames_remaining(17664)
02-17 04:01:46.689 809 5063 W audio_hw_primary: out_write: underrun(120) frames_by_time(18775) > out->last_fifo_frames_remaining(17808)
02-17 04:01:46.692 809 5063 W audio_hw_primary: out_write: underrun(121) frames_by_time(18929) > out->last_fifo_frames_remaining(17952)
02-17 04:01:46.695 809 5063 W audio_hw_primary: out_write: underrun(122) frames_by_time(19070) > out->last_fifo_frames_remaining(18096)
02-17 04:01:46.698 809 5063 W audio_hw_primary: out_write: underrun(123) frames_by_time(19214) > out->last_fifo_frames_remaining(18240)
02-17 04:01:46.701 809 5063 W audio_hw_primary: out_write: underrun(124) frames_by_time(19356) > out->last_fifo_frames_remaining(18384)
02-17 04:01:46.704 809 5063 W audio_hw_primary: out_write: underrun(125) frames_by_time(19499) > out->last_fifo_frames_remaining(18528)
02-17 04:01:46.707 809 5063 W audio_hw_primary: out_write: underrun(126) frames_by_time(19644) > out->last_fifo_frames_remaining(18672)
02-17 04:01:46.710 809 5063 W audio_hw_primary: out_write: underrun(127) frames_by_time(19790) > out->last_fifo_frames_remaining(18816)
02-17 04:01:46.717 809 5063 W audio_hw_primary: out_write: underrun(129) frames_by_time(20088) > out->last_fifo_frames_remaining(19104)
02-17 04:01:46.719 809 5063 W audio_hw_primary: out_write: underrun(130) frames_by_time(20223) > out->last_fifo_frames_remaining(19248)
02-17 04:01:46.722 809 5063 W audio_hw_primary: out_write: underrun(131) frames_by_time(20366) > out->last_fifo_frames_remaining(19392)
02-17 04:01:46.725 809 5063 W audio_hw_primary: out_write: underrun(132) frames_by_time(20503) > out->last_fifo_frames_remaining(19536)
02-17 04:01:46.728 809 5063 W audio_hw_primary: out_write: underrun(133) frames_by_time(20649) > out->last_fifo_frames_remaining(19680)

02-17 04:01:46.731 809 5063 W audio_hw_primary: out_write: underrun(134) frames_by_time(20801) > out->last_fifo_frames_remaining(19824)
02-17 04:01:46.735 809 5063 W audio_hw_primary: out_write: underrun(135) frames_by_time(20955) > out->last_fifo_frames_remaining(19968)
02-17 04:01:46.737 809 5063 W audio_hw_primary: out_write: underrun(136) frames_by_time(21087) > out->last_fifo_frames_remaining(20112)
02-17 04:01:46.740 809 5063 W audio_hw_primary: out_write: underrun(137) frames_by_time(21229) > out->last_fifo_frames_remaining(20256)
02-17 04:01:46.743 809 5063 W audio_hw_primary: out_write: underrun(138) frames_by_time(21373) > out->last_fifo_frames_remaining(20400)
02-17 04:01:46.746 809 5063 W audio_hw_primary: out_write: underrun(139) frames_by_time(21518) > out->last_fifo_frames_remaining(20544)
02-17 04:01:46.749 809 5063 W audio_hw_primary: out_write: underrun(140) frames_by_time(21656) > out->last_fifo_frames_remaining(20688)
02-17 04:01:46.752 809 5063 W audio_hw_primary: out_write: underrun(141) frames_by_time(21799) > out->last_fifo_frames_remaining(20832)
02-17 04:01:46.755 809 5063 W audio_hw_primary: out_write: underrun(142) frames_by_time(21953) > out->last_fifo_frames_remaining(20976)
02-17 04:01:46.758 809 5063 W audio_hw_primary: out_write: underrun(143) frames_by_time(22088) > out->last_fifo_frames_remaining(21120)
02-17 04:01:46.761 809 5063 W audio_hw_primary: out_write: underrun(144) frames_by_time(22231) > out->last_fifo_frames_remaining(21264)
02-17 04:01:46.764 809 5063 W audio_hw_primary: out_write: underrun(145) frames_by_time(22379) > out->last_fifo_frames_remaining(21408)
02-17 04:01:46.767 809 5063 W audio_hw_primary: out_write: underrun(146) frames_by_time(22520) > out->last_fifo_frames_remaining(21552)
02-17 04:01:46.770 809 5063 W audio_hw_primary: out_write: underrun(147) frames_by_time(22662) > out->last_fifo_frames_remaining(21696)
02-17 04:01:46.773 809 5063 W audio_hw_primary: out_write: underrun(148) frames_by_time(22808) > out->last_fifo_frames_remaining(21840)
02-17 04:01:46.776 809 5063 W audio_hw_primary: out_write: underrun(149) frames_by_time(22953) > out->last_fifo_frames_remaining(21984)
02-17 04:01:46.779 809 5063 W audio_hw_primary: out_write: underrun(150) frames_by_time(23098) > out->last_fifo_frames_remaining(22128)
02-17 04:01:46.782 809 5063 W audio_hw_primary: out_write: underrun(151) frames_by_time(23242) > out->last_fifo_frames_remaining(22272)
02-17 04:01:46.785 809 5063 W audio_hw_primary: out_write: underrun(152) frames_by_time(23384) > out->last_fifo_frames_remaining(22416)
02-17 04:01:46.788 809 5063 W audio_hw_primary: out_write: underrun(153) frames_by_time(23528) > out->last_fifo_frames_remaining(22560)
02-17 04:01:46.791 809 5063 W audio_hw_primary: out_write: underrun(154) frames_by_time(23674) > out->last_fifo_frames_remaining(22704)
02-17 04:01:46.795 809 5063 W audio_hw_primary: out_write: underrun(155) frames_by_time(23829) > out->last_fifo_frames_remaining(22848)
02-17 04:01:46.797 809 5063 W audio_hw_primary: out_write: underrun(156) frames_by_time(23960) > out->last_fifo_frames_remaining(22992)
02-17 04:01:46.800 809 5063 W audio_hw_primary: out_write: underrun(157) frames_by_time(24106) > out->last_fifo_frames_remaining(23136)
02-17 04:01:46.803 809 5063 W audio_hw_primary: out_write: underrun(158) frames_by_time(24248) > out->last_fifo_frames_remaining(23280)
02-17 04:01:46.806 809 5063 W audio_hw_primary: out_write: underrun(159) frames_by_time(24399) > out->last_fifo_frames_remaining(23424)
02-17 04:01:46.809 809 5063 W audio_hw_primary: out_write: underrun(160) frames_by_time(24545) > out->last_fifo_frames_remaining(23568)
02-17 04:01:46.813 809 5063 W audio_hw_primary: out_write: underrun(161) frames_by_time(24703) > out->last_fifo_frames_remaining(23712)
02-17 04:01:46.815 809 5063 W audio_hw_primary: out_write: underrun(162) frames_by_time(24833) > out->last_fifo_frames_remaining(23856)
02-17 04:01:46.818 809 5063 W audio_hw_primary: out_write: underrun(163) frames_by_time(24977) > out->last_fifo_frames_remaining(24000)
02-17 04:01:46.821 809 5063 W audio_hw_primary: out_write: underrun(164) frames_by_time(25116) > out->last_fifo_frames_remaining(24144)
02-17 04:01:46.824 809 5063 W audio_hw_primary: out_write: underrun(165) frames_by_time(25261) > out->last_fifo_frames_remaining(24288)
02-17 04:01:46.827 809 5063 W audio_hw_primary: out_write: underrun(166) frames_by_time(25407) > out->last_fifo_frames_remaining(24432)
02-17 04:01:46.830 809 5063 W audio_hw_primary: out_write: underrun(167) frames_by_time(25553) > out->last_fifo_frames_remaining(24576)

02-17 04:01:46.849 1017 2779 W AudioIDCMicroNegotiator: idcm_warn: timeout for obtainFocusState: RequestInfosToIDCM{mPid=4942, mUid=10101}
02-17 04:01:46.849 1017 2029 D MediaFocusControl: audio_idcm: updateCurrentAudioFocus: mFocusStack is null, return
02-17 04:01:46.849 4942 4957 D miHoYo.Yuanshe: PlayerBase::stop() from IPlayer

02-17 04:01:46.849 1017 2779 W AudioService.PlaybackActivityMonitor: idcm_warn: ====rejected by IDCM: PLAYER_STATE_STARTED
02-17 04:01:46.849 4942 4957 D AudioTrack: stop(32): called with 25344 frames delivered
02-17 04:01:46.850 1017 2779 I MicroServiceManager: requestResult(abandonAudioFocus) parameters is{"functionInfo":{"IDCM_AudioFocus":"AudioFocus_Media"}}.

02-17 04:01:47.451 1017 2779 W AudioIDCMicroNegotiator: idcm_warn: timeout for obtainFocusState: null
02-17 04:01:47.451 1017 2029 W AS.AudioService: idcm_warn: onAudioFocusIDCMicroChanged: info is null return
02-17 04:01:47.452 2071 2891 D Avrcp_ext: AudioManager Player: AudioPlaybackConfiguration piid:295 deviceId:0 type:android.media.SoundPool u/pid:10086/2090 state:idle attr:AudioAttributes: usage=USAGE_ASSISTANCE_SONIFICATION content=CONTENT_TYPE_SONIFICATION flags=0x800 tags= bundle=null sessionId:0
02-17 04:01:47.453 2071 2891 D Avrcp_ext: AudioManager Player: AudioPlaybackConfiguration piid:311 deviceId:0 type:android.media.SoundPool u/pid:1000/2312 state:idle attr:AudioAttributes: usage=USAGE_ASSISTANCE_SONIFICATION content=CONTENT_TYPE_SONIFICATION flags=0x801 tags= bundle=null sessionId:0
02-17 04:01:47.453 2071 2891 D Avrcp_ext: AudioManager Player: AudioPlaybackConfiguration piid:343 deviceId:0 type:OpenSL ES AudioPlayer (Buffer Queue) u/pid:10101/4942 state:stopped attr:AudioAttributes: usage=USAGE_MEDIA content=CONTENT_TYPE_UNKNOWN flags=0x0 tags= bundle=null sessionId:321
02-17 04:01:47.453 2071 2891 D Avrcp_ext: AudioManager Player: AudioPlaybackConfiguration piid:287 deviceId:0 type:android.media.SoundPool u/pid:1000/1017 state:idle attr:AudioAttributes: usage=USAGE_ASSISTANCE_SONIFICATION content=CONTENT_TYPE_SONIFICATION flags=0x800 tags= bundle=null sessionId:0
02-17 04:01:47.453 2071 2891 D Avrcp_ext: AudioManager Player: AudioPlaybackConfiguration piid:319 deviceId:0 type:android.media.MediaPlayer u/pid:10094/3991 state:idle attr:AudioAttributes: usage=USAGE_UNKNOWN content=CONTENT_TYPE_UNKNOWN flags=0x800 tags= bundle=null sessionId:0
02-17 04:01:47.453 2071 2891 D Avrcp_ext: AudioManager Player: AudioPlaybackConfiguration piid:335 deviceId:0 type:android.media.MediaPlayer u/pid:10057/5014 state:idle attr:AudioAttributes: usage=USAGE_UNKNOWN content=CONTENT_TYPE_UNKNOWN flags=0x800 tags= bundle=null sessionId:0
02-17 04:01:47.453 2071 2891 D Avrcp_ext: AudioManager isPlaying: false, mAudioPlaybackIsActive = false
02-17 04:01:47.453 2071 2891 D Avrcp_ext: AudioManager Reset Active Player

从这个角度来看，需要测试的同事@赵飞 ，用Jenkins的版本进行测试，获取更多的样本，分析该种情况的是否正常。
（Tips：测试环境尽量全面，游戏应用，播放音乐等等，应用越多，场景越复杂，获取的分析样本就更多）

Jenkins的版本信息：
//userdebug 版本
/Pre_figure/VerifyBuild/Pre_figure_turbox-c2130c-la1.1-qssi12-dev/20230314/202303141719-2928
//user版本
/Pre_figure/VerifyBuild/Pre_figure_turbox-c2130c-la1.1-qssi12-dev/20230314/202303141750-2929

#9 Updated by CDTS_TEST 王成 over 2 years ago

  • Target version changed from VC1_FSE_0082_20230314 to VC1_FSE_0090_20230411

#10 Updated by CD FW王武军 over 2 years ago

【】当前情况

1、Jenkins版本相关日志的分析

发生no focused window的ANR大致存在两个情况：
情况1）应用启动时花费较长时间，如在activityStart阶段耗时很长，这个时候事件输入，那么就存在no focused window的问题；

情况2）启动应用正常，但是focused window的切换时间过长，焦点未能及时的聚焦到当前应用上。分发事件时出现no focused window

结合逻辑层面的分析：
情况1：应用启动阶段耗时长，也许是应用内部启动问题，也许是系统调度问题。
情况2：应用正常启动，但是设置焦点的逻辑在较长一段时间未设置到位。这个应该与系统的性能有关系，因为焦点的切换与屏幕时钟信号的回调有关系。

【】后续策略

从目前获取到的调查信息来看，该ANR的发生与系统的整体系统有关系，或者说与跑monkey测试时系统的整体性能有关系。
1、针对性能方面的猜想，已经向高通提了对应的case，在持续跟进中。到底瓶颈在什么地方？要具体到逻辑层面这个可能还需要研究。
2、针对ANR的思考，该ANR的发生从功能层面来说是无效的ANR，应用还在启动界面都还没有加载完成或者获取到正确的焦点，这个时候事件的输入
从功能层面来说，这个时候的事件是没有view来承载的。
3、为了测试考虑，针对monkey测试时，为了规避no focused window的触发，做了一个拦截方案
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/186925
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/native/+/186924

#11 Updated by CD APP-王营 over 2 years ago

  • Category changed from CD-APP to CD-FW

#12 Updated by CD TPM-王祥林 about 2 years ago

  • Severity changed from Normal to Critical

#13 Updated by CD FW 曹覃刚 about 2 years ago

  • Category changed from CD-FW to SYSTEM
  • Assignee changed from CD FW王武军 to CD SYSTEM-夏旭

Hi 夏旭(是与雷祥沟通的)

■ 我的分析
1.AF当前的分析情况
原生问题，和性能瓶颈有关，相同的monkey测试，设置点击时间间隔为500ms，联想的对比机基本不会发生问题，但是使用高合的板子，很容易复现问题
联想的对比机将时间间隔设置成50ms, 才容易出现问题
但是高合的板子从芯片以及内存来看，性能都是要优于联想的对比机的
其他分析情况请参考之前更新的comment

2.以下是高通对于这个问题的回复
----------------------
Dear Valued Customer:
....
然后从systrace上看，该activity start确实是耗费了11S的时间，你可以看下我上传的截图。
但查看该systrace，并没有看到这个启动耗时是花费在哪里了，这个时候查看CPU的信息，可以看到4,5,6,7这4个大核基本都是没参与进程运行的，所以问题发生的原因应该是和这几个CPU大核没出力有关。
Thanks & Brs.
----------------------

今天跟雷祥将高合的板子，通过脚本将性能拉满后，设置monkey的时间间隔为100ms, 测试暂时未复现问题
从目前的分析和测试情况来看，需要system组的同学帮忙分析此性能问题

■ 下一步解析计划
需要system组的同学帮忙分析此性能问题, 谢谢

#14 Updated by CD SYSTEM-夏旭 about 2 years ago

  • % Done changed from 0 to 10

[当前情况]
1. 目前怀疑的activity start确耗费大量时间，可能依赖某些input，但是高通CE也并没有看出啥信息，需要FW这边后续继续追踪此问题，可能为root case.
2. 当提高cpu的频率为最大，再次进行monkey测试，发现没有出现ANR，确认此ANR错误是由于高通在当前环境的cpu调度策略引起的性能问题。

[下一步动作]
针对第2点，system这边有2个事情需要处理：
1. 重新提高通case，调查并定位此场景，并查看如何在此场景进行规避此问题。
2. 对对比机进行测试并抓取trace，对比2者在monkey时cpu的频率和调度情况。

#15 Updated by CD SYSTEM-夏旭 about 2 years ago

[当前情况]
正在按照高通的手顺复现问题并抓取日志，并反馈给高通CE

adb shell setprop persist.debug_anr.enable 1
adb shell setprop persist.debug_anr.timer_value 100
adb shell setprop persist.debug_anr.process xxx

[下一步动作]
等待高通CE的反馈

#16 Updated by CD SYSTEM-夏旭 about 2 years ago

[当前情况]
添加增强日志后，在只存在预置app的情况下，使用如下monkey命令，执行1小时未发生anr，

monkey --pkg-blacklist-file /sdcard/blacklist.txt --ignore-crashes --ignore-timeouts --ignore-security-exceptions --monitor-native-crashes --ignore-native-crashes -s 20 --throttle 100 --pct-touch 30 --pct-motion 15 --pct-nav 15 --pct-majornav 15 --pct-syskeys 5 --pct-appswitch 10 --pct-anyevent 10 --ignore-crashes -v -v -v 86400

[下一步动作]
准备多安装几个app在进行尝试复现问题

#17 Updated by CD SYSTEM-夏旭 about 2 years ago

[当前情况]
在原本预置app的情况下，使用monkey 100ms进行测试，问题复现概率不算太高，且发生ANR的应用比较随机，但是高通提供的手顺需要指定应用，所以一直在复现中，
目前已经复现成功，并抓取logcat和anr日志，已经提供给高通

[下一步动作]
等待高通CE根据目前的日志反馈信息

#18 Updated by CD SYSTEM-夏旭 about 2 years ago

[当前情况]
提供给高通的日志显示：
04-12 16:29:19.908 1072 1806 I WindowManager: ANR in ActivityRecord{4363639 u0 com.android.settings/.Settings$RunningServicesActivity t2423}. Reason: Application does not have a focused window
从这次的Log中看到出现了settings的anr，然后查看出现ANR之前的log，看到
04-12 16:29:16.926 2712 2712 W Looper : Slow dispatch took 5020ms h=Handler (android.view.Choreographer$FrameHandler) {a76fc43} c=android.view.Choreographer$FrameDisplayEventReceiver@45802c0 m=0
当时该应用中主线程中处理该消息时耗时5020ms，导致了ANR。然后结合代码看到
1033 public void handleMessage(Message msg) {
1034 switch (msg.what) {
1035 case MSG_DO_FRAME:
1036 doFrame(System.nanoTime(), 0, new DisplayEventReceiver.VsyncEventData());
1037 break;
是在执行doFrame的过程耗时长了。但是具体是这个函数中哪里耗时长了，需要查看对应的trace log来查看堆栈。但是我查看提供的anr文件夹中，发现所有的trace文件中打印的时间都是
----- pid 2712 at 2023-04-12 17:31:14.041003102+0800 -----
也就是logcat log和trace log不对应，所以，没有对应时间点的trace来确认当时该线程在执行什么，为什么会耗时较长。
高通没法继续深入分析。

[下一步动作]
需要重新再复现并抓取日志提供给高通

#19 Updated by CD SYSTEM-夏旭 about 2 years ago

[当前情况]
提供给高通的日志后，高通回复如下：

04-12 16:19:02.309 1090 9744 I am_anr : [0,2679,com.android.settings,952647173,Input dispatching timed out (Application does not have a focused window)]
这个时候出现了ANR，然后在这个之前看到

04-12 16:18:56.531 2679 2679 I wm_on_stop_called: [52621795,com.android.settings.homepage.SettingsHomepageActivity,STOP_ACTIVITY_ITEM]
SettingsHomepageActivity当时已经stop了。所以，看到后续出现ANR后，提示Application does not have a focused window。
然后查看出现问题时的窗口信息

行 1362705: 04-12 16:18:56.429 2679 2679 I wm_on_resume_called: [52621795,com.android.settings.homepage.SettingsHomepageActivity,RESUME_ACTIVITY]
行 1362726: 04-12 16:18:56.497 2679 2679 I wm_on_top_resumed_gained_called: [52621795,com.android.settings.homepage.SettingsHomepageActivity,topWhenResuming]
行 1362728: 04-12 16:18:56.499 2679 2679 I wm_on_top_resumed_lost_called: [52621795,com.android.settings.homepage.SettingsHomepageActivity,topStateChangedWhenResumed]
行 1362736: 04-12 16:18:56.506 2679 2679 I wm_on_paused_called: [52621795,com.android.settings.homepage.SettingsHomepageActivity,performPause]
行 1362738: 04-12 16:18:56.508 1090 1188 I wm_stop_activity: [0,52621795,com.android.settings/.homepage.SettingsHomepageActivity]
行 1362742: 04-12 16:18:56.520 2679 2679 I wm_on_destroy_called: [198303984,com.android.settings.Settings$StorageUseActivity,performDestroy]
行 1362745: 04-12 16:18:56.521 1090 2188 I wm_task_removed: [3442,removeChild:removeChild last r=ActivityRecord{bd1e0f0 u0 com.android.settings/.Settings$StorageUseActivity t-1 f}} in t=Task{8c8718f #3442 type=standard A=1000:com.android.settings U=0 visible=false mode=fullscreen translucent=true sz=0}]
行 1362746: 04-12 16:18:56.521 1090 2188 I wm_task_removed: [3442,removeChild]
行 1362757: 04-12 16:18:56.531 2679 2679 I wm_on_stop_called: [52621795,com.android.settings.homepage.SettingsHomepageActivity,STOP_ACTIVITY_ITEM]

看到SettingsHomepageActivity调用resume后，立刻又调用了SettingsHomepageActivity的pause和stop。从而导致了问题。但是为什么会出现这个调用，目前的log中看不出原因。请在frameworks/base/services/core/java/com/android/server/wm/ActivityTaskManagerDebugConfig.java
中将
static final boolean DEBUG_ALL = false;
赋值为true，然后复现问题，并提供对应的log。通过开启更多的Log看看上面所说的activity的相关调用。

[下一步动作]
需要重新再复现并抓取日志提供给高通

#20 Updated by CD SYSTEM-夏旭 about 2 years ago

[当前情况]
应用高通的patch后，已复现问题，并抓取日志提供给高通。
另外system内部分析应该不是cpu调度的问题，app并没有处于等待调用的状态 且有自由调度到大核。

[下一步动作]
等待高通CE反馈，并与FW进行沟通确认问题

#21 Updated by CD SYSTEM-胡兵 about 2 years ago

  • Assignee changed from CD SYSTEM-夏旭 to CD-Dev 夏坤

#22 Updated by CD-Dev 夏坤 about 2 years ago

[当前情况]


Dear Valued Customer
从这次的log看到
04-20 17:13:28.537 1052 13917 I am_anr : [0,9803,com.android.settings,952647173,Input dispatching timed out (2a40e00 com.android.settings/com.android.settings.homepage.SettingsHomepageActivity (server) is not responding. Waited 5001ms for KeyEvent(deviceId=-1, eventTime=2017039000000, source=0x00000101, displayId=-1, action=UP, flags=0x00000008, keyCode=22, scanCode=0, metaState=0x00000000, repeatCount=0), policyFlags=0x6b000000)]
ANR的原因是Input dispatching timed out，没有看到之前没有焦点窗口的信息。并且看到
04-20 17:13:33.540 9803 9803 W Looper : Slow dispatch took 10258ms h=Handler (android.view.Choreographer$FrameHandler) {734fe1d} c=android.view.Choreographer$FrameDisplayEventReceiver@e6b3892 m=0
在主线程中处理该消息耗时10258ms，然后从对应的trace log看到
at android.widget.LinearLayout.onMeasure(LinearLayout.java:721)
at android.view.View.measure(View.java:25778)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:6980)
at android.widget.FrameLayout.onMeasure(FrameLayout.java:194)
at com.android.internal.policy.DecorView.onMeasure(DecorView.java:825)
at android.view.View.measure(View.java:25778)
at android.view.ViewRootImpl.performMeasure(ViewRootImpl.java:3631)
at android.view.ViewRootImpl.measureHierarchy(ViewRootImpl.java:2427)
at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:2697)
at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:2146)
at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:8676)
at android.view.Choreographer$CallbackRecord.run(Choreographer.java:1120)
at android.view.Choreographer.doCallbacks(Choreographer.java:926)
at android.view.Choreographer.doFrame(Choreographer.java:859)
at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:1105)
当时该消息的处理就是执行doFrame来刷新界面显示。所以，从当时的应用本身来看，并没有什么异常，只是正常的刷新界面而已。然后从出现ANR时的CPU占用来看
04-20 17:13:33.974 1052 13917 E ActivityManager: CPU usage from 0ms to 5410ms later (2023-04-20 17:13:28.457 to 2023-04-20 17:13:33.867):
04-20 17:13:33.974 1052 13917 E ActivityManager: 52% 4490/adbd: 6.2% user + 46% kernel / faults: 771 minor
04-20 17:13:33.974 1052 13917 E ActivityManager: 46% 1043/surfaceflinger: 22% user + 24% kernel / faults: 119 minor
04-20 17:13:33.974 1052 13917 E ActivityManager: 37% 1052/system_server: 14% user + 22% kernel / faults: 25319 minor
04-20 17:13:33.974 1052 13917 E ActivityManager: 33% 955/vendor.qti.hardware.display.composer-service: 11% user + 22% kernel / faults: 19 minor
04-20 17:13:33.974 1052 13917 E ActivityManager: 31% 498/logd: 1.6% user + 29% kernel / faults: 212 minor
04-20 17:13:33.974 1052 13917 E ActivityManager: 21% 2108/com.android.systemui: 13% user + 8.3% kernel / faults: 2087 minor
04-20 17:13:33.974 1052 13917 E ActivityManager: 19% 77/kworker/6:1+max96755g_dtc_work: 0% user + 19% kernel
04-20 17:13:33.974 1052 13917 E ActivityManager: 18% 1410/media.codec: 3.1% user + 15% kernel / faults: 12 minor
04-20 17:13:33.974 1052 13917 E ActivityManager: 17% 2798/com.android.launcher3: 9.2% user + 8.6% kernel / faults: 7211 minor
04-20 17:13:33.974 1052 13917 E ActivityManager: 13% 9803/com.android.settings: 7.1% user + 6.6% kernel / faults: 916 minor

settings应用本身也没有占用太多，看到占用较多的是surfaceflinger等和显示相关的模块，另外就是adbd进程了。所以，针对该问题，我建议后续测试中抓一下top信息和meminfo信息，看看是否由于CPU占用或者内存占用导致了系统性能下降，从而引起该问题。

Thanks
Weidong Feng
Tel: 021-61105311

[下一步动作]
测试中抓一下top信息和meminfo信息

#23 Updated by CD-Dev 夏坤 about 2 years ago

[当前情况]
内部讨论，Monkey测试下抓top和meminfo可能意义不大，跑Monkey本来负载就高和有一些随机性

当前有几点尝试
1. 修改为小分辨率，看是否有改善
2. 相关进程绑核，看看是否有改善

#24 Updated by IoT scm about 2 years ago

Gerrit Merge Information：
ID Project Branch Uploader
195914 general/platform/frameworks/base Pre_figure_turbox-c2130c-la1.1-qssi12-dev
AF:QuickSettings: Prohibit screen off when doing monkey test
TC-RID: 1201-0201903
IssueID: TS-R-BUG-116540
Change-Id: Id74297e57c7168bd40cf918585af43c9cef700c1

#25 Updated by CD FW 曹覃刚 about 2 years ago

  • Category changed from SYSTEM to CD-FW
  • Status changed from ASSIGNED to RESOLVED
  • Assignee changed from CD-Dev 夏坤 to CD TEST-方永红
  • % Done changed from 10 to 100
  • Resolution changed from -- to FIXED
  • Degrated changed from -- to No
  • Fixed Version set to 2023-04-25
  • Root cause set to 已修复Monkey产生的Application does not have a focused window类型ANR

----------
在ANR发生前，屏幕被关了，在屏幕再次开启后又好了，没有ANR
04-24 07:48:51.948 972 972 I PowerManagerService: Powering off display group due to power_button (groupId= 0, uid= 1000)...
04-24 07:48:51.949 972 972 I PowerManagerService: Going to sleep due to power_button (uid 1000)...

04-24 07:48:57.434 972 1797 I WindowManager: ANR in ActivityRecord{d837c7a u0 com.hht.lebocast/.GuidanceActivity t590}. Reason: Application does not have a focused window
04-24 07:49:02.644 972 1797 I WindowManager: ANR in ActivityRecord{d837c7a u0 com.hht.lebocast/.GuidanceActivity t590}. Reason: Application does not have a focused window
04-24 07:49:23.242 972 1797 I WindowManager: ANR in ActivityRecord{de12058 u0 com.android.gallery3d/.app.MovieActivity t580}. Reason: Application does not have a focused window
04-24 07:51:00.465 972 1797 I WindowManager: ANR in ActivityRecord{de12058 u0 com.android.gallery3d/.app.MovieActivity t580}. Reason: Application does not have a focused window
04-24 07:51:10.798 972 1797 I WindowManager: ANR in ActivityRecord{de12058 u0 com.android.gallery3d/.app.MovieActivity t580}. Reason: Application does not have a focused window
04-24 07:51:15.955 972 1797 I WindowManager: ANR in ActivityRecord{de12058 u0 com.android.gallery3d/.app.MovieActivity t580}. Reason: Application does not have a focused window

04-24 07:51:16.031 972 5485 I PowerManagerService: Powering on display group fromAsleep (groupId=0, uid=1000, reason=WAKE_REASON_WAKE_KEY, details=android.policy:KEY)...
04-24 07:51:16.032 972 5485 I PowerManagerService: Waking up from Asleep (uid=1000, reason=WAKE_REASON_WAKE_KEY, details=android.policy:KEY)...
----------

息屏时，收到event事件，导致ANR
修复提交
https://dev.thundercomm.com/gerrit/c/general/platform/frameworks/base/+/195914

#26 Updated by CD TEST-方永红 about 2 years ago

5.15
13日DB未复现
继续跟踪两个版本

#27 Updated by CD TEST-方永红 about 2 years ago

5.16
15日DB未复现
继续跟踪一个版本

#28 Updated by CD TEST-方永红 about 2 years ago

  • Status changed from RESOLVED to VERIFIED
  • Verified Version set to FlatBuild_HH_MCE_FSE.M.R.user.01.00.0100.C103(X103)

5.17
0100版本未复现，先关闭

#29 Updated by CD TEST-方永红 about 2 years ago

  • Status changed from VERIFIED to CLOSED

Also available in: Atom PDF