以小窥大：IO卡顿探寻苹果文件系统

用户瞎胡闹

作者：rhythmzhang，腾讯WXG客户端开发工程师从一个不寻常的I/O卡顿入手，发现苹果APFS的一个严重bug。近期有用户反馈频繁遇到了一个奇怪的严重卡顿问题，微信刷朋友圈和查看聊天都非常卡，主线程卡在最普通的access,rename等常见I/O系统调用，并且经常卡上百ms，而这种场景的底层接口一般都没干什么大量的I/O操作。比如access接口也就是获取文件是否存在的轻量操作，正常耗时都只有几十us而已，远达不到此时的上百ms耗时。一、分析问题寻找关键堆栈堆栈上看，只是很常规的视频号卡片列表滑动时，触发了下载和查本地缓存的逻辑，通过access接口同步查本地是否存在，有则直接展示，否则从网络下载，下载完成时再尝试删除可能已有的旧文件。这完全是一个非常简单的缓存和加载逻辑。通过搜寻卡顿报告，发现子线程都疑似存在大量的并发I/O操作，那是否卡顿的主因是和并发I/O有关呢？尝试触发子线程并发I/O这个目录的，并打日志输出access接口的平均耗时，一切正常。走查功能也一切正常，毫无卡顿。有同学说可能是目录下文件过多才会有I/O问题，在对应目录下构造了足够多的文件，再次走查业务功能，还是一切正常。最终在多次试验和猜测后，构造出了一个高概率复现的场景，在对应目录下写入10万个小伪造数据，并触发并发I/O，此时问题终于复现了。这个时候如果触发视频号卡片滑动，朋友圈卡片滑动，就大概率必现严重的滑动掉帧和卡顿了。构造必现代码大概知道了必现路径后，我们构造出了一个必现代码，打开Instruments的SystemTrace分析，结果如下：发现access等常规I/O接口的平均耗时依旧很低只有几十us，但等待耗时波动很大，可以达到140ms，也就导致了主线程每次查询存在状态时，单次调用耗时超过了140ms，而滑动过程中大概存在十几次这样的行为，那最终就是每次滑动都要因为这些I/Owaittime导致滑动耗时数秒之久，甚至个别情况下还会因此滑动卡死触发watchdog。继续分析Instruments报告，发现等待的主因如下：willwaitforevent/lockxxx.经过前面的研究，我们已经能够构造一个必现demo了。大概如下：特定目录下写入大约10万个文件主线程触发频繁的access接口调用，统计平均耗时子线程触发对该目录下的文件遍历并频繁的rename操作调用，统计平均耗时如果2和3是同一个目录且当前目录文件数较多时，那么会高概率稳定复现平均access和rename等I/O接口调用调用耗时过高的问题。而其它情况组合下，都不会复现这个问题。测试工程跑在MacBookPro(2019)macOS12.3上，会定时benchmark测access接口耗时。  int retry = 5;  long long duration = benchmark(retry,^{    access(path.UTF8String, F_OK);  });  if(duration > 1000 * retry) {    //avg >1 ms.    LOG_P("lag: avg access %.3f ms",duration*1.f/1000/retry);  }在APFS分区的该目录下会频繁因大目录并发I/O遍历导致access超时问题，log输出如下：  lag: avg access 2.134 ms  lag: avg access 11.859 ms  lag: avg access 5.483 ms  lag: avg access 5.259 ms  lag: avg access 4.634 ms这时在x86的ssd设备上都能稳定复现出access调用平均耗时1ms以上，个别情况下可以达到几十ms，确实令人费解。dtrace分析既然Instruments告诉我们耗时的主因是waitforlock，那接下来我们尝试分析下到底在wait什么lock最多。这就需要借助于dtrace来进一步分析了。DTrace即动态追踪技术（DynamicTracing），是内核提供的高级动态调试能力，可以帮助开发者快速调试定位一些奇怪的疑难杂症。操作系统会在内核的一些关键调用操作里提供trace代码执行的入口，我们可以通过注入trace命令或代码来实现自定义trace分析。XcodeInstruments本质就是基于内核提供的dtrace能力来封装并实现的。由于iOS平台不支持自定义dtrace（虽然Instruments就是基于dtrace的，但iOS即便越狱了也没办法触发自定义dtrace行为），我们只有基于macOS打开dtrace分析下这个时候到底发生了什么。运行demo，多次跑如下dtrace命令分析demo运行状态。sudo dtrace -n 'lockstat:::adaptive-block { @[stack()] = sum(arg1); }' -p 95637sudo dtrace -n 'profile-999 /arg0/ { @[stack()] = count(); }'  -p 95806sudo lockstat sleep 10得到的dtrace相关数据如下：  kernel`0xffffff8005aa6990+0x72  apfs`apfs_vnop_rename+0x94  kernel`vn_rename+0x4ae  kernel`0xffffff8005d42020+0xb12  kernel`unix_syscall64+0x1fb  kernel`hndl_unix_scall64+0x16  1367  kernel`lck_mtx_lock_spinwait_x86+0x2be  kernel`vn_rename+0x4ae  kernel`0xffffff8005d42020+0xb12  kernel`unix_syscall64+0x1fb  kernel`hndl_unix_scall64+0x16  2242  kernel`0xffffff8005aa67f0+0x7e  kernel`namei+0x9f7  kernel`0xffffff8005d375a0+0x79  kernel`0xffffff8005d42020+0x35b  kernel`unix_syscall64+0x1fb  kernel`hndl_unix_scall64+0x16  2262R/W writer blocked by readers: 239 events in 10.048 seconds (24 events/sec)Count indv cuml rcnt      abs Lock                   Caller                  -------------------------------------------------------------------------------  227  95%  95% 0.00 13385718 0xffffff8b638223e0     apfs_vnop_lookup+0x2f6     11   5% 100% 0.00  8140855 0xffffff8b638223e0     apfs_vnop_getattr+0xc4      1   0% 100% 0.00  2610265 0xffffff90339a97b0     omap_get+0x7c           -------------------------------------------------------------------------------R/W reader blocked by writer: 192 events in 10.021 seconds (19 events/sec)Count indv cuml rcnt      abs Lock                   Caller                  -------------------------------------------------------------------------------  129  67%  67% 0.00  6408120 0xffffff8b638223e0     IORWLockWrite+0x90         22  11%  79% 0.00    23902 0xffffff99cd1fbc00     IORWLockWrite+0x90         12   6%  85% 0.00    28194 0xffffff804e970608     IORWLockWrite+0x90          4   2%  87% 0.00    18808 0xffffff8048892e08     IORWLockWrite+0x90          3   2%  89% 0.00    41491 0xffffff803825e608     lck_rw_lock_exclusive_check_contended+0x93    2   1%  90% 0.00    22725 0xffffff99cd1fbc80     IORWLockWrite+0x90          2   1%  91% 0.00    78215 0xffffff8b666c2610     IORWLockWrite+0x90          2   1%  92% 0.00    34049 0xffffff8b666c22c8     IORWLockWrite+0x90          2   1%  93% 0.00    23949 0xffffff8b666bc4c0     IORWLockWrite+0x90          2   1%  94% 0.00    28546 0xffffff8b666b94c0     IORWLockWrite+0x90          2   1%  95% 0.00    38088 0xffffff804e97ab08     lck_rw_lock_exclusive_check_contended+0x93    2   1%  96% 0.00    17158 0xffffff803dc78d08     0xffffff8005aa77d0          2   1%  97% 0.00    18658 0xffffff803dc78d08     IORWLockWrite+0x90          2   1%  98% 0.00    29096 tcbinfo+0x38           IORWLockWrite+0x90          1   1%  98% 0.00    52994 0xffffff8b666be7a0     IORWLockWrite+0x90          1   1%  99% 0.00    20135 0xffffff8048892e08     0xffffff8005aa77d0          1   1%  99% 0.00    18584 0xffffff80345de608     IORWLockWrite+0x90          1   1% 100% 0.00    13805 0xffffff803825e608     IORWLockWrite+0x90      -------------------------------------------------------------------------------通过dtrace的lockstat数据，大概率怀疑是kernel层的APFS相关的 lock出了问题，那为什么APFSlock会导致如此严重的问题呢？Hopper分析rename和access都是系统调用，他们都是XNU里VFS注册的系统服务。APFS的系统支持是通过系统的apfs.kext内核扩展载入的，我们通过Hopper打开apfs.kext，分析下APFS对应的rename或access里到底干了什么_apfs_vnop_renamex{    r12 = arg0;    r14 = *(int32_t *)(arg0 + 0x40);    r14 = r14 & 0xfffffff7;    if (r14 90G的占用。WebKitWebKit的网络缓存默认在/Library/Caches/WebKit/NetworkCache/，按照WebKit源码NetworkCacheStorage里的实现，WebKit会采取一定随机+权重的方式删除网络缓存，但是极端情况下，个别用户会因此而占用10G或更多的存储空间。也就是这个随机删除存在很大的随机性。NSURLCacheNSURLCache自定义磁盘缓存路径时，如果diskCapacity设置过大，会导致占用超大存储空间，同时也会导致网络请求因为I/O读写慢而变慢。删除文件实测部分情况下删文件的I/O量基本等于写文件的I/O量，而且密集删文件时会容易导致I/O性能下降过快。因此业务应尽量避免短时间大量密集I/O。三、结论SystemTrace数据表明：当并发I/O遍历的文件目录是同一个时，Instruments报告里的willwaitforlockxxx会显示为同一个，也就进一步证明了APFS内部存在某种目录锁的结构，当对同一个目录的文件进行遍历I/O操作时，都会先请求加解锁。而在超大目录遍历时这个加锁导致的等待问题会急剧扩大，导致锁等待超时，最终可能导致了并发I/O速度骤降的问题。为了避免这种极端情况导致的I/O性能骤降问题，移动端app也需要合理的设计存储结构。例如需要分层分级管理文件，尽量不要将单个文件夹或单个文件搞的过大，同时也需要定时清理临时缓存目录，来进一步优化存储空间占用和优化I/O效率。四、附录苹果从iOS10.3开始引入了APFS，而在此之前HFS+一直是作为iOS和macOS的文件系统。应用程序是如何从ssd等存储介质上读写文件的呢？如下图：VFSVFS统一并抽象了不同文件系统的接口，使得用户可以通过统一的系统调用接口去访问不同文件系统不同存储介质上的文件。VFS主要可以被抽象为3层，vfstbllist用于管理不同的文件系统，mount管理文件系统的挂载，vnode则抽象代表了文件和文件夹等对象。vfstbllistXNU中主要使用vfstbllist来注册管理多个文件系统，典型的vfstlblist如下：/* * Set up the filesystem operations for vnodes. */static struct vfstable vfstbllist[] = { /* HFS/HFS+ Filesystem */#if HFS { &hfs_vfsops, "hfs", 17, 0, (MNT_LOCAL | MNT_DOVOLFS), hfs_mountroot, NULL, 0, 0, VFC_VFSLOCALARGS | VFC_VFSREADDIR_EXTENDED | VFS_THREAD_SAFE_FLAG | VFC_VFS64BITREADY | VFC_VFSVNOP_PAGEOUTV2 | VFC_VFSVNOP_PAGEINV2, NULL, 0},#endif /* Sun-compatible Network Filesystem */#if NFSCLIENT { &nfs_vfsops, "nfs", 2, 0, 0, NULL, NULL, 0, 0, VFC_VFSGENERICARGS | VFC_VFSPREFLIGHT | VFS_THREAD_SAFE_FLAG | VFC_VFS64BITREADY | VFC_VFSREADDIR_EXTENDED, NULL, 0},#endif#ifndef __LP64__#endif /* __LP64__ */    ... ... {NULL, "", 0, 0, 0, NULL, NULL, 0, 0, 0, NULL, 0}, {NULL, "", 0, 0, 0, NULL, NULL, 0, 0, 0, NULL, 0}};内核可以动态的通过vfs_fsadd等接口来加载不同的内核扩展，以启用并支持新的文件系统。mount文件系统只有被mount挂载后才可以被访问。对于内核支持的文件系统，macOS会自动从/System/Library/FileSystems里找到对应的内核扩展并挂载，而对于内核不支持的文件系统，则需要触发一次kext加载操作以支持对应的文件系统。macOS上常见的mount操作如下图：vnodevnode是VFS中最主要的组成。一个vnode可以代表一个文件或特定的一个文件系统对象。一个vnode一般对应实际的文件系统的对应inode。HFS+HFS+(HierarchicalFileSystemPlus)是MacOS8.1（1998年）开始引入的文件系统，同时也是iOS10.3以前默认的文件系统。HFS+能更好的利用磁盘空间，使用unicode存储文件编码，提供了更多当时来说更现代的文件系统支持。HFS+使用了CatalogFile来存储目录结构。CatalogFile的引入极大的提升了文件系统的查找速度，但也导致了所有I/O都会因为频繁访问CatalogFile而被迫串行等待，导致超大并发性能会有较大下降。APFSAPFS(AppleFileSystem)是苹果推出的最新文件系统，它是HFS+的接任者，解决了HFS+在更现代的文件系统上所缺失的能力。APFS为ssd而设计和优化，新增了cloning,snapshots,spacesharing,fastdirectorysizing,atomicsafe-save,sparsefiles等特性，并补齐了苹果在现代文件系统能力上的缺失。苹果的APFS和安卓设备的F2FS类似，都是专门为移动设备而优化的文件系统。二者设计上有很多异曲同工之处。以rename调用为例，开发者通过触发rename系统调用向VFS请求文件操作，VFS触发vn_rename调用，如果当前目录使用的分区是APFS，则最终会触发apfs_vnop_renamex，而如果是HFS+分区，则会触发hfs_vnop_rename调用，最终完成rename操作。五、参考MacOSXandiOSInternals:TotheApple'sCoreMacOSandiOSInternals,VolumeII:KernelModeDTraceFileSystemProgrammingGuideHFSPlusVolumeFormatAppleFileSystemReferenceAppleFileSystemGuideXNU七夕彩蛋