System process continuous ANR

[VulcainMan]

Which system do you use? Android, Ubuntu, OOWOW or others?

Android

Which version of system do you use? Please provide the version of the system here:

9.0 (built locally from sources the 2025/10/16)

Please describe your issue below:

Basically, we are using Khadas VIM3L as Set Top Boxes for the IPTV solutions we provide. We noticed that sometimes (rarely) after a device reboot, we face continuous ANR of the system process (every 2 or 3 minutes) for a duration between 30 minutes to several hours then, it suddendly ends like it begins. Moreover, this behavior continues even if the device is rebooted, powered off, etc.

Since such incident are usually hard to track, do you want me to provide full logcat ? ANR report ? Anything else ?

Post a console log of your issue below:

02-09 09:05:19.583  3348  3363 W ActivityManager: Timeout executing service: ServiceRecord{e71df53 u0 android/com.android.internal.backup.LocalTransportService}
02-09 09:05:20.009  3348  3363 I chatty  : uid=1000 system_server expire 42 lines
02-09 09:05:20.010  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3348 and type kDebuggerdJavaBacktrace
02-09 09:05:20.010  3348  3353 I chatty  : uid=1000 system_server expire 6 lines
02-09 09:05:20.213  3214  3214 I /system/bin/tombstoned: received crash request for pid 3348
02-09 09:05:20.213  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3348 and type kDebuggerdJavaBacktrace
02-09 09:05:20.217  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3925 and type kDebuggerdJavaBacktrace
02-09 09:05:20.217  3925  3939 I SubTitleServic: Thread[3,tid=3939,WaitingInMainSignalCatcherLoop,Thread*=0x7331139000,peer=0x13440020,"Signal Catcher"]: reacting to signal 3
02-09 09:05:20.217  3925  3939 I SubTitleServic: 
02-09 09:05:20.262  3214  3214 I /system/bin/tombstoned: received crash request for pid 3925
02-09 09:05:20.262  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3925 and type kDebuggerdJavaBacktrace
02-09 09:05:20.262  3925  3939 I SubTitleServic: Wrote stack traces to '[tombstoned]'
02-09 09:05:20.264  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3916 and type kDebuggerdJavaBacktrace
02-09 09:05:20.264  3916  3924 I com.android.se: Thread[3,tid=3924,WaitingInMainSignalCatcherLoop,Thread*=0x7331139000,peer=0x13380020,"Signal Catcher"]: reacting to signal 3
02-09 09:05:20.264  3916  3924 I com.android.se: 
02-09 09:05:20.311  3214  3214 I /system/bin/tombstoned: received crash request for pid 3916
02-09 09:05:20.311  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3916 and type kDebuggerdJavaBacktrace
02-09 09:05:20.312  3916  3924 I com.android.se: Wrote stack traces to '[tombstoned]'
02-09 09:05:20.313  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3903 and type kDebuggerdJavaBacktrace
02-09 09:05:20.313  3903  3909 I utmethod.remot: Thread[3,tid=3909,WaitingInMainSignalCatcherLoop,Thread*=0x7331139000,peer=0x132c0020,"Signal Catcher"]: reacting to signal 3
02-09 09:05:20.313  3903  3909 I utmethod.remot: 
02-09 09:05:20.359  3214  3214 I /system/bin/tombstoned: received crash request for pid 3903
02-09 09:05:20.359  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3903 and type kDebuggerdJavaBacktrace
02-09 09:05:20.359  3903  3909 I utmethod.remot: Wrote stack traces to '[tombstoned]'
02-09 09:05:20.360  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3612 and type kDebuggerdJavaBacktrace
02-09 09:05:20.361  3612  3632 I m.android.phon: Thread[3,tid=3632,WaitingInMainSignalCatcherLoop,Thread*=0x7331139000,peer=0x13080020,"Signal Catcher"]: reacting to signal 3
02-09 09:05:20.361  3612  3632 I m.android.phon: 
02-09 09:05:20.427  3214  3214 I /system/bin/tombstoned: received crash request for pid 3612
02-09 09:05:20.427  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3612 and type kDebuggerdJavaBacktrace
02-09 09:05:20.427  3612  3632 I m.android.phon: Wrote stack traces to '[tombstoned]'
02-09 09:05:20.428  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3593 and type kDebuggerdJavaBacktrace
02-09 09:05:20.428  3593  3611 I com.droidlogic: Thread[3,tid=3611,WaitingInMainSignalCatcherLoop,Thread*=0x7331139000,peer=0x13040020,"Signal Catcher"]: reacting to signal 3
02-09 09:05:20.428  3593  3611 I com.droidlogic: 
02-09 09:05:20.489  3214  3214 I /system/bin/tombstoned: received crash request for pid 3593
02-09 09:05:20.489  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3593 and type kDebuggerdJavaBacktrace
02-09 09:05:20.489  3593  3611 I com.droidlogic: Wrote stack traces to '[tombstoned]'
02-09 09:05:20.490  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3488 and type kDebuggerdJavaBacktrace
02-09 09:05:20.490  3488  3504 I ndroid.systemu: Thread[3,tid=3504,WaitingInMainSignalCatcherLoop,Thread*=0x7331139000,peer=0x13900088,"Signal Catcher"]: reacting to signal 3
02-09 09:05:20.491  3488  3504 I ndroid.systemu: 
02-09 09:05:21.567  3214  3214 I /system/bin/tombstoned: received crash request for pid 3488
02-09 09:05:21.567  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3488 and type kDebuggerdJavaBacktrace
02-09 09:05:21.568  3488  3504 I ndroid.systemu: Wrote stack traces to '[tombstoned]'
02-09 09:05:21.570  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3028 and type kDebuggerdNativeBacktrace
02-09 09:05:21.593  4043  4043 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:21.594  3214  3214 I /system/bin/tombstoned: received crash request for pid 3028
02-09 09:05:21.594  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3028 and type kDebuggerdNativeBacktrace
02-09 09:05:21.594  4043  4043 I crash_dump64: performing dump of process 3028 (target tid = 3028)
02-09 09:05:21.596     1     1 I init    : type=1400 audit(0.0:186): avc: denied { sigchld } for scontext=u:object_r:dhclient_exec:s0 tcontext=u:r:init:s0 tclass=process permissive=1
02-09 09:05:21.598  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3092 and type kDebuggerdNativeBacktrace
02-09 09:05:21.598  3092  3092 I libc    : Requested dump for tid 3092 (hdmicecd)
02-09 09:05:21.656  4048  4048 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:21.657  3214  3214 I /system/bin/tombstoned: received crash request for pid 3092
02-09 09:05:21.657  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3092 and type kDebuggerdNativeBacktrace
02-09 09:05:21.657  4048  4048 I crash_dump64: performing dump of process 3092 (target tid = 3092)
02-09 09:05:21.667  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3095 and type kDebuggerdNativeBacktrace
02-09 09:05:21.668  3095  3095 I libc    : Requested dump for tid 3095 (systemcontrol)
02-09 09:05:21.690  4053  4053 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:21.690  3214  3214 I /system/bin/tombstoned: received crash request for pid 3095
02-09 09:05:21.691  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3095 and type kDebuggerdNativeBacktrace
02-09 09:05:21.691  4053  4053 I crash_dump64: performing dump of process 3095 (target tid = 3095)
02-09 09:05:21.707  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3125 and type kDebuggerdNativeBacktrace
02-09 09:05:21.707  3125  3125 I libc    : Requested dump for tid 3125 (audioserver)
02-09 09:05:21.737  4059  4059 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:21.738  3214  3214 I /system/bin/tombstoned: received crash request for pid 3125
02-09 09:05:21.738  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3125 and type kDebuggerdNativeBacktrace
02-09 09:05:21.738  4059  4059 I crash_dump32: performing dump of process 3125 (target tid = 3125)
02-09 09:05:21.776  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3127 and type kDebuggerdNativeBacktrace
02-09 09:05:21.811  4064  4064 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:21.811  3214  3214 I /system/bin/tombstoned: received crash request for pid 3127
02-09 09:05:21.811  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3127 and type kDebuggerdNativeBacktrace
02-09 09:05:21.811  4064  4064 I crash_dump64: performing dump of process 3127 (target tid = 3127)
02-09 09:05:21.974  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3187 and type kDebuggerdNativeBacktrace
02-09 09:05:21.974  3187  3187 I libc    : Requested dump for tid 3187 (cameraserver)
02-09 09:05:22.000  4070  4070 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:22.001  3214  3214 I /system/bin/tombstoned: received crash request for pid 3187
02-09 09:05:22.001  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3187 and type kDebuggerdNativeBacktrace
02-09 09:05:22.001  4070  4070 I crash_dump32: performing dump of process 3187 (target tid = 3187)
02-09 09:05:22.021  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3188 and type kDebuggerdNativeBacktrace
02-09 09:05:22.021  3188  3188 I libc    : Requested dump for tid 3188 (drmserver)
02-09 09:05:22.046  4076  4076 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:22.047  3214  3214 I /system/bin/tombstoned: received crash request for pid 3188
02-09 09:05:22.047  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3188 and type kDebuggerdNativeBacktrace
02-09 09:05:22.047  4076  4076 I crash_dump32: performing dump of process 3188 (target tid = 3188)
02-09 09:05:22.060     1     1 I init    : type=1400 audit(0.0:187): avc: denied { sigchld } for scontext=u:object_r:dhclient_exec:s0 tcontext=u:r:init:s0 tclass=process permissive=1
02-09 09:05:22.064  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3197 and type kDebuggerdNativeBacktrace
02-09 09:05:22.065  3197  3197 I libc    : Requested dump for tid 3197 (mediadrmserver)
02-09 09:05:22.087  4082  4082 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:22.088  3214  3214 I /system/bin/tombstoned: received crash request for pid 3197
02-09 09:05:22.088  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3197 and type kDebuggerdNativeBacktrace
02-09 09:05:22.088  4082  4082 I crash_dump32: performing dump of process 3197 (target tid = 3197)
02-09 09:05:22.102  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3198 and type kDebuggerdNativeBacktrace
02-09 09:05:22.104  3214  3214 I /system/bin/tombstoned: received crash request for pid 3198
02-09 09:05:22.104  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3198 and type kDebuggerdNativeBacktrace
02-09 09:05:22.150  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3199 and type kDebuggerdNativeBacktrace
02-09 09:05:22.151  3199  3199 I libc    : Requested dump for tid 3199 (mediametrics)
02-09 09:05:22.173  4088  4088 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:22.174  3214  3214 I /system/bin/tombstoned: received crash request for pid 3199
02-09 09:05:22.174  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3199 and type kDebuggerdNativeBacktrace
02-09 09:05:22.174  4088  4088 I crash_dump64: performing dump of process 3199 (target tid = 3199)
02-09 09:05:22.184  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3201 and type kDebuggerdNativeBacktrace
02-09 09:05:22.184  3201  3201 I libc    : Requested dump for tid 3201 (mediaserver)
02-09 09:05:22.212  4093  4093 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:22.213  3214  3214 I /system/bin/tombstoned: received crash request for pid 3201
02-09 09:05:22.213  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3201 and type kDebuggerdNativeBacktrace
02-09 09:05:22.213  4093  4093 I crash_dump32: performing dump of process 3201 (target tid = 3201)
02-09 09:05:22.233  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3205 and type kDebuggerdNativeBacktrace
02-09 09:05:22.235  3214  3214 I /system/bin/tombstoned: received crash request for pid 3205
02-09 09:05:22.235  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3205 and type kDebuggerdNativeBacktrace
02-09 09:05:22.309  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3458 and type kDebuggerdNativeBacktrace
02-09 09:05:22.309  3458  3458 I libc    : Requested dump for tid 3458 (droid.bluetooth)
02-09 09:05:22.365  4098  4098 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:05:22.365  3214  3214 I /system/bin/tombstoned: received crash request for pid 3458
02-09 09:05:22.365  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3458 and type kDebuggerdNativeBacktrace
02-09 09:05:22.366  4098  4098 I crash_dump64: performing dump of process 3458 (target tid = 3458)
02-09 09:05:22.584  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3940 and type kDebuggerdJavaBacktrace
02-09 09:05:22.585  3940  3954 I reamvision.hya: Thread[3,tid=3954,WaitingInMainSignalCatcherLoop,Thread*=0x7331139000,peer=0x13500020,"Signal Catcher"]: reacting to signal 3
02-09 09:05:22.585  3940  3954 I reamvision.hya: 
02-09 09:05:23.620  3214  3214 I /system/bin/tombstoned: received crash request for pid 3940
02-09 09:05:23.620  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3940 and type kDebuggerdJavaBacktrace
02-09 09:05:23.620  3940  3954 I reamvision.hya: Wrote stack traces to '[tombstoned]'
02-09 09:05:23.622  3348  3363 E ActivityManager: ANR in system
02-09 09:05:23.622  3348  3363 E ActivityManager: PID: 3348
02-09 09:05:23.622  3348  3363 E ActivityManager: Reason: executing service android/com.android.internal.backup.LocalTransportService
02-09 09:05:23.622  3348  3363 E ActivityManager: Load: 1.87 / 0.52 / 0.18
02-09 09:05:23.622  3348  3363 E ActivityManager: CPU usage from 9571ms to 0ms ago (2026-02-09 09:05:10.016 to 2026-02-09 09:05:19.587):
02-09 09:05:23.622  3348  3363 E ActivityManager:   12% 3097/android.hardware.audio@2.0-service: 0.8% user + 11% kernel / faults: 39 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:   7.6% 3940/com.streamvision.hyas: 4.5% user + 3% kernel / faults: 312 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:   3.5% 3127/surfaceflinger: 1.6% user + 1.8% kernel / faults: 341 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:   3.4% 3348/system_server: 2.1% user + 1.2% kernel / faults: 46 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:   2% 3027/logd: 0.4% user + 1.6% kernel / faults: 3 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:   1.3% 3120/android.hardware.sensors@1.0-service: 0.7% user + 0.6% kernel / faults: 278 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:   1.1% 7/rcu_preempt: 0% user + 1.1% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.8% 2146/kworker/0:2: 0% user + 0.8% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.6% 3327/irq/27-ff660000: 0% user + 0.6% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.5% 1434/kworker/3:1: 0% user + 0.5% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.5% 1916/kthread_di: 0% user + 0.5% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.4% 1797/cfinteractive: 0% user + 0.4% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.4% 2391/kworker/u9:1: 0% user + 0.4% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.4% 3092/hdmicecd: 0.1% user + 0.3% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.3% 3113/android.hardware.graphics.composer@2.2-service: 0.1% user + 0.2% kernel / faults: 36 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.1% 3095/systemcontrol: 0% user + 0.1% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.1% 3180/rild: 0% user + 0.1% kernel / faults: 16 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:   0.1% 3344/aml_buf_toggle_: 0% user + 0.1% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager: 6.1% TOTAL: 2.3% user + 3.8% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager: CPU usage from 55ms to 394ms later (2026-02-09 09:05:19.642 to 2026-02-09 09:05:19.981):
02-09 09:05:23.622  3348  3363 E ActivityManager:   27% 3027/logd: 6.9% user + 20% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:     24% 3040/logd.auditd: 0% user + 24% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   19% 3348/system_server: 0% user + 19% kernel / faults: 116 minor
02-09 09:05:23.622  3348  3363 E ActivityManager:     19% 3363/ActivityManager: 3.9% user + 15% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   3.5% 3097/android.hardware.audio@2.0-service: 3.5% user + 0% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:     3.5% 3324/HwBinder:3097_1: 0% user + 3.5% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager:   4.4% 3940/com.streamvision.hyas: 4.4% user + 0% kernel
02-09 09:05:23.622  3348  3363 E ActivityManager: 12% TOTAL: 4% user + 8.8% kernel
02-09 09:05:23.648  3348  3365 I ActivityManager: Start proc 4102:com.android.deskclock/u0a32 for broadcast com.android.deskclock/.AlarmInitReceiver
02-09 09:05:23.651  4102  4102 I Zygote  : seccomp disabled by setenforce 0
02-09 09:05:23.719  3111  3111 I gralloc : framebuffer hal alread move to hwcomposer
02-09 09:05:23.725  3111  3111 I gralloc : framebuffer hal alread move to hwcomposer
02-09 09:05:23.727  3111  3111 I gralloc : framebuffer hal alread move to hwcomposer
02-09 09:05:23.735  4102  4102 I droid.deskcloc: The ClassLoaderContext is a special shared library.
02-09 09:05:23.735  3348  4107 I chatty  : uid=1000 system_server expire 7 lines
02-09 09:05:23.749  3111  3111 I gralloc : framebuffer hal alread move to hwcomposer
02-09 09:05:23.803  4102  4102 I AlarmClock: AlarmInitReceiver android.intent.action.LOCKED_BOOT_COMPLETED
02-09 09:05:23.811  4102  4135 I AlarmClock: Fixing alarm instances
02-09 09:05:23.831  4102  4135 V AlarmClock: AlarmInitReceiver finished
02-09 09:05:23.849  4137  4137 I Zygote  : seccomp disabled by setenforce 0
02-09 09:05:23.849  3348  3365 I ActivityManager: Start proc 4137:com.khadas.khadascontrol/1000 for broadcast com.khadas.khadascontrol/.KhadasControlInitReceiver
02-09 09:05:23.894  4137  4137 D KhadasControlInitReceiver: Factory fullpath=/storage/emulated/0/bootup.bmp
02-09 09:05:23.896  3348  3364 W Looper  : Slow dispatch took 165ms android.ui h=android.view.Choreographer$FrameHandler c=android.view.Choreographer$FrameDisplayEventReceiver@9c9330c m=0
02-09 09:05:23.899  3127  3875 I chatty  : uid=1000(system) Binder:3127_5 expire 4 lines
02-09 09:05:23.899  3111  3111 I gralloc : framebuffer hal alread move to hwcomposer
02-09 09:05:23.912  4155  4155 I Zygote  : seccomp disabled by setenforce 0
02-09 09:05:23.916  3348  3365 I ActivityManager: Start proc 4155:android.process.media/u0a2 for broadcast com.android.providers.downloads/.DownloadReceiver
02-09 09:05:23.948  3113  3977 I chatty  : uid=1000(system) HwBinder:3113_3 expire 11 lines
02-09 09:05:24.048  4155  4155 D MediaScannerReceiver: action: android.intent.action.MEDIA_MOUNTED path: /storage/emulated/0
02-09 09:05:24.052  3593  3593 I FastBootComplete: action:android.intent.action.BOOT_COMPLETED
02-09 09:05:24.053  3593  3593 W ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1531 android.content.ContextWrapper.startService:664 android.content.ContextWrapper.startService:664 com.droidlogic.FastBootComplete.onReceive:27 android.app.ActivityThread.handleReceiver:3379 
02-09 09:05:24.055  3593  3593 D BLE_Service: Service onCreate
02-09 09:05:24.058  3925  3925 I SubTitleServiceBroadcastReceiver: [onReceive]action:android.intent.action.BOOT_COMPLETED, subtitleService:null
02-09 09:05:24.059  3925  3925 I SubtitleMiddleClientManager: SubtitleMiddleClientManager....
02-09 09:05:24.062  3925  3925 I android_os_HwBinder: HwBinder: Starting thread pool for default::vendor.amlogic.hardware.subtitleserver@1.0::ISubtitleServer
02-09 09:05:24.066  3094  3130 I SubtitleServerHal: [setCallback]
02-09 09:05:24.066  3094  3130 I SubtitleServerHal: setCallback cookie:0, client size:1
02-09 09:05:24.066  3925  3925 I SubtitleMiddleClientManager: connect to subtitleserver HIDL service success
02-09 09:05:24.075  3925  3925 I tvsubtitle_tv: load tvsubtitle_tv ok
02-09 09:05:24.080  3127  3127 I chatty  : uid=1000(system) /system/bin/surfaceflinger expire 10 lines
02-09 09:05:24.089  3348  3365 I ActivityManager: Start proc 4180:com.wesion.remotesettings/u0a38 for broadcast com.wesion.remotesettings/.RemoteSettingReceiver
02-09 09:05:24.089  4180  4180 I Zygote  : seccomp disabled by setenforce 0
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: keyInfo [{
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 20,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "POWER",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "POWER",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 116
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 3,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "UP",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "UP",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 103
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 2,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "DOWN",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "DOWN",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 108
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 14,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "LEFT",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "LEFT",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 105
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 26,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "RIGHT",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "RIGHT",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 106
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 7,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "OK",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "OK",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 232
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 1,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "BACK",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "BACK",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 158
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 91,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "MOUSE",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "MOUSE",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 63
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 13,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "MENU",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "MENU",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 139
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: },  {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 88,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "Volume Down",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "Volume Down",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 114
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }, {
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 11,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "Volume UP",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "Volume UP",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 115
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: },{
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"irCode": 72,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"isSelect": true,
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"key": "HOME",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"name": "HOME",
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: 	"scanCode": 102
02-09 09:05:24.136  4180  4180 D IRSettingReceiver: }]
02-09 09:05:24.157  3593  3593 I BLE_Service: mConnRunnable, looking on bonded devices in order to find connection target...
02-09 09:05:24.157  3593  3593 I BLE_Service: connectToBondedDevices><
02-09 09:05:24.158  3593  3593 I BLE_Service: bondedDevices size:0
02-09 09:05:24.475  4155  4177 V MediaProvider: pruneThumbnails 
02-09 09:05:24.478  4155  4177 V MediaProvider: /pruneDeadThumbnailFiles... 
02-09 09:05:28.791  4102  4128 I droid.deskcloc: Waiting for a blocking GC ProfileSaver
02-09 09:05:28.803  4102  4128 I droid.deskcloc: WaitForGcToComplete blocked ProfileSaver on AddRemoveAppImageSpace for 11.905ms
02-09 09:05:28.927  4137  4154 I s.khadascontro: Waiting for a blocking GC ProfileSaver
02-09 09:05:28.943  4137  4154 I s.khadascontro: WaitForGcToComplete blocked ProfileSaver on AddRemoveAppImageSpace for 15.489ms
02-09 09:05:28.990  4155  4170 I d.process.medi: Waiting for a blocking GC ProfileSaver
02-09 09:05:29.001  4155  4170 I d.process.medi: WaitForGcToComplete blocked ProfileSaver on AddRemoveAppImageSpace for 10.209ms
02-09 09:05:29.163  4180  4195 I .remotesetting: Waiting for a blocking GC ProfileSaver
02-09 09:05:29.184  4180  4195 I .remotesetting: WaitForGcToComplete blocked ProfileSaver on AddRemoveAppImageSpace for 20.557ms
02-09 09:05:29.208     1     1 I init    : type=1400 audit(0.0:188): avc: denied { getpgid } for scontext=u:r:init:s0 tcontext=u:object_r:dhclient_exec:s0 tclass=process permissive=1
02-09 09:05:29.208     1     1 I init    : type=1400 audit(0.0:189): avc: denied { sigkill } for scontext=u:r:init:s0 tcontext=u:object_r:dhclient_exec:s0 tclass=process permissive=1
02-09 09:05:29.216     1     1 I init    : type=1400 audit(0.0:190): avc: denied { sigchld } for scontext=u:object_r:dhclient_exec:s0 tcontext=u:r:init:s0 tclass=process permissive=1

Thanks for your support !

[VulcainMan]

This part may also be useful :

02-09 09:06:24.137  3348  3363 W BroadcastQueue: Timeout of broadcast BroadcastRecord{b09970e u0 android.intent.action.BOOT_COMPLETED} - receiver=android.app.LoadedApk$ReceiverDispatcher$InnerReceiver@8889beb, started 60000ms ago
02-09 09:06:24.137  3348  3363 W BroadcastQueue: Receiver during timeout of BroadcastRecord{b09970e u0 android.intent.action.BOOT_COMPLETED} : BroadcastFilter{26567e1 u-1 ReceiverList{46e2d48 3348 system/1000/u-1 local:8889beb}}
02-09 09:06:24.608  3348  3513 I android_os_HwBinder: HwBinder: Starting thread pool for default::android.hidl.manager@1.0::IServiceManager
02-09 09:06:24.644  3348  3513 I system_server: libdebuggerd_client: started dumping process 3348
02-09 09:06:24.645  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3348 and type kDebuggerdJavaBacktrace
02-09 09:06:24.645  3348  3353 I system_server: Thread[2,tid=3353,WaitingInMainSignalCatcherLoop,Thread*=0x733100f400,peer=0x12c40000,"Signal Catcher"]: reacting to signal 3
02-09 09:06:24.646  3348  3353 I system_server: 
02-09 09:06:25.850  3214  3214 I /system/bin/tombstoned: received crash request for pid 3348
02-09 09:06:25.850  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3348 and type kDebuggerdJavaBacktrace
02-09 09:06:25.850  3348  3353 I system_server: Wrote stack traces to '[tombstoned]'
02-09 09:06:25.853  3348  3513 I system_server: libdebuggerd_client: done dumping process 3348
02-09 09:06:25.853  3348  3513 I system_server: libdebuggerd_client: started dumping process 3612
02-09 09:06:25.854  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3612 and type kDebuggerdJavaBacktrace
02-09 09:06:25.854  3612  3632 I m.android.phon: Thread[3,tid=3632,WaitingInMainSignalCatcherLoop,Thread*=0x7331139000,peer=0x13080020,"Signal Catcher"]: reacting to signal 3
02-09 09:06:25.854  3612  3632 I m.android.phon: 
02-09 09:06:25.911  3214  3214 I /system/bin/tombstoned: received crash request for pid 3612
02-09 09:06:25.911  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3612 and type kDebuggerdJavaBacktrace
02-09 09:06:25.911  3612  3632 I m.android.phon: Wrote stack traces to '[tombstoned]'
02-09 09:06:25.912  3348  3513 I system_server: libdebuggerd_client: done dumping process 3612
02-09 09:06:25.912  3348  3513 I system_server: libdebuggerd_client: started dumping process 3120
02-09 09:06:25.913  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3120 and type kDebuggerdNativeBacktrace
02-09 09:06:25.913  3120  3120 I libc    : Requested dump for tid 3120 (sensors@1.0-ser)
02-09 09:06:25.933  4302  4302 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:25.933  3214  3214 I /system/bin/tombstoned: received crash request for pid 3120
02-09 09:06:25.934  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3120 and type kDebuggerdNativeBacktrace
02-09 09:06:25.934  4302  4302 I crash_dump64: performing dump of process 3120 (target tid = 3120)
02-09 09:06:25.941  3348  3513 I system_server: libdebuggerd_client: done dumping process 3120
02-09 09:06:25.942  3348  3513 I system_server: libdebuggerd_client: started dumping process 3205
02-09 09:06:25.942  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3205 and type kDebuggerdNativeBacktrace
02-09 09:06:25.943  3214  3214 I /system/bin/tombstoned: received crash request for pid 3205
02-09 09:06:25.943  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3205 and type kDebuggerdNativeBacktrace
02-09 09:06:26.016  3348  3513 I system_server: libdebuggerd_client: done dumping process 3205
02-09 09:06:26.016  3348  3513 I system_server: libdebuggerd_client: started dumping process 3097
02-09 09:06:26.016  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3097 and type kDebuggerdNativeBacktrace
02-09 09:06:26.017  3097  3097 I libc    : Requested dump for tid 3097 (audio@2.0-servi)
02-09 09:06:26.046  4308  4308 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.046  3214  3214 I /system/bin/tombstoned: received crash request for pid 3097
02-09 09:06:26.047  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3097 and type kDebuggerdNativeBacktrace
02-09 09:06:26.047  4308  4308 I crash_dump32: performing dump of process 3097 (target tid = 3097)
02-09 09:06:26.081  3348  3513 I system_server: libdebuggerd_client: done dumping process 3097
02-09 09:06:26.081  3348  3513 I system_server: libdebuggerd_client: started dumping process 3113
02-09 09:06:26.081  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3113 and type kDebuggerdNativeBacktrace
02-09 09:06:26.110  4314  4314 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.110  3214  3214 I /system/bin/tombstoned: received crash request for pid 3113
02-09 09:06:26.110  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3113 and type kDebuggerdNativeBacktrace
02-09 09:06:26.110  4314  4314 I crash_dump64: performing dump of process 3113 (target tid = 3113)
02-09 09:06:26.126  3348  3513 I system_server: libdebuggerd_client: done dumping process 3113
02-09 09:06:26.126  3348  3513 I system_server: libdebuggerd_client: started dumping process 3098
02-09 09:06:26.126  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3098 and type kDebuggerdNativeBacktrace
02-09 09:06:26.127  3098  3098 I libc    : Requested dump for tid 3098 (bluetooth@1.0-s)
02-09 09:06:26.148  4320  4320 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.148  3214  3214 I /system/bin/tombstoned: received crash request for pid 3098
02-09 09:06:26.148  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3098 and type kDebuggerdNativeBacktrace
02-09 09:06:26.148  4320  4320 I crash_dump64: performing dump of process 3098 (target tid = 3098)
02-09 09:06:26.157  3348  3513 I system_server: libdebuggerd_client: done dumping process 3098
02-09 09:06:26.157  3348  3513 I system_server: libdebuggerd_client: started dumping process 3100
02-09 09:06:26.157  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3100 and type kDebuggerdNativeBacktrace
02-09 09:06:26.158  3100  3100 I libc    : Requested dump for tid 3100 (provider@2.4-se)
02-09 09:06:26.187  4325  4325 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.187  3214  3214 I /system/bin/tombstoned: received crash request for pid 3100
02-09 09:06:26.187  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3100 and type kDebuggerdNativeBacktrace
02-09 09:06:26.188  4325  4325 I crash_dump64: performing dump of process 3100 (target tid = 3100)
02-09 09:06:26.200  3348  3513 I system_server: libdebuggerd_client: done dumping process 3100
02-09 09:06:26.200  3348  3513 I system_server: libdebuggerd_client: started dumping process 3028
02-09 09:06:26.200  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3028 and type kDebuggerdNativeBacktrace
02-09 09:06:26.220  4330  4330 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.220  3214  3214 I /system/bin/tombstoned: received crash request for pid 3028
02-09 09:06:26.220  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3028 and type kDebuggerdNativeBacktrace
02-09 09:06:26.220  4330  4330 I crash_dump64: performing dump of process 3028 (target tid = 3028)
02-09 09:06:26.223  3348  3513 I system_server: libdebuggerd_client: done dumping process 3028
02-09 09:06:26.224  3348  3513 I system_server: libdebuggerd_client: started dumping process 3092
02-09 09:06:26.224  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3092 and type kDebuggerdNativeBacktrace
02-09 09:06:26.224  3092  3092 I libc    : Requested dump for tid 3092 (hdmicecd)
02-09 09:06:26.272  4335  4335 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.273  3214  3214 I /system/bin/tombstoned: received crash request for pid 3092
02-09 09:06:26.273  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3092 and type kDebuggerdNativeBacktrace
02-09 09:06:26.273  4335  4335 I crash_dump64: performing dump of process 3092 (target tid = 3092)
02-09 09:06:26.282  3348  3513 I system_server: libdebuggerd_client: done dumping process 3092
02-09 09:06:26.283  3348  3513 I system_server: libdebuggerd_client: started dumping process 3095
02-09 09:06:26.283  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3095 and type kDebuggerdNativeBacktrace
02-09 09:06:26.284  3095  3095 I libc    : Requested dump for tid 3095 (systemcontrol)
02-09 09:06:26.308  4340  4340 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.308  3214  3214 I /system/bin/tombstoned: received crash request for pid 3095
02-09 09:06:26.308  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3095 and type kDebuggerdNativeBacktrace
02-09 09:06:26.308  4340  4340 I crash_dump64: performing dump of process 3095 (target tid = 3095)
02-09 09:06:26.322  3348  3513 I system_server: libdebuggerd_client: done dumping process 3095
02-09 09:06:26.322  3348  3513 I system_server: libdebuggerd_client: started dumping process 3125
02-09 09:06:26.323  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3125 and type kDebuggerdNativeBacktrace
02-09 09:06:26.323  3125  3125 I libc    : Requested dump for tid 3125 (audioserver)
02-09 09:06:26.351  4345  4345 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.351  3214  3214 I /system/bin/tombstoned: received crash request for pid 3125
02-09 09:06:26.351  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3125 and type kDebuggerdNativeBacktrace
02-09 09:06:26.352  4345  4345 I crash_dump32: performing dump of process 3125 (target tid = 3125)
02-09 09:06:26.387  3348  3513 I system_server: libdebuggerd_client: done dumping process 3125
02-09 09:06:26.387  3348  3513 I system_server: libdebuggerd_client: started dumping process 3127
02-09 09:06:26.388  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3127 and type kDebuggerdNativeBacktrace
02-09 09:06:26.422  4350  4350 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.423  3214  3214 I /system/bin/tombstoned: received crash request for pid 3127
02-09 09:06:26.423  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3127 and type kDebuggerdNativeBacktrace
02-09 09:06:26.423  4350  4350 I crash_dump64: performing dump of process 3127 (target tid = 3127)
02-09 09:06:26.584  3348  3513 I system_server: libdebuggerd_client: done dumping process 3127
02-09 09:06:26.584  3348  3513 I system_server: libdebuggerd_client: started dumping process 3187
02-09 09:06:26.584  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3187 and type kDebuggerdNativeBacktrace
02-09 09:06:26.585  3187  3187 I libc    : Requested dump for tid 3187 (cameraserver)
02-09 09:06:26.611  4355  4355 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.611  3214  3214 I /system/bin/tombstoned: received crash request for pid 3187
02-09 09:06:26.611  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3187 and type kDebuggerdNativeBacktrace
02-09 09:06:26.612  4355  4355 I crash_dump32: performing dump of process 3187 (target tid = 3187)
02-09 09:06:26.631  3348  3513 I system_server: libdebuggerd_client: done dumping process 3187
02-09 09:06:26.632  3348  3513 I system_server: libdebuggerd_client: started dumping process 3188
02-09 09:06:26.632  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3188 and type kDebuggerdNativeBacktrace
02-09 09:06:26.633  3188  3188 I libc    : Requested dump for tid 3188 (drmserver)
02-09 09:06:26.657  4360  4360 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.657  3214  3214 I /system/bin/tombstoned: received crash request for pid 3188
02-09 09:06:26.657  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3188 and type kDebuggerdNativeBacktrace
02-09 09:06:26.658  4360  4360 I crash_dump32: performing dump of process 3188 (target tid = 3188)
02-09 09:06:26.674  3348  3513 I system_server: libdebuggerd_client: done dumping process 3188
02-09 09:06:26.675  3348  3513 I system_server: libdebuggerd_client: started dumping process 3197
02-09 09:06:26.675  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3197 and type kDebuggerdNativeBacktrace
02-09 09:06:26.676  3197  3197 I libc    : Requested dump for tid 3197 (mediadrmserver)
02-09 09:06:26.698  4365  4365 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.698  3214  3214 I /system/bin/tombstoned: received crash request for pid 3197
02-09 09:06:26.698  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3197 and type kDebuggerdNativeBacktrace
02-09 09:06:26.698  4365  4365 I crash_dump32: performing dump of process 3197 (target tid = 3197)
02-09 09:06:26.713  3348  3513 I system_server: libdebuggerd_client: done dumping process 3197
02-09 09:06:26.713  3348  3513 I system_server: libdebuggerd_client: started dumping process 3198
02-09 09:06:26.713  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3198 and type kDebuggerdNativeBacktrace
02-09 09:06:26.714  3214  3214 I /system/bin/tombstoned: received crash request for pid 3198
02-09 09:06:26.714  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3198 and type kDebuggerdNativeBacktrace
02-09 09:06:26.757  3348  3513 I system_server: libdebuggerd_client: done dumping process 3198
02-09 09:06:26.757  3348  3513 I system_server: libdebuggerd_client: started dumping process 3199
02-09 09:06:26.758  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3199 and type kDebuggerdNativeBacktrace
02-09 09:06:26.758  3199  3199 I libc    : Requested dump for tid 3199 (mediametrics)
02-09 09:06:26.781  4370  4370 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.782  3214  3214 I /system/bin/tombstoned: received crash request for pid 3199
02-09 09:06:26.782  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3199 and type kDebuggerdNativeBacktrace
02-09 09:06:26.782  4370  4370 I crash_dump64: performing dump of process 3199 (target tid = 3199)
02-09 09:06:26.791  3348  3513 I system_server: libdebuggerd_client: done dumping process 3199
02-09 09:06:26.791  3348  3513 I system_server: libdebuggerd_client: started dumping process 3201
02-09 09:06:26.792  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3201 and type kDebuggerdNativeBacktrace
02-09 09:06:26.792  3201  3201 I libc    : Requested dump for tid 3201 (mediaserver)
02-09 09:06:26.819  4375  4375 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.820  3214  3214 I /system/bin/tombstoned: received crash request for pid 3201
02-09 09:06:26.820  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3201 and type kDebuggerdNativeBacktrace
02-09 09:06:26.820  4375  4375 I crash_dump32: performing dump of process 3201 (target tid = 3201)
02-09 09:06:26.839  3348  3513 I system_server: libdebuggerd_client: done dumping process 3201
02-09 09:06:26.839  3348  3513 I system_server: libdebuggerd_client: started dumping process 3205
02-09 09:06:26.840  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3205 and type kDebuggerdNativeBacktrace
02-09 09:06:26.841  3214  3214 I /system/bin/tombstoned: received crash request for pid 3205
02-09 09:06:26.841  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3205 and type kDebuggerdNativeBacktrace
02-09 09:06:26.913  3348  3513 I system_server: libdebuggerd_client: done dumping process 3205
02-09 09:06:26.913  3348  3513 I system_server: libdebuggerd_client: started dumping process 3458
02-09 09:06:26.913  3214  3214 I /system/bin/tombstoned: registered intercept for pid 3458 and type kDebuggerdNativeBacktrace
02-09 09:06:26.914  3458  3458 I libc    : Requested dump for tid 3458 (droid.bluetooth)
02-09 09:06:26.968  4380  4380 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdNativeBacktrace
02-09 09:06:26.968  3214  3214 I /system/bin/tombstoned: received crash request for pid 3458
02-09 09:06:26.969  3214  3214 I /system/bin/tombstoned: found intercept fd 512 for pid 3458 and type kDebuggerdNativeBacktrace
02-09 09:06:26.969  4380  4380 I crash_dump64: performing dump of process 3458 (target tid = 3458)
02-09 09:06:27.176  3348  3513 I system_server: libdebuggerd_client: done dumping process 3458
02-09 09:06:29.193  3348  4018 D DhcpClient: Unicasting DHCPREQUEST ciaddr=10.84.85.203 request=0.0.0.0 serverid=null to /10.84.85.1:67
02-09 09:06:29.205  3348  4022 D DhcpClient: Received packet: c8:63:14:70:ca:65 ACK: your new IP /10.84.85.203, netmask /255.255.255.0, gateways [/10.84.85.1] DNS servers: /8.8.8.8 /9.9.9.9 , lease time 60
02-09 09:06:29.206  3348  4018 D DhcpClient: Renewed lease: IP address 10.84.85.203/24 Gateway 10.84.85.1  DNS servers: [ 8.8.8.8 9.9.9.9 ] Domains  DHCP server /10.84.85.1 Vendor info null lease 60 seconds
02-09 09:06:29.210  3348  4018 D DhcpClient: Scheduling renewal in 29s
02-09 09:06:29.210  3348  4018 D DhcpClient: Scheduling rebind in 52s
02-09 09:06:29.210  3348  4018 D DhcpClient: Scheduling expiry in 59s
02-09 09:06:29.778  3348  3513 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in handler on main thread (main)
02-09 09:06:29.785  3348  3513 W Watchdog: main annotated stack trace:
02-09 09:06:29.785  3348  3513 W Watchdog:     at java.lang.Object.wait(Native Method)
02-09 09:06:29.786  3348  3513 W Watchdog:     at java.lang.Thread.parkFor$(Thread.java:2137)
02-09 09:06:29.787  3348  3513 W Watchdog:     - locked <0x09fc7054> (a java.lang.Object)
02-09 09:06:29.787  3348  3513 W Watchdog:     at sun.misc.Unsafe.park(Unsafe.java:358)
02-09 09:06:29.787  3348  3513 W Watchdog:     at java.util.concurrent.locks.LockSupport.park(LockSupport.java:190)
02-09 09:06:29.788  3348  3513 W Watchdog:     at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:450)
02-09 09:06:29.788  3348  3513 W Watchdog:     at java.util.concurrent.FutureTask.get(FutureTask.java:192)
02-09 09:06:29.789  3348  3513 W Watchdog:     at com.android.server.location.GnssGeofenceProvider.runOnHandlerThread(GnssGeofenceProvider.java:75)
02-09 09:06:29.789  3348  3513 W Watchdog:     at com.android.server.location.GnssGeofenceProvider.isHardwareGeofenceSupported(GnssGeofenceProvider.java:84)
02-09 09:06:29.789  3348  3513 W Watchdog:     at android.hardware.location.GeofenceHardwareImpl.updateGpsHardwareAvailability(GeofenceHardwareImpl.java:133)
02-09 09:06:29.790  3348  3513 W Watchdog:     at android.hardware.location.GeofenceHardwareImpl.setGpsHardwareGeofence(GeofenceHardwareImpl.java:170)
02-09 09:06:29.790  3348  3513 W Watchdog:     at android.hardware.location.GeofenceHardwareService$1.setGpsGeofenceHardware(GeofenceHardwareService.java:70)
02-09 09:06:29.791  3348  3513 W Watchdog:     at com.android.server.location.GeofenceProxy.setGpsGeofenceLocked(GeofenceProxy.java:135)
02-09 09:06:29.791  3348  3513 W Watchdog:     at com.android.server.location.GeofenceProxy.access$400(GeofenceProxy.java:38)
02-09 09:06:29.791  3348  3513 W Watchdog:     at com.android.server.location.GeofenceProxy$4.handleMessage(GeofenceProxy.java:172)
02-09 09:06:29.792  3348  3513 W Watchdog:     - locked <0x0fad9bfd> (a java.lang.Object)
02-09 09:06:29.792  3348  3513 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:106)
02-09 09:06:29.792  3348  3513 W Watchdog:     at android.os.Looper.loop(Looper.java:193)
02-09 09:06:29.792  3348  3513 W Watchdog:     at com.android.server.SystemServer.run(SystemServer.java:456)
02-09 09:06:29.793  3348  3513 W Watchdog:     at com.android.server.SystemServer.main(SystemServer.java:296)
02-09 09:06:29.793  3348  3513 W Watchdog:     at java.lang.reflect.Method.invoke(Native Method)
02-09 09:06:29.793  3348  3513 W Watchdog:     at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
02-09 09:06:29.793  3348  3513 W Watchdog:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:838)
02-09 09:06:29.794  3348  3513 W Watchdog: *** GOODBYE!
02-09 09:06:29.794  3348  3513 I Process : Sending signal. PID: 3348 SIG: 9

[william.lin]

@VulcainMan ,
Can you try our official version?

/products/vim3l/firmware/android/

It’s better to provide us with a video.

[VulcainMan]

Hi @william.lin ,

Thanks for your reactivity. I’m not really sure we can reproduce it with the Khadas official firmware since we add our applications in AOSP tree that requires several system level permissions to run so we cannot have a pilot strictly equivalent (in term of app running) to the one that is currently running in our lab. Nevertheless, we are waiting for 5 additional K3L units that will arrive in 5-10 days so we’ll give it a try when I receive them.

By the way, after a lot of time on this issue these last days (actually weeks), we suspect that it depends of the screen that is plugged on the device. Indeed, we have 3 units plugged on 3 differents screens :

• A Samsung TV HG43EJ690 4K
• A Viewsonic TD241
• A generic DELL display for PC

And after some time it seems that the only the one on the Samsung TV is facing this issue (maybe something related with the HDMI, screen resolution, refresh rate, CEC ?).

Based on this DMESG output I recorded yersterday, I really suspect something related to CEC :

...


[   67.819395] type=1400 audit(1770656905.373:204): avc: denied { sigkill } for pid=1 comm="init" scontext=u:r:init:s0 tcontext=u:object_r:dhclient_exec:s0 tclass=process permissive=1
[   67.830322] type=1400 audit(1770656920.285:205): avc: denied { getattr } for pid=4137 comm="sh" path="/vendor/bin/toybox_vendor" dev="mmcblk0p16" ino=829 scontext=u:r:shell:s0 tcontext=u:object_r:vendor_toolbox_exec:s0 tclass=file permissive=1
[   67.852836] type=1400 audit(1770656920.285:205): avc: denied { getattr } for pid=4137 comm="sh" path="/vendor/bin/toybox_vendor" dev="mmcblk0p16" ino=829 scontext=u:r:shell:s0 tcontext=u:object_r:vendor_toolbox_exec:s0 tclass=file permissive=1
[   67.873521] type=1400 audit(1770656920.285:206): avc: denied { execute } for pid=4137 comm="sh" name="toybox_vendor" dev="mmcblk0p16" ino=829 scontext=u:r:shell:s0 tcontext=u:object_r:vendor_toolbox_exec:s0 tclass=file permissive=1
[   67.894246] type=1400 audit(1770656920.285:206): avc: denied { execute } for pid=4137 comm="sh" name="toybox_vendor" dev="mmcblk0p16" ino=829 scontext=u:r:shell:s0 tcontext=u:object_r:vendor_toolbox_exec:s0 tclass=file permissive=1
[   67.915081] type=1400 audit(1770656920.285:207): avc: denied { getattr } for pid=4137 comm="sh" path="/vendor/xbin/busybox" dev="mmcblk0p16" ino=402 scontext=u:r:shell:s0 tcontext=u:object_r:vendor_file:s0 tclass=file permissive=1
[   67.936255] type=1400 audit(1770656920.285:207): avc: denied { getattr } for pid=4137 comm="sh" path="/vendor/xbin/busybox" dev="mmcblk0p16" ino=402 scontext=u:r:shell:s0 tcontext=u:object_r:vendor_file:s0 tclass=file permissive=1
[   67.955853] type=1400 audit(1770656920.285:208): avc: denied { execute } for pid=4137 comm="sh" name="busybox" dev="mmcblk0p16" ino=402 scontext=u:r:shell:s0 tcontext=u:object_r:vendor_file:s0 tclass=file permissive=1
[   68.751462] DI: DI: tasklet schedule cost 52ms.
[   71.246847] DI: DI: tasklet schedule cost 52ms.
[   71.420288] DI: DI: tasklet schedule cost 48ms.
[   71.952223] DI: DI: tasklet schedule cost 40ms.
[   73.882895] DI: DI: tasklet schedule cost 52ms.
[   75.497291] DI: DI: tasklet schedule cost 52ms.
[   76.377171] DI: DI: tasklet schedule cost 52ms.
[   77.999182] DI: DI: tasklet schedule cost 40ms.
[   78.162642] DI: DI: tasklet schedule cost 32ms.
[   78.203492] DI: DI: tasklet schedule cost 40ms.
[   80.754411] DI: DI: tasklet schedule cost 40ms.
[   81.297290] DI: DI: tasklet schedule cost 52ms.
[   82.661165] DI: DI: tasklet schedule cost 32ms.
[   82.918092] DI: DI: tasklet schedule cost 52ms.
[   85.493388] DI: DI: tasklet schedule cost 32ms.
[   85.625766] DI: DI: tasklet schedule cost 52ms.
[   86.413560] DI: DI: tasklet schedule cost 52ms.
[   87.118292] DI: DI: tasklet schedule cost 32ms.
[   87.414385] DI: DI: tasklet schedule cost 52ms.
[   87.793162] DI: DI: tasklet schedule cost 44ms.
[   89.009297] DI: DI: tasklet schedule cost 52ms.
[   89.796232] DI: DI: tasklet schedule cost 48ms.
[   90.255200] DI: DI: tasklet schedule cost 52ms.
[   90.623062] DI: DI: tasklet schedule cost 40ms.
[   94.069748] DI: DI: tasklet schedule cost 32ms.
[   95.459717] DI: DI: tasklet schedule cost 52ms.
[   95.541444] DI: DI: tasklet schedule cost 52ms.
[   96.654763] DI: DI: tasklet schedule cost 32ms.
[   98.463004] DI: DI: tasklet schedule cost 52ms.
[   98.994683] DI: DI: tasklet schedule cost 32ms.
[   99.127115] DI: DI: tasklet schedule cost 52ms.
[   99.219421] DI: DI: tasklet schedule cost 60ms.
[  101.275162] DI: DI: tasklet schedule cost 32ms.
[  101.611933] DI: DI: tasklet schedule cost 28ms.
[  102.694635] DI: DI: tasklet schedule cost 32ms.
[  104.789178] DI: DI: tasklet schedule cost 52ms.
[  106.259712] DI: DI: tasklet schedule cost 52ms.
[  106.749917] DI: DI: tasklet schedule cost 32ms.
[  106.832504] DI: DI: tasklet schedule cost 32ms.
[  107.334419] DI: DI: tasklet schedule cost 52ms.
[  110.210749] DI: DI: tasklet schedule cost 60ms.
[  113.961160] DI: DI: tasklet schedule cost 52ms.
[  116.158914] DI: DI: tasklet schedule cost 32ms.
[  116.873414] DI: DI: tasklet schedule cost 52ms.
[  117.051984] sysrq: SysRq : Show Blocked State
[  117.052039] task                        PC stack   pid father
[  117.057166] vdec-core       D    0  2975      2 0x00000000
[  117.062644] Call trace:
[  117.065258] [ffffff80201f7be0+   0][<ffffff80090861e8>] __switch_to+0xa0/0xc8
[  117.072596] [ffffff80201f7c00+ 112][<ffffff8009c79e68>] __schedule+0x250/0x7b0
[  117.079966] [ffffff80201f7c70+ 128][<ffffff8009c7a404>] schedule+0x3c/0xa0
[  117.087136] [ffffff80201f7c90+ 144][<ffffff8009c7de48>] schedule_hrtimeout_range_clock+0x90/0x118
[  117.095982] [ffffff80201f7d20+  48][<ffffff8009c7df08>] schedule_hrtimeout_range+0x38/0x48
[  117.104358] [ffffff80201f7e08+   0][<ffffff8001d63c10>] decoder_common_exit+0x2ca8/0x1098 [decoder_common]
[  117.114142] hdmi_cec_loop   D    0  3265      1 0x00000000
[  117.119729] Call trace:
[  117.122347] [ffffff802045bb60+  32][<ffffff80090861e8>] __switch_to+0xa0/0xc8
[  117.129615] [ffffff802045bb80+ 112][<ffffff8009c79e68>] __schedule+0x250/0x7b0
[  117.137022] [ffffff802045bbf0+  32][<ffffff8009c7a404>] schedule+0x3c/0xa0
[  117.144057] [ffffff802045bc10+ 176][<ffffff8009c7d858>] schedule_timeout+0x1a0/0x428
[  117.152082] [ffffff802045bcc0+ 144][<ffffff8009c7b0e4>] wait_for_common+0xd4/0x170
[  117.159653] [ffffff802045bd50+  32][<ffffff8009c7b1e4>] wait_for_completion_timeout+0x2c/0x38
[  117.168318] [ffffff802045bd70+  64][<ffffff80099a3a4c>] hdmitx_cec_read+0x114/0x1e0
[  117.176111] [ffffff802045bdb0+ 144][<ffffff8009214ba8>] __vfs_read+0x48/0x120
[  117.183387] [ffffff802045be40+  64][<ffffff8009215b3c>] vfs_read+0x94/0x150
[  117.190524] [ffffff802045be80+   0][<ffffff80092170f4>] SyS_read+0x54/0xb0
[  117.197495] [0000000000000000+   0][<ffffff80090830c0>] el0_svc_naked+0x34/0x38
[  117.205731] sysrq: SysRq : Show backtrace of all active CPUs
[  117.592229] binder: undelivered TRANSACTION_COMPLETE
[  117.592299] binder: undelivered transaction 90523, process died.
[  117.607142] binder: 3211:3814 transaction failed 29189/-22, size 60-0 line 3121
[  117.634457] VID: VD1 set global output as 0
[  117.634500] VID: VD1 off
[  117.648885] hdmitx: hdmitx_set_hdr10plus_pkt: null vsif
[  117.648941] hdmitx: hdmitx_set_drm_pkt: HDR->SDR, DRM_DB[0]=2
[  117.654887] hdmitx: hdr_work_func: send zero DRM
[  117.673436] [DI] load 0x3e00 pq table len 424 later.
[  117.673507] [DI] remove 0x3e00 table.
[  117.802239] asoc-aml-card auge_sound: tdm playback stop
[  117.802288] spdif_a is set to disable
[  117.811943] init: couldn't write 4529 to /dev/cpuset/camera-daemon/tasks: No such file or directory
[  117.909382] audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3
[  117.909404] aml_dai_tdm_hw_free(), disable mclk for TDM-B
[  117.909473] tdm playback mute: 1, lane_cnt = 8
[  117.911362] audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1
[  117.930322] BT_RADIO going: off
[  117.930353] AML_BT: going OFF
[  118.197347] binder: release 3997:4151 transaction 90764 out, still active
[  118.198673] binder: undelivered TRANSACTION_COMPLETE
[  118.231583] is_reset=1
[  118.233413] PPMGRVPP: info: task: quit
[  118.233540] ppmgr local_init
[  118.235446] DI: di_receiver_event_fun , is_bypass() 1 trick_mode 0 bypass_all 0
[  118.235455] DI: di_receiver_event_fun: unreg
[  118.249197] DI: provider name:(null)
[  118.249276] DI: di_unreg_process unreg start 1.
[  118.249277] di:no w
[  118.249578] use keep buffer keep frame!
[  118.253931] vf_keep_current: keep video successful!
[  118.265376] video_vf_unreg_provider: vd1 used: true, vd2 used: false, keep_ret:1, black_out:0, cur_dispbuf:ffffff800a75cc18
[  118.289586] video first pts = 0
[  118.289612] VD1 AFBC 0x1700.
[  118.290303] pattern detected = 0, pts_enter_pattern_cnt =2, pts_exit_pattern_cnt =1
[  118.311497] DI: di_unreg_process vf unreg cost 60 ms.
[  118.311511] DI: di_unreg_process unreg stop 1.
[  118.311559] DI: di_unreg_process_irq:cma release req time: -182032 ms
[  118.311561] di:retry cnt=0
[  118.311591] DI: no release nr ds mem.
[  118.312658] di_cma_release:release 0 buffer use 0 ms(4294785264~4294785264)
[  118.312660] DI: unreg f
[  118.312673] PPMGRVPP: info: tb cma free addr is 67560000, size is 18000
[  118.312712] vdec_disable_DMC input->target= 0x1
[  118.313638] vdec_release instance ffffff8008e53000, total 1
[  118.313744] the clk_hevc_mux    clock off, ref cnt: 0
[  118.313748] the clk_hevcb_mux   clock off, ref cnt: 0
[  118.313756] the vdec            clock off, ref cnt: 0
[  118.313760] the parser_top      clock off, ref cnt: 0
[  118.313763] the demux           clock off, ref cnt: 0
[  118.313863] the demux           clock on, ref cnt: 1
[  118.313866] the parser_top      clock on, ref cnt: 1
[  118.313869] the vdec            clock on, ref cnt: 1
[  118.313887] the clk_hevc_mux    clock on, ref cnt: 1
[  118.313889] the clk_hevcb_mux   clock on, ref cnt: 1
[  118.313915] hevc mux clock is 499999992 Hz
[  118.313929] hevc back mux clock is 499999992 Hz
[  118.314001] vdec_create instance ffffff800bc11000, total 1
[  118.314035] no drmmode
[  118.314060] is_reset=1
[  118.314068] The fw has been loaded.
[  118.314073] vdec_init, dev_name:ammvdec_h265, vdec_type=VDEC_TYPE_FRAME_BLOCK
[  118.314454] [0]pdata->config=hevc_buf_width:3840;hevc_buf_height:2160;hevc_buf_margin:7;hevc_double_write_mode:3;save_buffer_mode:0;
[  118.314478] decoder_bmmu_box_alloc_box, tvp_flags = 0
[  118.320111] [0]dynamic_buf_num_margin=7
[  118.320114] [0]double_write_mode=3
[  118.320121] [0]h265:pts_unstable=0
[  118.320124] [0]h265: ver (201602101,0) decinfo: 0x0 rate=3600
[  118.341494] [LOCAL], the fw (hevc_mmu) will be loaded.
[  118.341544] hevc mux clock is 799999987 Hz
[  118.341558] hevc back mux clock is 799999987 Hz
[  118.341562] hevc video changed to 3840 x 2160 60 fps clk->800MHZ
[  118.341605] vfm map vdec-map-0 created
[  118.341627] ppmgr local_init
[  118.341652] di_receiver_event_fun: vframe provider reg ppmgr
[  118.381724] DI: reg f
[  118.387811] ppmgr local_init
[  118.393265] vdec_init, vf_provider_name = vdec.h265.00
[  118.393651] create_gdc_work_queue: GDC is not supported for this chip
[  118.397461] vdec->port_flag=0x102, port_flag=0x10b
[  118.400059] is_reset=0
[  118.416423] PPMGRVPP: info: task: quit
[  118.416486] ppmgr local_init
[  118.417842] DI: di_receiver_event_fun , is_bypass() 1 trick_mode 0 bypass_all 0
[  118.417852] DI: di_receiver_event_fun: unreg
[  118.420980] binder: 3211:3814 transaction failed 29189/-22, size 60-0 line 3121
[  118.430547] DI: provider name:(null)
[  118.433763] DI: di_unreg_process unreg start 1.
[  118.433778] use keep buffer keep frame!
[  118.437217] di:no w
[  118.439645] vf_keep_current: keep video successful!
[  118.444691] video_vf_unreg_provider: vd1 used: true, vd2 used: false, keep_ret:1, black_out:0, cur_dispbuf:ffffff800a75cc18
[  118.456168] VD1 AFBC 0x1700.
[  118.459016] DI: di_unreg_process vf unreg cost 24 ms.
[  118.459026] DI: di_unreg_process unreg stop 1.
[  118.459069] DI: di_unreg_process_irq:cma release req time: -181884 ms
[  118.459072] di:retry cnt=0
[  118.459413] DI: unreg f
[  118.459439] vdec_disable_DMC input->target= 0x1
[  118.459948] vdec_release instance ffffff800bc11000, total 1
[  118.460044] the clk_hevc_mux    clock off, ref cnt: 0
[  118.460048] the clk_hevcb_mux   clock off, ref cnt: 0
[  118.460055] the vdec            clock off, ref cnt: 0
[  118.460059] the parser_top      clock off, ref cnt: 0
[  118.460063] the demux           clock off, ref cnt: 0
[  118.464465] DI: no release nr ds mem.
[  118.468546] di_cma_release:release 0 buffer use 4 ms(4294785416~4294785420)
[  118.534176] set video_inuse val:0
[  118.596744] aml_spdif_open
[  118.597702] audio_ddr_mngr: toddrs[0] registered by device ff660000.audiobus:spdif@0
[  118.598022] aml_spdif_close
[  118.598207] audio_ddr_mngr: toddrs[0] released by device ff660000.audiobus:spdif@0
[  118.598580] aml_tdm_open
[  118.599918] audio_ddr_mngr: toddrs[0] registered by device ff660000.audiobus:tdm@1
[  118.601283] tdm capture mute: 1
[  118.601894] audio_ddr_mngr: toddrs[0] released by device ff660000.audiobus:tdm@1
[  118.602242] aml_tdm_open
[  118.602452] audio_ddr_mngr: toddrs[0] registered by device ff660000.audiobus:tdm@2
[  118.602718] tdm capture mute: 1
[  118.602786] audio_ddr_mngr: toddrs[0] released by device ff660000.audiobus:tdm@2
[  118.603161] earc_dai_startup
[  118.605509] asoc debug: earc_open
[  118.609175] audio_ddr_mngr: toddrs[0] registered by device ff663800.earc
[  118.609500] earc_dai_shutdown
[  118.611952] asoc debug: earc_close
[  118.615679] audio_ddr_mngr: toddrs[0] released by device ff663800.earc
[  118.616265] aml_tdm_open
[  118.621368] type=1400 audit(1770656920.285:208): avc: denied { execute } for pid=4137 comm="sh" name="busybox" dev="mmcblk0p16" ino=402 scontext=u:r:shell:s0 tcontext=u:object_r:vendor_file:s0 tclass=file permissive=1
[  118.621395] type=1400 audit(1770656971.085:209): avc: denied { create } for pid=4533 comm="HwBinder:4533_1" scontext=u:r:hal_audio_default:s0 tcontext=u:r:hal_audio_default:s0 tclass=netlink_kobject_uevent_socket permissive=1
[  118.621528] type=1400 audit(1770656971.085:209): avc: denied { create } for pid=4533 comm="HwBinder:4533_1" scontext=u:r:hal_audio_default:s0 tcontext=u:r:hal_audio_default:s0 tclass=netlink_kobject_uevent_socket permissive=1
[  118.621544] type=1400 audit(1770656971.085:210): avc: denied { setopt } for pid=4533 comm="HwBinder:4533_1" scontext=u:r:hal_audio_default:s0 tcontext=u:r:hal_audio_default:s0 tclass=netlink_kobject_uevent_socket permissive=1
[  118.621632] type=1400 audit(1770656971.085:210): avc: denied { setopt } for pid=4533 comm="HwBinder:4533_1" scontext=u:r:hal_audio_default:s0 tcontext=u:r:hal_audio_default:s0 tclass=netlink_kobject_uevent_socket permissive=1
[  118.621645] type=1400 audit(1770656971.085:211): avc: denied { bind } for pid=4533 comm="HwBinder:4533_1" scontext=u:r:hal_audio_default:s0 tcontext=u:r:hal_audio_default:s0 tclass=netlink_kobject_uevent_socket permissive=1
[  118.739806] audio_ddr_mngr: toddrs[0] registered by device ff660000.audiobus:tdm@0
[  118.740201] tdm capture mute: 1
[  118.740290] audio_ddr_mngr: toddrs[0] released by device ff660000.audiobus:tdm@0
[  118.741450] loopback_dai_startup
[  118.743236] audio_ddr_mngr: toddrs[0] registered by device ff660000.audiobus:loopback@0
[  118.743525] loopback_dai_shutdown
[  118.746498] audio_ddr_mngr: toddrs[0] released by device ff660000.audiobus:loopback@0
[  118.751616] aml_tdm_open
[  118.751644] Not init audio effects
[  118.753890] audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1
[  118.813264] aml_dai_set_tdm_sysclk(), mpll no change, keep clk
[  118.813277] aml_dai_set_tdm_sysclk(), mclk no change, keep clk
[  118.813286] set mclk:12288000, mpll:24576000, get mclk:12287994, mpll:24575987
[  118.813291] asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc05381ec18, id(1), clksel(1)
[  118.813301] aml_dai_set_tdm_fmt(), fmt not change
[  118.813466] dump_pcm_setting(ffffffc05381ec18)
[  118.813469] \x09pcm_mode(1)
[  118.813472] \x09sysclk(12288000)
[  118.813475] \x09sysclk_bclk_ratio(4)
[  118.813478] \x09bclk(3072000)
[  118.813481] \x09bclk_lrclk_ratio(64)
[  118.813484] \x09lrclk(48000)
[  118.813486] \x09tx_mask(0x3)
[  118.813489] \x09rx_mask(0x3)
[  118.813492] \x09slots(2)
[  118.813494] \x09slot_width(32)
[  118.813497] \x09lane_mask_in(0x2)
[  118.813500] \x09lane_mask_out(0x1)
[  118.813503] \x09lane_oe_mask_in(0x0)
[  118.813505] \x09lane_oe_mask_out(0x0)
[  118.813508] \x09lane_lb_mask_in(0x0)
[  118.813519] aml_dai_set_tdm_sysclk(), mpll no change, keep clk
[  118.813527] aml_dai_set_tdm_sysclk(), mclk no change, keep clk
[  118.813532] set mclk:12288000, mpll:24576000, get mclk:12287994, mpll:24575987
[  118.813535] aml_dai_set_clkdiv, div 4, clksel(1)
[  118.813542] aml_dai_set_bclk_ratio, select I2S mode
[  118.813557] aml_dai_tdm_hw_params(), enable mclk for TDM-B
[  118.813608] aml_tdm_prepare(), reset fddr
[  118.813626] spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10
[  118.813632] spdif_info: rate: 48000, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x200, ch1_r:0x200
[  118.813648] audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3
[  118.953202] tdm playback mute: 0, lane_cnt = 8
[  118.953975] asoc-aml-card auge_sound: tdm playback enable
[  118.954027] spdif_a is set to enable
[  119.193173] hdmitx: hdr_work_func: disable DRM
[  119.317995] audit: audit_lost=137 audit_rate_limit=5 audit_backlog_limit=64
[  119.318059] type=1400 audit(1770656971.085:211): avc: denied { bind } for pid=4533 comm="HwBinder:4533_1" scontext=u:r:hal_audio_default:s0 tcontext=u:r:hal_audio_default:s0 tclass=netlink_kobject_uevent_socket permissive=1
[  119.318082] type=1400 audit(1770656971.785:212): avc: denied { read } for pid=4526 comm="main" name="cmdline" dev="proc" ino=4026531977 scontext=u:r:zygote:s0 tcontext=u:object_r:proc_cmdline:s0 tclass=file permissive=1
[  119.318351] type=1400 audit(1770656971.785:212): avc: denied { read } for pid=4526 comm="main" name="cmdline" dev="proc" ino=4026531977 scontext=u:r:zygote:s0 tcontext=u:object_r:proc_cmdline:s0 tclass=file permissive=1
[  119.318364] type=1400 audit(1770656971.785:213): avc: denied { open } for pid=4526 comm="main" path="/proc/cmdline" dev="proc" ino=4026531977 scontext=u:r:zygote:s0 tcontext=u:object_r:proc_cmdline:s0 tclass=file permissive=1
[  119.398731] audit: rate limit exceeded
[  120.217299] early_suspend_state=0
[  120.663400] binder: 3212:3212 transaction failed 29189/0, size 8-0 line 3053
[  120.665078] binder: send failed reply for transaction 90764, target dead
[  121.219563] acc_open
[  121.219602] acc_release
[  121.284711] audit: audit_lost=138 audit_rate_limit=5 audit_backlog_limit=64
[  121.286247] audit: rate limit exceeded
[  121.590940] Process ip granted CAP_NET_ADMIN from Android group net_admin.
[  121.592376] Please update the .rc file to explictly set 'capabilities NET_ADMIN'
[  121.600295] Implicit grants are deprecated and will be removed in the future.
[  121.607651] Process ip granted CAP_NET_ADMIN from Android group net_admin.
[  121.614644] Please update the .rc file to explictly set 'capabilities NET_ADMIN'
[  121.622291] Implicit grants are deprecated and will be removed in the future.
[  121.630075] Process ip granted CAP_NET_ADMIN from Android group net_admin.
[  121.636785] Please update the .rc file to explictly set 'capabilities NET_ADMIN'
[  121.644480] Implicit grants are deprecated and will be removed in the future.
[  123.099220] audit: audit_lost=244 audit_rate_limit=5 audit_backlog_limit=64
[  123.100764] audit: rate limit exceeded
[  123.109645] the demux           clock on, ref cnt: 1
[  123.109656] the parser_top      clock on, ref cnt: 1
[  123.109661] the vdec            clock on, ref cnt: 1
[  123.109683] the clk_hevc_mux    clock on, ref cnt: 1
[  123.109687] the clk_hevcb_mux   clock on, ref cnt: 1

[  123.109718] hevc mux clock is 499999992 Hz
[  123.109733] hevc back mux clock is 499999992 Hz
[  123.109806] vdec_create instance ffffff800beef000, total 1
[  123.109826] vdec_disable_DMC input->target= 0x0
[  123.109831] vdec_release instance ffffff800beef000, total 1
[  123.109855] the clk_hevc_mux    clock off, ref cnt: 0
[  123.109860] the clk_hevcb_mux   clock off, ref cnt: 0
[  123.109866] the vdec            clock off, ref cnt: 0
[  123.109871] the parser_top      clock off, ref cnt: 0
[  123.109875] the demux           clock off, ref cnt: 0
[  123.109967] the demux           clock on, ref cnt: 1
[  123.109973] the parser_top      clock on, ref cnt: 1
[  123.109978] the vdec            clock on, ref cnt: 1
[  123.109994] the clk_vdec_mux    clock on, ref cnt: 1
[  123.110015] vdec mux clock is 799999987 Hz
[  123.110065] vdec_create instance ffffff800bf08000, total 1
[  123.110078] vdec_disable_DMC input->target= 0x0
[  123.110082] vdec_release instance ffffff800bf08000, total 1
[  123.110099] the clk_vdec_mux    clock off, ref cnt: 0
[  123.110104] the vdec            clock off, ref cnt: 0
[  123.110109] the parser_top      clock off, ref cnt: 0
[  123.110113] the demux           clock off, ref cnt: 0
[  123.110210] ionvid: dbg: ionvideo open
[  123.110219] ionvid: dbg: vidioc_close!!!!
[  123.110231] ionvid: dbg: vidioc_close
[  123.162631] the demux           clock on, ref cnt: 1
[  123.162642] the parser_top      clock on, ref cnt: 1
[  123.162647] the vdec            clock on, ref cnt: 1
[  123.162668] the clk_hevc_mux    clock on, ref cnt: 1
[  123.162673] the clk_hevcb_mux   clock on, ref cnt: 1

... (last repeatead a lot of time)

[  123.611652] ionvid: dbg: ionvideo open
[  123.611662] ionvid: dbg: vidioc_close!!!!
[  123.611676] ionvid: dbg: vidioc_close
[  124.607297] BT_RADIO going: on
[  124.607328] AML_BT: going ON
[  124.723390] zram: Cannot change disksize for initialized device
[  124.750650] type=1400 audit(1770656975.225:330): avc: denied { write } for pid=4722 comm="dhclient" lport=546 scontext=u:object_r:dhclient_exec:s0 tcontext=u:object_r:dhclient_exec:s0 tclass=udp_socket permissive=1
[  124.758043] mkswap: Swapspace size: 262140k, UUID=5234869a-b975-4fb7-9f21-778becdd1975
[  124.759447] init: [libfs_mgr]swapon failed for /dev/block/zram0
[  124.779014] type=1400 audit(1770656977.217:338): avc: denied { getattr } for pid=5160 comm="preinstall.sh" path="/data/local/symbol_thirdpart_apks_installed" dev="mmcblk0p20" ino=130583 scontext=u:r:preinstall:s0 tcontext=u:object_r:system_data_file:s0 tclass=file permissive=1
[  124.803466] type=1400 audit(1770656977.217:338): avc: denied { getattr } for pid=5160 comm="preinstall.sh" path="/data/local/symbol_thirdpart_apks_installed" dev="mmcblk0p20" ino=130583 scontext=u:r:preinstall:s0 tcontext=u:object_r:system_data_file:s0 tclass=file permissive=1
[  124.828061] type=1400 audit(1770656977.225:339): avc: denied { sigchld } for pid=1 comm="init" scontext=u:object_r:dhclient_exec:s0 tcontext=u:r:init:s0 tclass=process permissive=1
[  124.830406] selinux: SELinux: Skipping restorecon_recursive(/data/system_ce/0)\x0a
[  124.833040] selinux: SELinux: Skipping restorecon_recursive(/data/misc_ce/0)\x0a
[  124.862014] type=1400 audit(1770656977.225:339): avc: denied { sigchld } for pid=1 comm="init" scontext=u:object_r:dhclient_exec:s0 tcontext=u:r:init:s0 tclass=process permissive=1
[  124.869622] audit: audit_lost=251 audit_rate_limit=5 audit_backlog_limit=64
[  124.869626] audit: rate limit exceeded
[  124.888912] type=1400 audit(1770656977.297:340): avc: denied { setattr } for pid=2382 comm="init" name="env" dev="tmpfs" ino=1060 scontext=u:r:vendor_init:s0 tcontext=u:object_r:env_device:s0 tclass=blk_file permissive=1
[  124.908788] type=1400 audit(1770656977.297:340): avc: denied { setattr } for pid=2382 comm="init" name="env" dev="tmpfs" ino=1060 scontext=u:r:vendor_init:s0 tcontext=u:object_r:env_device:s0 tclass=blk_file permissive=1
[  124.909729] logd: logdr: UID=1000 GID=1007 PID=5166 n tail=0 logMask=80 pid=0 start=0ns timeout=0ns
[  124.928309] type=1400 audit(1770656977.337:341): avc: denied { write } for pid=4722 comm="dhclient" path="socket:[41415]" dev="sockfs" ino=41415 scontext=u:object_r:dhclient_exec:s0 tcontext=u:object_r:dhclient_exec:s0 tclass=unix_dgram_socket permissive=1
[  124.984995] type=1400 audit(1770656977.337:341): avc: denied { write } for pid=4722 comm="dhclient" path="socket:[41415]" dev="sockfs" ino=41415 scontext=u:object_r:dhclient_exec:s0 tcontext=u:object_r:dhclient_exec:s0 tclass=unix_dgram_socket permissive=1
[  125.033755] meson_uart ffd24000.serial: ttyS1 use xtal(24M) 24000000 change 2000000 to 2000000
[  125.037128] meson_uart ffd24000.serial: ttyS1 use xtal(24M) 24000000 change 2000000 to 115200
[  125.050008] meson_uart ffd24000.serial: ttyS1 use xtal(24M) 24000000 change 115200 to 2000000
[  125.329260] asoc-aml-card auge_sound: tdm playback stop
[  125.329317] spdif_a is set to disable
[  125.330693] aml_tdm_prepare(), reset fddr
[  125.330730] spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10
[  125.330737] spdif_info: rate: 48000, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x200, ch1_r:0x200
[  125.330756] audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3
[  125.469388] tdm playback mute: 0, lane_cnt = 8
[  125.471100] asoc-aml-card auge_sound: tdm playback enable
[  125.471141] spdif_a is set to enable
[  125.535193] meson_uart ffd24000.serial: ttyS1 use xtal(24M) 24000000 change 2000000 to 115200
[  125.743758] meson_uart ffd24000.serial: ttyS1 use xtal(24M) 24000000 change 115200 to 2000000
[  129.544783] VID: VD1 off
[  129.544818] disabled amvideo on vd1 for next before free keep buffer!
[  129.548550] VID: VD1 off
[  129.552490] video_inuse return 0,set 1
[  129.555530] the demux           clock on, ref cnt: 1
[  129.555539] the parser_top      clock on, ref cnt: 1
[  129.555544] the vdec            clock on, ref cnt: 1
[  129.555565] the clk_hevc_mux    clock on, ref cnt: 1
[  129.555569] the clk_hevcb_mux   clock on, ref cnt: 1
[  129.555601] hevc mux clock is 499999992 Hz
[  129.555616] hevc back mux clock is 499999992 Hz
[  129.555701] vdec_create instance ffffff8008e53000, total 1
[  129.555738] no drmmode
[  129.555774] is_reset=0
[  129.557617] The fw has been loaded.
[  129.562157] vdec_init, dev_name:ammvdec_h265, vdec_type=VDEC_TYPE_FRAME_BLOCK
[  129.569102] [0]pdata->config=hevc_buf_width:3840;hevc_buf_height:2160;hevc_buf_margin:7;hevc_double_write_mode:3;save_buffer_mode:0;
[  129.569182] decoder_bmmu_box_alloc_box, tvp_flags = 0
[  129.571628] [0]dynamic_buf_num_margin=7
[  129.571634] [0]double_write_mode=3
[  129.571645] [0]h265:pts_unstable=0
[  129.571650] [0]h265: ver (201602101,0) decinfo: 0x0 rate=3600
[  129.573609] [LOCAL], the fw (hevc_mmu) will be loaded.
[  129.573813] hevc mux clock is 799999987 Hz
[  129.573835] hevc back mux clock is 799999987 Hz
[  129.573841] hevc video changed to 3840 x 2160 60 fps clk->800MHZ
[  129.573898] vfm map vdec-map-0 created
[  129.573921] ppmgr local_init
[  129.576825] di_receiver_event_fun: vframe provider reg ppmgr
[  129.594873] DI: reg f
[  129.595044] ppmgr local_init
[  129.595149] vdec_init, vf_provider_name = vdec.h265.00
[  129.595196] create_gdc_work_queue: GDC is not supported for this chip
[  129.606524] vdec->port_flag=0x102, port_flag=0x10b
[  129.616830] [0]vh265 cached=16384  need_size=16384 speed= 48 ms
[  129.617463] [0]Bit depth luma = 10
[  129.617470] [0]Bit depth chroma = 10
[  129.617495] [0]set pic_list_init_flag 1
[  129.656443] [0]init_buf_spec2 3840 1608
[  129.656451] [0]set pic_list_init_flag to 2
[  129.656500] [0]set pic_list_init_flag to 3
[  129.664368] [0]VH265: output first frame
[  129.664544] PPMGRVPP: info: tb first frame type: 0
[  129.667335] PPMGRVPP: info: tb cma memory 67550000, size 18000, item 8
[  129.671290] DI bypass all 960x401-0x509000.
[  129.677459] video first pts = f46b0400
[  129.681775] omx need drop 0
[  129.701628] VID: VD1 set global output as 1
[  129.794328] hdmitx: hdmitx_set_hdr10plus_pkt: flag = 1


...

And especially these kernel crashes have a correlation with the ANRs (one of them for each ANR) :

[  117.051984] sysrq: SysRq : Show Blocked State
[  117.052039] task                        PC stack   pid father
[  117.057166] vdec-core       D    0  2975      2 0x00000000
[  117.062644] Call trace:
[  117.065258] [ffffff80201f7be0+   0][<ffffff80090861e8>] __switch_to+0xa0/0xc8
[  117.072596] [ffffff80201f7c00+ 112][<ffffff8009c79e68>] __schedule+0x250/0x7b0
[  117.079966] [ffffff80201f7c70+ 128][<ffffff8009c7a404>] schedule+0x3c/0xa0
[  117.087136] [ffffff80201f7c90+ 144][<ffffff8009c7de48>] schedule_hrtimeout_range_clock+0x90/0x118
[  117.095982] [ffffff80201f7d20+  48][<ffffff8009c7df08>] schedule_hrtimeout_range+0x38/0x48
[  117.104358] [ffffff80201f7e08+   0][<ffffff8001d63c10>] decoder_common_exit+0x2ca8/0x1098 [decoder_common]
[  117.114142] hdmi_cec_loop   D    0  3265      1 0x00000000
[  117.119729] Call trace:
[  117.122347] [ffffff802045bb60+  32][<ffffff80090861e8>] __switch_to+0xa0/0xc8
[  117.129615] [ffffff802045bb80+ 112][<ffffff8009c79e68>] __schedule+0x250/0x7b0
[  117.137022] [ffffff802045bbf0+  32][<ffffff8009c7a404>] schedule+0x3c/0xa0
[  117.144057] [ffffff802045bc10+ 176][<ffffff8009c7d858>] schedule_timeout+0x1a0/0x428
[  117.152082] [ffffff802045bcc0+ 144][<ffffff8009c7b0e4>] wait_for_common+0xd4/0x170
[  117.159653] [ffffff802045bd50+  32][<ffffff8009c7b1e4>] wait_for_completion_timeout+0x2c/0x38
[  117.168318] [ffffff802045bd70+  64][<ffffff80099a3a4c>] hdmitx_cec_read+0x114/0x1e0
[  117.176111] [ffffff802045bdb0+ 144][<ffffff8009214ba8>] __vfs_read+0x48/0x120
[  117.183387] [ffffff802045be40+  64][<ffffff8009215b3c>] vfs_read+0x94/0x150
[  117.190524] [ffffff802045be80+   0][<ffffff80092170f4>] SyS_read+0x54/0xb0
[  117.197495] [0000000000000000+   0][<ffffff80090830c0>] el0_svc_naked+0x34/0x38
[  117.205731] sysrq: SysRq : Show backtrace of all active CPUs
[  117.592229] binder: undelivered TRANSACTION_COMPLETE
[  117.592299] binder: undelivered transaction 90523, process died.
[  117.607142] binder: 3211:3814 transaction failed 29189/-22, size 60-0 line 3121
[  117.634457] VID: VD1 set global output as 0
[  117.634500] VID: VD1 off

Here are the tests I’ll run today/tomorrow :

• Disable the CEC functionnality on the unit connected to the Samsung TV and check if the issue still occurs.
• Replace the Viewsone/Dell displays by CEC enabled TVs (A LG and a Toshiba) and check if the issue occurs.

Below some information about the device situation when the ANR occurs :

• The device has just been powered or rebooted
• The device plays a video (in our lab a 4K HEVC but IMO it doesn’t really matter)
• The ANRs starts 2-3 mintes after boot
• The ANRs stops after some time, I don’t manage to know why

In term of statistics, this is not something that is easy to reproduce (it occurs randomly once every ~50 reboots) but, the final customer that reported us the issue has several hundreds of K3L units running and it experiences this issue every days…

Best regards,

PS : I’ll try to record you a video next time it occurs in our lab.

[VulcainMan]

Hi @william.lin ,

Just happens on the Toshiba TV set, here is the link to the video (Filebin | x6fpf066542xgri5).

• 00:40 : First ANR
• 01:40 : AOSP watchdog kill system_server (services and app are killed/restarted)
• 02:26 : Second ANR
• …

Best regards

[william.lin]

@VulcainMan ,
Can you use the following command to fetch a log for me?
This is an unusual issue, as we don’t experience it in our office using the official version. I hope you can try our official version.

adb logcat -b all > log.txt

[VulcainMan]

For sure @william.lin

I have recorded a lot of logs last days, I created an archive with

• A complete logcat of a crashy boot
• A complete logcat of a normal boot
• Complete DMESG outputs for both boots
• All Android ANR reports concerning the crashy boot

Here is a link to download it : Filebin | ax1h9nryk2s8k8hb

I’m not astonished that you didn’t manage to reproduce it easily, basically, for this pilot we wrote a small script that automatically reboot our 3 units every 5 minutes 24/7 and collect all logs before rebooting. Here are my last observation :

• The issue is rare, it happened only 2 times last 24 hours
• The issue ‘seems’ to happen
• The issue happens only if and only if a CEC compliant (and enabled) TV set is connected on the K3L (and switched on)
• This issue ‘seems’ (we need more time without ANR to confirm) to happen if and only if CEC switch is enabled on the K3L
• This issue ‘seems’ (we need more time without ANR to confirm) to happen if and only if CEC switch is enabled on the K3L at boot time (doesn’t happen if it is enabled programmatically later)
• This issue happens on a Samsung SmartTV, on a Toshiba TV but not on a LG SmartTV (however, this one is pretty old and, it looks like its CEC implementation is not fully working so I’m not sure we can conclude anything from this last point)

Let me know if you need anything else from my side.

[william.lin]

@VulcainMan ,
I apologize for the delayed response, as we were on holiday for the Chinese New Year.

The link you provided above has expired.

This is a rather peculiar issue. I tested it with LG, Samsung, Dell, and some other brand extended screens in our office, but was unable to reproduce the problem.

[VulcainMan]

Dear @william.lin ,

Sorry for my delay to get back, I was in holiday myself too! As requested, I’ve re-uploaded a full logcat/dmesg for a normal boot and a crashy one : Logs

Based on my latests observations, this issue seems to have definitely something related with HDMI-CEC for the reasons below:

• The issue is not encountered anymore if HDMI-CEC on the K3L, whatever the screen used
• The issue is not encountered anymore if the HDMI-CEC is disabled at boot and, manually enabled later (this is the way we are currently using to mitigate the ‘partially’ issue). Indeed, we have patched our app in order to disable HDMI-CEC before any reboot and, enable it manually at boot time. It partially mitigate the issue because it cannot works if the device’s power supply is unplugged/plugged. Morever, it seems that if HDMI-CEC is enabled at boot, disable it then kill the system_server process ASAP seems to prevent this issue “most of the time” (but we need more time to conclude on this last point).
• This issue is encountered if HDMI-CEC is enabled even if we inhibit our app (i.e it is started like it should at boot but it doesn’t do anything)

I insist that the issue is rare and pretty hard to reproduce (it sometime needs us one hundred boots to be encountered).

By the way, you’ll find below the AOSP version used to build our firmware : Information (repo info). Our modification consists in adding our app in the AOSP tree, tune some parameters (spash screen, status bar, etc).

My next move (next week) is to check if I can reproduce it with the Khadas official firmware. I’ll let you know.

Let me know if you need anything from my side.

Best regards