【NE现场】
02-24 16:16:42.352 14969 14975 I art : Do partial code cache collection, code=96KB, data=100KB 02-24 16:16:42.353 14969 14975 I art : After code cache collection, code=96KB, data=100KB 02-24 16:16:42.353 14969 14975 I art : Increasing code cache capacity to 512KB 02-24 16:16:42.407 14969 15400 E TUnionLoginManager: not tblogin module, not handle and module is video 02-24 16:16:42.991 14969 14969 I art : CrashHandler::Action in:0 02-24 16:16:42.992 14969 14969 I art : trap_no 00000000 error_code 00000000 oldmask 00001204 fault_address ebcc3000 02-24 16:16:42.992 14969 14969 I art : r0 cd7d3c50 r1 00004001 r2 00000000 r3 00000002 02-24 16:16:42.992 14969 14969 I art : r4 00000001 r5 c7e1f720 r6 c614f014 r7 33dd2da0 02-24 16:16:42.992 14969 14969 I art : r8 33352a28 r9 e9d85400 sl 33dd2db0 fp 00000001 02-24 16:16:42.992 14969 14969 I art : ip ec8fc010 sp ffba3978 lr ec9cac0f pc ebcc3000 cpsr 800e0010 02-24 16:16:42.992 14969 14969 I art : Generating CrashHandler 02-24 16:16:42.992 14969 14969 I DEBUG : begin to generate native report 02-24 16:16:43.108 14969 15039 I DEBUG : Resume native log stat thread 15039 02-24 16:16:43.566 14969 14969 I DEBUG : generate native report finished 02-24 16:16:43.608 1556 2225 I ActivityManager: Process com.UCMobile (pid 14969) has died 02-24 16:16:43.608 1556 1573 I libprocessgroup: Killing pid 15503 in uid 10134 as part of process group 14969
日志解读如下：
1.art标签：系统的Dump模块发现一个SIGSEGV异常后打印了CPU信息，后面应该还有更多的dump信息，但没有执行。
2.DEBUG标签：UC的异常收集模块发现一个Native异常后收集FC信息。
3.AMS打印UC has died。
因为UC截获了异常时候的SIGNAL后没有继续发给Debuggerd，所以系统无法dump tombstone。
好在UC的同事提供了他们收集到的异常信息
FC的现场来看，和系统的Dump逻辑截获的异常不一样，而且指明了是系统的Dump逻辑出了异常。
上图中ArtDumpJavaStack()就是系统的Dump逻辑。
所以这里有两个异常，系统的Dump逻辑捕获一个SIGSEGV异常后，执行dump操作时，又触发一个SIGSEGV异常。
系统的dump逻辑是2月23号进的代码，而问题是24号爆发的，所以判断这段逻辑肯定有问题。
问题是即使是没有这个change，那第一个SIGSEGV异常，默认情况下必然会导致应用FC，但23号版本中不会出现闪退现象。
唯一的解释是，UC截获了这个异常，且这个异常很可能是UC故意搞出来的。
后来跟UC工程师沟通后证实了这个猜想：
UC为了跳过Android N的加载so库的限制，搞了个"黑科技"，会主动触发一个SIGSEGV。
方法是PC指向一个没有可执行权限的内存，这样会触发一个SIGSEGV，sig code为SIGV_ACCERR。
他们会注册SIGSEGV的信号处理函数，在这个信号处理函数中执行"黑科技"。
而系统的dump逻辑却把这个当做异常来处理，在执行dump过程中出现某个异常，导致了新的异常。
UC提供的日志就是系统的dump逻辑产生的异常相关的信息。
出错的原因是未定义指令异常（ILL_ILLOPC），也就是PC指向了一个非法指令。
但实际上PC的值0xe8609dd4指向的是正确的值，也就是ArtDumpJavaStack()。
那为什么是未定义的指令呢？原因是因为cprs的Thumb位(bit5)为0，CUP把ArtDumpJavaStack()当做arm指令了。
而实际上ArtDumpJavaStack()是Thumb Code。
跟UC同事确认，他们没改过cpsr，那很可能是系统的dump逻辑中cpsr没有正确赋值。
Review代码，发现确实有问题：
@art/runtime/fault_handler_crash.cc ... #if defined(__arm__) sc->arm_sp -= (SIGSEGV_PROTECT_SP_SIZE); sc->arm_r0 = reinterpret_cast<unsigned long>(&savedSigInfo); sc->arm_r1 = reinterpret_cast<unsigned long>(&savedContext); sc->arm_pc = reinterpret_cast<uintptr_t>(ArtDumpJavaStack);
这里只修改了pc，没有对应地修改cpsr。
修改代码，将cpsr的Thumb位置上后发现依然FC。
但FC的日志跟之前有很大的改变：
02-28 11:36:59.236 26154 26154 I art : Handling fault 02-28 11:36:59.236 26154 26154 I art : CrashHandler::Action in:0 02-28 11:36:59.236 26154 26154 I art : trap_no 00000000 error_code 00000000 oldmask 00001204 fault_address f5b69000 02-28 11:36:59.236 26154 26154 I art : r0 d766f550 r1 00004001 r2 00000000 r3 00000000 02-28 11:36:59.236 26154 26154 I art : r4 00000001 r5 f65f7c21 r6 cfa58b75 r7 ceca0b00 02-28 11:36:59.236 26154 26154 I art : r8 d0d9d1a8 r9 f3a23230 sl 00000001 fp 00000001 02-28 11:36:59.236 26154 26154 I art : ip f65291d0 sp ffe1a7d0 lr f65f7c0f pc f5b69000 cpsr 80070010 02-28 11:36:59.236 26154 26154 I art : trap_no 00000000 error_code 00000000 oldmask 00001204 fault_address f5b69000 02-28 11:36:59.236 26154 26154 I art : r0 f3a3d9f8 r1 f3a3d710 r2 00000000 r3 00000000 02-28 11:36:59.236 26154 26154 I art : r4 00000001 r5 f65f7c21 r6 cfa58b75 r7 ceca0b00 02-28 11:36:59.237 26154 26154 I art : r8 d0d9d1a8 r9 f3a23230 sl 00000001 fp 00000001 02-28 11:36:59.237 26154 26154 I art : ip f65291d0 sp ffe1a3d0 lr f65f7c0f pc f388a160 cpsr 80070030 02-28 11:36:59.237 26154 26154 I art : Generating CrashHandler 02-28 11:36:59.237 26154 26154 I art : ArtDumpJavaStack in 02-28 11:36:59.237 26154 26154 I art : Checking for generated code 02-28 11:36:59.237 26154 26154 I art : not runnable 02-28 11:36:59.237 26154 26154 I art : in_generated_code:0 02-28 11:36:59.237 26154 26154 I art : DumpSigsegvJavaStack 02-28 11:36:59.237 26154 26154 I art : --------------QuickFrame: 0xffe1aa40 QuickFramePc:0 ShadowFrame:0x0 02-28 11:36:59.237 26154 26154 I art : sought_offset:24a199eb 02-28 11:36:59.237 26154 26154 I art : ... 02-28 11:36:59.240 26154 26154 I art : --------------QuickFrame: 0xffe1b7b0 QuickFramePc:75626805 ShadowFrame:0x0 02-28 11:36:59.240 26154 26154 I art : --------------#18:com.android.internal.os.ZygoteInit.main(ZygoteInit.java:764) 02-28 11:36:59.241 26154 26154 I art : ArtDumpJavaStack raise second sigsegv 02-28 11:36:59.241 26154 26154 I art : Handling fault 02-28 11:36:59.241 26154 26154 I art : Checking for generated code 02-28 11:36:59.241 26154 26154 I art : CrashHandler::Action in:1 02-28 11:36:59.241 26154 26154 I art : Caught unknown SIGSEGV in ART fault handler - chaining to next handler. 02-28 11:36:59.243 26154 26154 I android_uc_loader: load /data/app/com.UCMobile-1/lib/arm/libandroid_uc_44.so(0xd76f5014) success, hw_accel=1, api_level=24, window=1080x1920, display=1080x1920, cores=4, max_freq=1593, mem=2710, aggressive=0 02-28 11:36:59.254 26154 26154 I art : Handling fault 02-28 11:36:59.254 26154 26154 I art : CrashHandler::Action in:1 02-28 11:36:59.255 26154 26154 I art : Caught unknown SIGSEGV in ART fault handler - chaining to next handler. 02-28 11:36:59.255 26154 26154 I art : Handling fault 02-28 11:36:59.255 26154 26154 I art : CrashHandler::Action in:1 02-28 11:36:59.255 26154 26154 I art : Caught unknown SIGSEGV in ART fault handler - chaining to next handler. 02-28 11:36:59.256 26154 26154 E chromium: [ERROR:icu_util.cc(121)] InitFuncsFromSystemICU failed, status: 2 02-28 11:36:59.256 26154 26154 F chromium: [FATAL:content_main_runner.cc(760)] Check failed: base::i18n::InitializeICU(). 02-28 11:36:59.256 26154 26154 I art : Handling fault 02-28 11:36:59.256 26154 26154 I art : CrashHandler::Action in:1 02-28 11:36:59.256 26154 26154 I art : Caught unknown SIGSEGV in ART fault handler - chaining to next handler. 02-28 11:36:59.256 26154 26154 I DEBUG : begin to generate native report 02-28 11:36:59.470 26154 26229 I DEBUG : Resume native log stat thread 26229 02-28 11:36:59.998 26154 26154 I DEBUG : generate native report finished 02-28 11:37:00.064 11427 11480 I ActivityManager: Process com.UCMobile (pid 26154) has died 02-28 11:37:00.065 11427 11480 D ActivityManager: cleanUpApplicationRecord -- 26154
从日志中可以看到，系统的dump逻辑走完了，同时也有UC额日志输出。那为什么会FC呢?
打印signal的trace信息，如下：
com.UCMobile-6223 [003] d..2 659.442572: signal_generate: sig=11 errno=0 code=196610(SEGV_ACCERR) comm=com.UCMobile pid=6223 grp=0 res=0 com.UCMobile-6223 [003] d..2 659.442964: signal_deliver: sig=11 errno=0 code=196610(SEGV_ACCERR) sa_handler=f29dc2dd sa_flags=c000004 com.UCMobile-6223 [003] d..2 659.449876: signal_generate: sig=11 errno=0 code=196609(SEGV_MAPERR) comm=com.UCMobile pid=6223 grp=0 res=0 com.UCMobile-6223 [003] d..2 659.450257: signal_deliver: sig=11 errno=0 code=196609(SEGV_MAPERR) sa_handler=f29dc2dd sa_flags=c000004 com.UCMobile-6223 [003] d..2 659.464690: signal_generate: sig=11 errno=0 code=196610(SEGV_ACCERR) comm=com.UCMobile pid=6223 grp=0 res=0 com.UCMobile-6223 [003] d..2 659.465068: signal_deliver: sig=11 errno=0 code=196610(SEGV_ACCERR) sa_handler=f29dc2dd sa_flags=c000004 com.UCMobile-6223 [003] d..2 659.468323: signal_generate: sig=11 errno=0 code=196610(SEGV_ACCERR) comm=com.UCMobile pid=6223 grp=0 res=0 com.UCMobile-6223 [003] d..2 659.468645: signal_deliver: sig=11 errno=0 code=196610(SEGV_ACCERR) sa_handler=f29dc2dd sa_flags=c000004 com.UCMobile-6223 [003] d..2 659.470047: signal_generate: sig=11 errno=0 code=196609(SEGV_MAPERR) comm=com.UCMobile pid=6223 grp=0 res=0 com.UCMobile-6223 [003] d..2 659.470369: signal_deliver: sig=11 errno=0 code=196609(SEGV_MAPERR) sa_handler=f29dc2dd sa_flags=c000004
其中FC过程中一共有5个signal，
其中第一个信号SEGV_ACCERR是UC主动触发的异常，第二个信号SEGV_MAPERR是系统的Dump逻辑主动触发的异常。
如果说第一个信号SEGV_ACCERR是UC为了加载so库触发的，那第二个信号SEGV_MAPERR后有UC的日志，那说明一个so的加载过程结束了。
后面的两个SEGV_ACCERR和可能就是加载其他库时触发的。
而系统的dump逻辑设计时没考虑这种多个异常信号的case，它只考虑单个异常。
从日志中也能看出来，它只dump了第一个SEGV_ACCERR，后面的异常都没打印。
review代码后找到相关逻辑：
bool CrashHandler::Action(int sig ATTRIBUTE_UNUSED, siginfo_t *siginfo, void *context) { LogD << "CrashHandler::Action in:" << counter; if (1 == counter) { struct ucontext *uc = reinterpret_cast<struct ucontext *>(context); memcpy(uc, &savedContext, sizeof(struct ucontext)); memcpy(siginfo, &savedSigInfo, sizeof(siginfo_t)); return false; } counter++; struct ucontext *uc = reinterpret_cast<struct ucontext *>(context); struct sigcontext *sc = reinterpret_cast<struct sigcontext *>(&uc->uc_mcontext); DumpSigContext(uc->uc_mcontext); memcpy(&savedContext, uc, sizeof(struct ucontext)); memcpy(&savedSigInfo, siginfo, sizeof(siginfo_t));
...
它在第一次(SEGV_ACCERR)进异常处理函数的时候保存上下问到savedContext里，第二次进来时(SEGV_MAPERR)要恢复上下文。
而第三次(SEGV_ACCERR)进来时，用第一次保存下来的上下文覆盖当前上下文，这明显是逻辑错误。
第三次进来时，应该是重新进行新一次的dump才对。
如何修改呢？很简单，重置一下counter就可以了
bool CrashHandler::Action(int sig ATTRIBUTE_UNUSED, siginfo_t *siginfo, void *context) { LogD << "CrashHandler::Action in:" << counter; if (1 == counter) { counter = 0; struct ucontext *uc = reinterpret_cast<struct ucontext *>(context); memcpy(uc, &savedContext, sizeof(struct ucontext)); memcpy(siginfo, &savedSigInfo, sizeof(siginfo_t)); return false; } counter++; struct ucontext *uc = reinterpret_cast<struct ucontext *>(context); struct sigcontext *sc = reinterpret_cast<struct sigcontext *>(&uc->uc_mcontext); DumpSigContext(uc->uc_mcontext); memcpy(&savedContext, uc, sizeof(struct ucontext)); memcpy(&savedSigInfo, siginfo, sizeof(siginfo_t)); ...