手把手教你从iPhone系统日志中剖析App性能数据

背景

随着应用内多个业务的持续发展,客户端对性能的要求越来越高,持续要关注应用的性能。但是收集应用的性能数据我们面临着几个问题:

崩溃数据 —  在App内收集崩溃日志大家常用的方案有bugly收集,Crashlytics收集等第三方工具,将设备连接到Xcode工具打开“View Device Logs”导出等等。

问题 1 :部分崩溃数据在第三方手机平台中无法收集,比如终止程序的信号 SIGKILL 引起的崩溃。

问题 2 :非 iOS 开发人员出现 app 的崩溃,想把日志发送给开发人员去排查,如何导出该日志?

后台存活时间 —  在非调试环境下,iOS应用进入后台后会先进入挂起状态,这时系统不允许执行任何代码,但是系统不会立即杀死进程,在系统杀死进程之前打开app可以唤醒。

问题 1: 怎么获取当前进程在后台存活了多久?

问题 2: 如果进程在后台存活的时间过短,如何分析后台存活时间过短的原因?

iPhone系统日志

苹果发布了一个广告海报,海报显示“What happens on your iPhone,stays on your iPhone。”,意味着你的手机产出的数据就待在你的手机上。苹果公司对于用户的数据一直以来的对策都是不收集的态度,而对于一些不得不收集的内容,苹果则采用差分隐私的算法,对于收集过后的数据进行匿名、扰乱,从而让数据无法定位到具体的用户。系统日志是苹果记录硬件,操作系统的规格等方面的详细信息,性能统计数据以及设备和应用程序的使用数据的日志。在iOS10.2以上获取日志的需要打开“设置”-“隐私”-“分析”-“共享iPhone分析”的开关,iOS10.2以及以下需要打开“设置-隐私-诊断与用量”打开发送开关。打开开关后,进入“分析数据”中查看系统记录的所有日志。系统日志中包含二十多种不同类型,包括崩溃日志,Analytics日志,JetsamEvent日志,xp_amp_app_usage_dnu开头日志等等。

App Store Connect 是借助 App 分析、销售和趋势及付款和财务报告来查看别处无法提供的数据,以衡量您的 app 表现并获取独特的深入洞见。衡量 iOS macOS tvOS app 的用户活跃度、营销活动表现、获利情况及更多方面。如图:

图1 App Store Connect

App Store Connect中我们可以拿到App安装情况,App使用次数,App被删除,崩溃等等信息。而我们发现在iPhone系统日志确实都包含以上信息,并且不仅仅是我们自己开发的App,还包括其他App相关的信息。因此,我们能否利用这些数据来分析一些其他问题?

崩溃分析

在系统日志中以app进程名为开头的崩溃日志和CPU Usage日志,该日志是大家最熟悉的app崩溃日志和app CPU Usage日志,它其实是存到iPhone设备中。之前获取特定设备发生的崩溃日志我们是通过Xcode工具导出或bugly收集。但是不可能所有人都会安装Xcode工具,获取数据有一定的难度。还有通过bugly等第三方工具无法收集终止进程的SIGKILL等不可被阻塞,处理和忽略的信号,一旦出现这种崩溃就很难定位到具体原因。因此,用户可以通过进入iPhone设备的系统隐私数据中的崩溃日志通过Airdrops发送到电脑,或者发送到自动化解析工具进行解析。

图2 自动化崩溃解析工具

此外系统包括 xp_amp_app_usage_dnu开头的 日志,该日志其实是上述说明的App Store Connect中的数据,详细的记录了当前设备的app使用情况,包括当前设备安装的app信息,版本号,更新app日志,打开app置于前台时间等等。日志生成时机为每天的00:00和12:00各生成一个,因此每天都有两条相关日志。该日志主要由eventType来区分类型,包括crashes,installs,launches,redownload等。其中crashes记录的是从上一次发生日志时间开始,到生成当前日志期间崩溃的app信息,包括发生崩溃app的app版本号以及发生次数等。如下:该日志是2019.11.29的00:01生成的日志,说明在2019.11.28的12:00到2019.11.29的00:01期间QQ app发生了4次崩溃,发生崩溃的版本为8.1.8版本。

但是该日志不包括堆栈信息,具体的堆栈信息可参考1中的进程名为开头崩溃日志。因此,在隐私数据中寻找QQ进程名为开头的崩溃日志,确实在该时间段发生过4次崩溃。

图3 系统日志列表

有些崩溃用户可能感知不到,比如应用在后台时被系统杀死,这种情况可以通过xp_amp_app_usage_dnu日志判断每天发生崩溃的次数,还可以作为检测app质量的一个工具。

此外 installs 类型日志记录的是当前设备安装的所有 app 的版本信息,某个时间段通过 appstore 安装或者通过 appstore 自动更新的 app 信息。 installs 类型的日志区分 installType ,分为 prior update buy redownload 等等。 prior 是非当前时间段安装或更新的 app buy 是当前时间段通过 appstore 第一次下载的 app update 是在当前时间段通过 appstore 更新的 app redownload 是在当前时间段用户重装的 app launches 类型记录的是从上一次发生日志时间开始,到生成当前日志期间打开的所有 app ,打开次数,置于前台的 app 使用时间以及应用版本号等。 redownload 类型它记录的是从上一次发生日志时间开始,到生成当前日志期间重装的 app ,版本号,重装次数等等。它是当前设备的记录, App Store Connect收集了多个设备的 xp_amp_app_usage_dnu 日志,分析不同app的用户使用情况。

后台存活时间

首先,后台存活时间我们可以通过关注系统的控制台来获取准确的时间。我们可以在进入后台的时候输出一个 NSLog拿到进入后台的时间。

通过控制台输出的日志获取进入后台的时间

进入后台后控制台会输出很多系统进程日志,包括进程优先级变化情况,客户端到期通知等,最后进程优先级会变成0。

图4 优先级变为0

在后台任务结束后,App会进入挂起状态(suspended)

图5 进入挂起状态

若App由于触发了系统不允许的后台操作,系统刚发出termination request for application <xxx>

图6  发出Terminate Request

其中的Terminating with context:log中包含一个被杀死的原因,原因是“Time-out waiting for process”,也就是进程没有在时间内完成任务。

[application<com.58.LeakBackgroudTaskDemo>:3293] Terminating with context: <RBSTerminateContext: 0x102472e00; code: 0x2182BAAD; explanation: " Timed-out waiting for process  [application<com.58.LeakBackgroudTaskDemo>:3293] to invalidate assertion with identifier 26-3293-60297 and explanation 'Shared Background Assertion 0 for com.58.LeakBackgroudTaskDemo'. Direct this report to owners of that process"; reportType: 0; maxRole: 7; maxTerminationResistance: 3>

之后系统会将移除当前进程,相当于是被系统杀死。

图7 移除进程时间为20:18:26

因此我们可以拿到当前App从进入后台开始一直到被系统杀死的时间,就可以拿到当前App的后台存活时间。

那么我们怎么分析后台的什么任务导致的呢?

系统日志中可以找到以 Analytics 开头的日志,它有 6 种不同类型包括 90day Daily Never Journal-90day Journal-Daily Journal-Never 。在这 6 种数据中 Daily 类型的数据包含着非常多的内容,大小达到几百 k Daily 数据是苹果每天生成的日志,日志生成时间大约在每天的上午 08:00 左右,记录的是前一天所有用户行为日志。

我们在日志中找 com.apple. runningboard_sp_telemetry_ExceededTimeLimit 开头的进程相关日志,他有多种不同类型,包括 ExceededTimeLimit_FinishTask ExceededTimeLimit_BackgroundContentFetching ExceededTimeLimit_BackgroundDownload 分别为后台任务结束超时,后台访问数据超时,后台下载任务超时。该日志格式如下:

该日志还有permittedBackgroundDuration的值,是在当前当前系统上在后台可执行任务的最大时间。 这样,通过结合该日志可以通过hook的方式或者其他方式可以排查app的哪一种后台任务导致被系统强杀。

启动时间横向比较数据

在分析Analytics数据的时候我们发现这一份Daily数据不仅仅是包括后台任务相关的数据还包括启动时间数据。该日志发生的进程为com.apple.FrontBoard_AppLaunch_AppLaunch,Name为AppLaunch,StartProcessName通常是SpringBoard,EndProcessName是启动的进程,DurationInSeconds就是我们想要的启动时间。Xcode中打开DYLD_PRINT_STATISTICS时的启动数据只能获取当前开发的app的数据,该日志包括当天打开的所有App的启动数据。数据格式如下:

"FrameRate": null,

此外还有在com.apple.app_launch_measurement_ApplicationLaunch_ApplicationFirstFramePresentationResponsive进程中发生的ApplicationLaunch的时间,Name为ApplicationFirstFramePresentation,意思为应用的第一帧展示Application启动时间。看到进程名大家可能会想起来了,Xcode工具中Organizer-Metrics-iOS Apps-LaunchTime(Time to  first frame),当然Xcode工具中的数据只能看开发者Team包含的App的数据,Daily数据收集 的是当天打开的所有应用的数据。

图8 iOS Apps-LaunchTime(Time to first frame)

因此我们可以通过该数据获取多个App的启动时间,可以生成横向比较数据,判断我们自己App的启动时间是否有更多的优化空间。

被内存管理系统杀死时App高峰内存

系统日志中包括JetsamEvent开头的日志,主要是由于iOS设备不存在交换区导致的内存受限,iOS内核将优先级低或占用内存过大的进程杀掉后,系统在杀掉APP后记录的数据。可以说是另一类因iOS上能捕获的信号量限制而无法捕获的Crash日志。

Jetsam 日志包含当前设备的活跃内存,非活跃内存,存放内核代码的内存等等详细的内存状态。还包含设备的内存页大小,占用内存最大的 app ,系统杀掉的时候 app 占用的内存页数, app 的状态等等。

图9 JetsamEvent日志格式

那么Jetsam是怎么管理内存的呢?

(1) 监听:

#i#if CONFIG_MEMORYSTATUS //iOS上有Jetsam,低内存事件的常驻监控线程

都是调用kern_memorystatus.c里面暴露的接口,主要的作用就是从内核中开启了两个最高优先级的线程,来监控整个系统的内存情况。

CONFIG_FREEZE

当启用该功能,内核对进程是进行冷冻而不是 KILL ,这个功能通过在内核中启动 memorystatus_freeze_thread 进行,收到信号后调用 memorystatus_freeze_top_process 进行冷冻。

CONFIG_MEMORYSTATUS

启动该功能是针对低内存的情况下,对优先级低或占用内存过大的进行杀掉,入口是 memorystatus_init ,接下来我们重点讲的是 memorystatus_init 的实现。

(2) 处理Jetsam事件:

内核对于所有的进程都有一个优先级的分布,通过一个数组维护,数组每一项是一个进程的列表。这个数组的大小是 JETSAM_PRIORITY_MAX + 1 。其结构体定义如下:

线程在Mach下采用了不同的优先级,其中 MAXPRI_KERNEL 代表的是分配给内核可用范围内最高优先级的线程。

通过创建开启一个内核优先级最高的线程 VM_memorystatus ,这个线程会在维护两个列表,一个是基于进程优先级的进程列表,还有一个是内存快照列表,即保存了每个进程消耗的内存页 memorystatus_jetsam_snapshot

这个常驻线程接受从内核对于内存的守护程序 pageout 通过内核调用给每个 App 进程发送的内存压力通知来处理事件,这个事件转发成上层的 UI 事件就是平常我们会收到的全局内存警告或者每个 ViewController 里面的 didReceiveMemoryWarning

那么在哪些情况下会出现内存压力呢?我们来看一看 memorystatus_action_needed 这段函数:

频繁的的页面换进换出is_reason_thrashing,Mach Zone耗尽了is_reason_zone_map_exhaustion以及可用的页低于一个门槛了memorystatus_available_pages。在这几种情况下,就会准备去杀死进程了。

它会基于某个时间间隔在做条件判断,如果不满足这个判断,后续真正执行的 Kill 也不会走到。到达这段时间后根据优先级进程列表进行寻找可杀目标, jetsam 不是只杀一个进程,会杀掉 N 个进程。

自动化解析工具:

我们通过进入系统的设置中拿到的这些日志,日志的格式有多种,包括第一部分所讲的崩溃日志,以及其他格式的日志无法每个都手动解析。因此我们利用 iOS ShareExtension ,将日志拷贝到A pp 中,根据日志的类型做一个自动解析工具,并且把一些无用的数据进行过滤掉。下面是用Jetsam日志的原始日志以及通过自动化解析工具解析后的效果。

图10 原始系统JetsamEvent日志

图11 解析工具日志列表

图12  JetsamEvent日志解析效果

总结

系统日志 一个苹果系统生成的可以说是比较靠谱的日志,我们目前解析的是一部分 ,可以继续调研系统日志中的其他数据不断优化系统日志的自动化解析工具,帮助我们定位问题

参考文章

https://developer.apple.com/cn/app-store-connect/analytics/

https://www.apple.com/cn/privacy/

http://satanwoo.github.io/2017/10/18/abort/

我来评几句
登录后评论

已发表评论数()

相关站点

+订阅
热门文章