自从58同城iOS客户端9.0.0版本上线以来,陆续接到反馈说App有时启动会超时,无法响应,然后被系统杀死,只有重启手机才能恢复。得知存在App无法启动的问题后,我们马上展开了调查。通过对触发此问题的设备进行测试,发现此问题所影响的不仅仅是58同城App的启动,另有如京东、大众点评、腾讯视频等其他App也无法正常打开。 图1 App启动崩溃截屏
而且经过进一步测试,发现当此问题触发时,在任意App中进行剪贴板的相关操作都会突然导致App卡死无法操作。
图2 App卡死截屏
虽然我们总结出了这种卡死App问题的各种表现,但是如果没有清晰的崩溃栈信息,就没有线索去解决这个问题。于是我们开始去Bugly上查找有可能相关联的崩溃信息,但是并没有收获。
为什么Bugly上收集不到崩溃信息?
之后我们拿到发生崩溃的iPhone设备,连接到电脑并通过”Xcode-Devices and Simulators-View Devices Logs”导出了设备的崩溃日志去排查原因。它是在主线程(main-thread)中发生的崩溃,异常类型(Exception Type)为一个终止程序的信号(SIGKILL)类型,Code为0x8badf00d。
如下所示: 图3崩溃信息描述
(1)信号类型
首先,信号是Unix、类Unix以及其他POSIX兼容的操作系统中进程间通讯的一种有限制的方式。它是一种异步的通知机制,用来提醒进程一个事件已经发生。当一个信号发送给一个进程,操作系统中断了进程正常的控制流程,此时,任何非原子操作都将被中断。如果进程定义了信号的处理函数,那么它将被执行,否则就执行默认的处理函数。因此在应用的Crash引起的程序异常退出都会有signal。它的种类有多种,常见的有SIGSEGV,SIGILL,SIGABRT,SIGBUS,SIGKILL等等。
信号类型 | 信号解释 |
---|---|
SIGSEGV | 无效的内存地址引用信号,试图访问未分配给自己的内存, 或试图往没有写权限的内存地址写数据。 |
SIGILL | 执行了非法指令,通常是因为可执行文件本身出现错误, 或者试图执行数据段. 堆栈溢出时也有可能产生这个信号。 |
SIGABRT | 通常由于异常引起的中断信号,异常发生时系统会调用abort()函数发出该信号。 |
SIGBUS | 非法地址, 包括内存地址对齐(alignment)出错。与SIGSEGV的区别在于后者是由于对合法存储地址的非法访问触发的(如访问不属于自己存储空间或只读存储空间)。 |
SIGKILL | 用来立即结束程序的运行,该信号不能被阻塞、处理和忽略。 |
表 1 信号类型解释
其中本次发生崩溃的信号是终止程序的SIGKILL,它是不能被阻塞、处理和忽略。因此在应用中不能捕获此类崩溃,第三方工具中是无法收集到。
(2)Code异常编码
异常编码也是分析崩溃原因的重要依据之一,该日志中Code码0x8badf00d,即“ate bad food”,表示在应用程序启动、终止或响应系统事件花费的时间过长,应用程序已被系统终止,发生了监视程序超时。它是苹果设计的“看门狗”(watchdog)机制,若超出了该场景所规定的运行时间,“看门狗”就会强制终结这个应用的进程。
触发0x8badf00d的场景除了主线程被卡死的情况,还有以下几种情况:
因此以上的场景均无法应用拦截,处理,不能上报到第三方崩溃收集工具中。
既然第三方崩溃收集工具拿不到日志,那么我们之前是通过将iPhone设备连接到电脑中,通过”Xcode-Devices and Simulators-View Devices Logs”来导出当前设备发生的崩溃日志。这种方式可以收集到所有类型的崩溃。但是不可能人人都具备Xcode工具,也不可能时时刻刻都带电脑。而我们发现苹果会将当前设备所发生的所有事件都记录到系统日志中,包括崩溃日志,CPU Usage日志。
在系统日志中崩溃日志名称的格式为“进程名+日期+时间.ips.synced”或“进程名+日期+时间.ips”,如:“58tongcheng-2019-12-04-113614.ips”。该日志在iOS10.2以及以上系统的设备上可以进入“设置-隐私-诊断与用量”中获取,iOS10.2以上系统的设备上可以进入“设置-隐私-分析-分析数据”中获取。因此,用户可以直接通过iPhone设备选择一个崩溃日志后,通过Airdrops或其他三方app发送到电脑或崩溃自动解析工具进行解析。
图4系统隐私数据
在获取到日志之后如何进行解析呢?针对指定的日志进行日志解析,绝大多数iOS开发者都会想到使用符号表进行解析。但是原始的dSYM文件可能存在没有保存或者丢失的情况。因此58同城对日志解析进行了相应的扩展,扩大了日志的解析的适用范围。除了使用原始的dSYM符号表文件进行日志解析外,58的点对点日志解析工具还支持,针对bugly生成的符号表symbol文件的解析,甚至在没有任何符号表的情况下,也可以根据二进制数据进行日志解析。
众所周知,崩溃日志符号化所需要的符号表通常指dSYM文件,dSYM文件是用来记录调试信息的文件,其数据存储格式为DWARF格式。其数据来源为应用二进制文件的DEBUG段,记录的信息主要包括:文件路径信息、行号信息、变量与地址的映射、函数与地址的映射等。正是因为其存在地址与符号的映射关系,符号表才可以被用于解析崩溃日志。在得到崩溃日志和相应的dSYM文件后,可借助symbolicatecrash工具实现日志符号化。如果没有symbolicatecrash工具,那么dwarfdump命令也可以逐条实现地址符号化。
在业务开发过程中,本地调试状态下打包是默认不生成dSYM文件的,但是这并不意味着调试信息和符号信息丢失了。当我们本地Xcode打出来的包发生偶现崩溃时,可以通过Xcode提供的dsymutil工具将dSYM文件从应用程序的二进制文件中剥离。剥离出的dSYM文件即可借助相应symbolicatecrash实现地址符号化。
在使用bugly进行崩溃统计时,我们需要将符号表上传到bugly的后台。这个符号表并不是原始的dSYM文件,而是bugly从dSYM文件中提取的文本文件。其数据格式如下图所示: 图5 Symbol文件
bugly的符号表是bugly从dSYM文件中提取的函数地址与符号的映关系,其格式为:起始指令地址 + 结束指令地址 + 代码所在函数名 + 代码所在文件及行号。举例说明,假如我们拿到的崩溃偏移地址为B,通过文本扫描后发现函数F的L行代码的起始指令地址为A,结束指令地址C,地址满足A <= B <= C的原则,因此可以确定崩溃发生在F函数的L行。由于bugly的符号表只保留了函数地址符号映射,不包含文件路径、变量地址符号映射等信息,因此bugly的符号表相比于dSYM文件更轻量,更适合保存和传输。
58同城在业务开发阶段提供给测试同学的测试包都是通过Jenkins服务打包。随着业务的发展,58同城APP的体积越来越庞大,这就导致测试同学从Jenkins服务器上下载APP的时间较长。为了能够尽可能的减小下载体积,58同城将APP的符号表在打包期间从应用程序中剥离出来形成dSYM文件,保存在打包服务器中。因此测试同学下载的Jenkins包是不包含符号表信息的。由于剥离出来的dSYM文件较大,为了节省服务器空间,dSYM在保留2天后会自动清除。假设有这样一个场景:测试同学下载了一个测试包,在测试到第三天时发生了不可稳定复现的崩溃,那么此时我们进行日志解析是没有任何符号表的。
为了解决这种场景的问题,58同城开发了基于Mach-O文件解析的无符号表日志解析工具。通过遍历二进制文件中所有类的方法列表,确定崩溃堆栈的指令地址位于哪个函数的指令区间范围,从而确定崩溃发生时正在调用的函数,进而实现崩溃日志的符号化。目前此工具已经成为58质量保证必不可缺的工具之一。相关代码已经通过58技术委员会审核,近期将对外开源。
因此,通过点对点崩溃分析的方式将崩溃日志进行解析,我们获取了具体各个不同线程的堆栈信息,开始定位问题。该崩溃主要现象是主线程卡死,我们先从主线程的堆栈开始分析。主线程调用栈分析
图6 崩溃主线程堆栈信息
日志中,应用被杀死之前主线程停留在+[WIMOpenUDID valueWithError:]中获取系统剪贴板UIPasteboard对象的操作中。但是通常情况下,在主线程中获取一个对象不会把主线程卡死,于是我们便查看了这个方法的实现以尝试定位问题。如下:
图7 OpenUDID部分源码
这段代码是从开源代码库OpenUDID中直接私有化出来的一份代码,并维持了原有OpenUDID的逻辑。它在主线程中通过for循环100次来尝试获取标识从org.OpenUDID.slot.0到 org.OpenUDID.slot.99的UIPasteboard对象,并从每个获取到的剪贴板对象中获取OpenUDID的值,并保存起来。按照OpenUDID的逻辑,从100个剪贴板里取出的OpenUDID值可能会有不同,但是它最终回取出现次数最多的一个OpenUDID值作为最终的OpenUDID结果。
如此频繁地调用UIPasteboard的接口去获取对象会阻塞主线程吗?验证一下。
首先写一个循环来测试UIPasteboard的API的耗时情况 图8 主线程UIPasteboard测试代码
循环创建100个UIPasteboard对象,并为向每个UIPasteboard对象都存入100个字符串。并打印对每个UIPasteboard对象的操作时间,执行上述代码后,结果如下: 图9 主线程UIPasteboard测试代码执行输出结果
从打印结果可以看出,获取并对UIPasteboard进行操作的确是一个比较耗时的操作。按此结果100次循环需要50秒,这样的话App肯定是启动不了的。
但这是测试Demo的极端耗时操作,而OpenUDID对于剪贴板的频繁操作仅仅是尝试获取剪贴板对象,这个操作的耗时不至于卡死App,所以此时单看主线程的堆栈信息不能说明什么问题。需要再看其他线程堆栈。
子线程调用栈分析 图10崩溃子线程堆栈信息一
图11 崩溃子线程堆栈信息二
通过子线程堆栈信息的分析,我们发现在崩溃日志中除了主线程以外,还有另外两个子线程也停留在获取系统剪贴板UIPasteboard对象的操作中。其中有一个线程停留在+[WBWMDA_OpenUDID valueWithError:]方法中,查看他的实现后发现这是应该另一个私有化的OpenUDID代码,同样维持了OpenUDID原有的逻辑:循环100次尝试获取名称从org.OpenUDID.slot.0到org.OpenUDID.slot.99的UIPasteboard对象,从中获取openudid的值。由于它是在子线程中被调用的,就导致了子线程频繁获取UIPasteboard对象的情况。
子线程反复调用UIPasteboard的接口会使App卡主吗?接下来,我们再验证一下子线程操作UIPasteboard对象的情况:
图12 子线程UIPasteboard测试代码
如上图所示,将之前100次的UIPasteboard操作放在子线程中,执行后App成功启动,并得到如下输出: 图13 子线程UIPasteboard测试代码执行输出结果
从结果中可以看出,将上述复杂的UIPasteboard操作放入子线程的确可以使App启动,且对UIPasteboard的操作耗时与在主线程中是一致的。也并未阻塞App启动,反而很顺利地进入了测试Demo的首页。
由此可以看出单单在子线程反复调用剪贴板的逻辑并不会使App卡主。那么主线程与子线程同时调用UIPasteboard会有什么影响呢?继续测试主线程与子线程同步频繁调用UIPasteboard接口测试 图14 主线程与子线程混合UIPasteboard测试代码
同时开启主线程和子线程来执行多次UIPasteboard操作,其中主线程执行50次,子线程执行50次。在最开始的测试中,在主线程进行100次UIPasteboard操作耗时一共50秒,现在我们将其中的一般转移到了子线程那么耗时应该减少一半。是这样吗?执行代码验证一下,输出如下: 图15 主线程与子线程混合UIPasteboard测试代码
执行输出结果这个结果在我们的意料之外。尽管将50次的UIPasteboard对象的操作放在了子线程,主线程仅执行了50次,但是单次执行时间又原来的0.5秒左右提高到了接近1秒。显然系统对于剪贴板的操作是做了线程同步限制。总时间是不变的。
尽管我们知道了剪贴板是同步操作的,依然并未复现卡死的情况。那么多线程并发到底会不会有可能触发剪贴板的卡死呢?继续验证。
多线程并发频繁调用UIPasteboard接口测试 图16 多线程并发UIPasteboard测试代码
创建1000个子线程并发任务,每个并发任务中获取100次UIPasteboard对象。同时在主线程调用1次UIPasteboard的存取操作。执行后输出如下:
图17 多线程并发UIPasteboard测试代码
执行输出结果从输出内容可以看出,子线程在执行了150次左右便不再执行下去了,通过上面的操作,成功将App卡死无法执行下去了。并且此时尝试打开京东、腾讯视频等其他App发现此时已经无法打开了,而且在所有App中使用剪贴板都会使App卡主。
所以多线程并发使用UIPasteboard相关接口的确会导致App卡死现象,并且会影响其他程序。
测试到这里,我们了解到了系统对于UIPasteboard不但做了线程同步的限制,而且做了进程同步限制。在高并发使用UIPasteboard接口的情况下,很容易使UIPasteboard出现卡主的问题,并且影响整个系统的App。
那么触发100次UIPasteboard的OpenUDID对App会带来多大的风险?
通过上述调研,OpenUDID会在第一次获取OpenUDID值的时候访问100次UIPasteboard的API。如果启动时使用了OpenUDID等于间接使用了UIPasteboard,由于UIPasteboard是进程间同步的,当系统UIPasteboard被卡死时,App便无法启动了。
另外,大家在使用OpenUDID的时候经常会把它私有化,尤其是在做SDK时,仅仅改个类名,然后便使用原有逻辑也是常有的事。出于用户体验优化的需要,很多开发者会将部分逻辑比如初始化等放在子线程执行。如果放到子线程的这部分逻辑首先访问了私有OpenUDID代码去获取OpenUDID,就发生了子线程连续访问UIPasteboard的情况。通常一个App会接入多个SDK,如果每个SDK都有一个OpenUDID,并且各自创建子线程访问那么就会发生并发访问剪贴板的情况。如下图所示:
图18 OpenUDID多线程并发频繁使用剪贴板
基于上述测试的结果,可以猜测:线程开的越多,则越有可能触发剪贴板被卡死的情况。
为了了解App无法启动的情况,我们在启动时添加了启动异常计数的埋点策略,当启动失败次数达到3次时就进行埋点并上报。同时为了优化用户体验,启动失败次数达到3次时则进入启动修复页面,提示用户去重启设备。通过对该策略的埋点数据分析,每天大约会有万分之二的用户会触发连续三次启动失败的问题。虽然App启动失败还有许多其他的原因,但剪贴板卡死这个问题的影响应该还是比较大的。
为了进一步扩大对OpenUDID剪贴板问题的影响范围的了解,对经常用到的SDK使用OpenUDID以及修复的情况进行了调研(由于SDK存在版本差异,实际情况可能与结果有些偏差):
SDK | OpenUDID类名 | 是否修改了 | 启动注册是否调用 |
---|---|---|---|
滴滴打车 | DIOpenUDID | 否 | 否 |
讯飞 | IFlyOpenUDID | 否 | 否 |
微博 | WBSDKOpenUDID | 是(只修改了私有剪贴板标识,还是会访问100次剪贴板) | 否(但初始时会触发一次剪贴板的调用) |
支付宝 | UTDIDOpenUDID | 是(仅在App首次启动时会触发100次访问剪贴板的逻辑) | 否 |
微信 | WXOMTAOpenUDID | 是(不会触发100次访问剪贴板逻辑) | 否(但初始化时会触发一次剪贴板的调用) |
头条广告 | BUOpenUDID | 是(不会触发100次访问剪贴板逻辑) | 否 |
百度地图 | -- | -- | -- |
ZBar | -- | -- | -- |
听云 | -- | -- | -- |
表 2 常用SDK OpenUDID使用情况
从以上的调研结果中看出,目前OpenUDID使用还是非常广泛的,并且大多数情况下均保留了OpenUDID反复使用UIPasteboard接口的逻辑。
为了降低触发UIPasteboard卡死的概率,可以抛弃剪贴板保存OpenUDID的逻辑,将OpenUDID的值保存在钥匙串中。最初OpenUDID是利用系统自定义剪贴板,可以在不同App之前共享数据的特性来保证OpenUDID的值始终不变,但随着iOS系统对此特性的封锁,利用剪贴板保存OpenUDID反而会带来问题。
对此次App卡死问题调研,是基于一个个猜想而推动的,尽管它拥有非常低的概率复现,但我们还是循着蛛丝马迹找到了他们之间可能存在的关联,这里从隐私数据获取的崩溃日志以及基于点对点的崩溃分析技术起到了关键的作用,然后通过一步步验证,最终得出结论:
此次问题其实也是为我们敲响了一次警钟,对于第三方代码的使用,充分掌握其原理以及潜在影响是十分必要的,尤其是使用缺乏维护的代码时。随着其运行环境的不断迭代,其功能的稳定性也会受到影响,若放任不管则会便会在未来某一天带来意想不到的问题。
参考文章
作者简介:王晓晖:58同城用户价值增长部-iOS技术部高级研发工程师。专注于客户端架构优化与创新项目的研发。 邓竹立:58同城用户价值增长部-iOS技术部高级研发工程师。专注于客户端架构与性能优化。 朴惠姝:58同城用户价值增长部-iOS技术部高级研发工程师。专注于客户端性能优化及工具研发,跨平台库的维护。
Copyright© 2013-2020
All Rights Reserved 京ICP备2023019179号-8