【Android】【问题分析】G-sensor因数据交互问题导致手机crash

G-sensor因数据交互问题导致手机crash

问题现象：

测试同事发现，手机在使用和待机时，低概率发现手机会crash

问题原因：

G-sensor在driver和HAL层因交互的参数不匹配，导致timeout引起的crash，具体log如下：

通过工作抓取到的kernel层的log（截选重要部分）如下显示:

 

<6>[ 7040.264871] SysRq: Show backtrace of all active CPUs

 

<6>[ 7040.264925]Backtrace for cpu 0 (current):

 

<6>[ 7040.264946] CPU: 0PID: 4667 Comm: watchdog Tainted: P       W  O3.10.49-g8347c3d-00015-g4c1aa2f #1

 

<6>[ 7040.265001][<c00132f8>] (unwind_backtrace+0x0/0xe0) from [<c0011084>](show_stack+0x10/0x14)

 

<6>[ 7040.265023][<c0011084>] (show_stack+0x10/0x14) from [<c00125c8>](smp_send_all_cpu_backtrace+0x50/0xcc)

 

<6>[ 7040.265045][<c00125c8>] (smp_send_all_cpu_backtrace+0x50/0xcc) from[<c02fbfec>] (__handle_sysrq+0x9c/0x140)

 

<6>[ 7040.265066][<c02fbfec>] (__handle_sysrq+0x9c/0x140) from [<c02fc3f4>](write_sysrq_trigger+0x38/0x48)

 

<6>[ 7040.265090][<c02fc3f4>] (write_sysrq_trigger+0x38/0x48) from [<c013c124>](proc_reg_write+0x6c/0x80)

 

<6>[ 7040.265113][<c013c124>] (proc_reg_write+0x6c/0x80) from [<c00f66fc>](vfs_write+0xd0/0x180)

 

<6>[ 7040.265134][<c00f66fc>] (vfs_write+0xd0/0x180) from [<c00f6bb8>](SyS_write+0x38/0x68)

 

<6>[ 7040.265152][<c00f6bb8>] (SyS_write+0x38/0x68) from [<c000d700>](ret_fast_syscall+0x0/0x30)

 

<6>[ 7040.265161]

 

<6>[ 7040.265161]sending IPI to all other CPUs:

 

<4>[ 7040.265180] IPIbacktrace for cpu 1

 

<6>[ 7040.265192]

 

<6>[ 7040.265205] CPU: 1PID: 831 Comm: SensorService Tainted: P       W  O3.10.49-g8347c3d-00015-g4c1aa2f #1

 

<6>[ 7040.265215] task:ebce7380 ti: ebf3a000 task.ti: ebf3a000

 

<6>[ 7040.265231] PC isat sub_preempt_count+0x14/0xd4

这段log提供了，从kernellog的时间点看7040打印出堆栈异常信息，换算对应于logcat的19:11:27秒打印出了watchdog 和sensor service的 堆栈，而kernel没有挂掉，仅仅打印出异常堆栈信息，logcat 在19:11:20 秒的时候 watchdog 已经被PowerManagerService block住的信息，而log被保存在了“ Wrote stack traces to'/data/anr/traces.txt'”下 。随即打印主动watchdog 的堆栈（即kernel log的 7040s打印的堆栈信息）“01-01 19:11:27.258   767  4667 I Watchdog_N: dumpKernelStac。而且sensorservice的堆栈信息。所以应该是PowerManagerService 被block主了，要看下/data/anr/traces.txt'的信息。Logcat 里面多次 “watchdog: Blocked in handler onmain thread (main), Blocked in handler on PowerManagerService(PowerManagerService)”而引发kernel 打印堆栈。

同时上层也有抓到具体重启的原因是Watchdog: *** WATCHDOGKILLING SYSTEM PROCESS: Blocked in handler on main thread (main), Blocked inhandler on PowerManagerService (PowerManagerService)

追溯“Blocked in handler on main thread(main), Blocked in handler on PowerManagerService (PowerManagerService)”来源于下段函数任务没完成或者time out导致。

// something is overdue!

                blockedCheckers =getBlockedCheckersLocked();

                subject =describeCheckersLocked(blockedCheckers);

                allowRestart = mAllowRestart;

 

if (hc.isOverdueLocked()) {

                checkers.add(hc);

            }

 

public booleanisOverdueLocked() {

            return (!mCompleted) &&(SystemClock.uptimeMillis() > mStartTime + mWaitMax);

        }

默认的超时时间是6s，也可以调用函数时传入，现在看来应该是传入的数据，而HAL层的数据都是由轮询的方式由底层传入。

static final longDEFAULT_TIMEOUT = DB ? 10*1000 : 60*1000;

static final boolean DB =false;

于是锁定在了PhoneWindowManager.goingToSleep（）这里和PhoneWindowManager.screenTurnedOff（）持有同一个同步锁导致。screenTurnedOff 在等待 goingToSleep 释放锁，于是导致系统卡在android.hardware.SystemSensorManager$BaseEventQueue.nativeDisableSensor。最后被watchdog 杀掉。

详细逻辑原因：

具体情况是在qcom的HAL层里的sensors.cpp下的这个函数

int sensors_poll_context_t::pollEvents(sensors_event_t* data, int count)

在以下的时候，先会拿到锁，然后有查到函数会在sm.readEvents()里面耗费很大时间以致无法解锁，才导致被kill掉。继续往下调查

178 Mutex::Autolock _l(mLock);

179 int nb = sm.readEvents(slist[i].handle, data, count);

180 if (nb < 0) {

181 ALOGE("readEvents failed.(%d)", errno);

182 return nb;

 

进ReadEvent（）里面会因为下面这段导致不断被循环，而这段循环的要求mEnable =1是ok的，而numEventReceived只有在上面一个循环里面才会++，

291 if (numEventReceived == 0 && mEnabled == 1) {

292 n = mInputReader.fill(data_fd);

293 if (n)

294 goto again;

295 }

 

在操作numEventReceived变量的函数循环，发现在report事件的时候有如下循环：

257 case SYN_REPORT:

258 {

259 if(mUseAbsTimeStamp != true) {

260 mPendingEvent.timestamp = timevalToNano(event->time);

261 }

262 if (mEnabled) {

263 if(mPendingEvent.timestamp >= mEnabledTime) {

264/* [BUFFIX]-Mod- Begin by TCTNB.XQJ,PR-915938, 2015/2/11, from AKM fae modify,for cts test */

265 raw = mPendingEvent;

266 if (algo != NULL)

267 {

268 if (algo->methods->convert(&raw, NULL, NULL)) {

269 ALOGE("Calibration failed.");

270 }

271 }

272/* [BUFFIX]-Mod- End by TCTNB.XQJ*/

273 *data++ = mPendingEvent;

274 numEventReceived++;

275 }

如红色部分，这里的函数就无法进入，但在report的case里面，有SYN_TIME_NSEC下有如下操作

245 case SYN_TIME_SEC:

246 {

247 mUseAbsTimeStamp = true;

248 report_time = event->value*1000000000LL;

249 }

250 break;

251 case SYN_TIME_NSEC:

252 {

253 mUseAbsTimeStamp = true;

254 mPendingEvent.timestamp = report_time+event->value;

这样才能理顺这个流程。而如果流程中间卡主，在长事件卡在循环里面，如果7-8秒，会导致无法唤醒，更长时间会导致system crash掉。

 

Best regards,