一、起因EFC（Elastic File Client）是 NAS 自研的分布式文件系统客户端，最近完成了对缓存架构的更新，现在支持多个客户端之间构成分布式缓存，底层支持 NAS、CPFS 和 OSS。由于开发时间较短，一直没有做 NAS 场景 CTO 测试的适配。CTO：Close-to-Open，指当一个文件被关闭后，再次 open 时，文件系统必须保证之前所有通过 close 操作提交的数据已经持久化到文件系统，并且读取时能获取到最新的、一致的状态。CTO 测试的具体实现是对本地和远端文件系统的文件执行相同的操作，在某些操作后读取两端文件系统的内容，比较是否相同。本地为 EXT4 文件系统，符合 POSIX 语义，远端文件系统跟本地文件系统对比，信任本地文件系统的表现。读缓存的测试是分布式的，单客户端读取由分布式缓存提供服务。最近忙里偷闲适配了一下，静静等待测试的通过，结果没想到发生了 data mismatch 的错误，因为关闭缓存直读 NAS 的 CTO 测试在每次发版前都会跑一遍。得，缓存的锅铁定没跑了，那咱就来看看这个问题。
二、错误类型判断读数据错误？EFC 读缓存在 NAS 场景下会使用 dv（data version）作为缓存的版本号，文件系统数据更新的时候会对 dv 自增。EFC 与文件系统通信的 RPC 会更新本地记录的 dv 信息，EFC 读缓存就会根据客户端手上的 dv 作为版本号从缓存读取数据。由于这个机制的存在，所以 data mismatch 问题一眼认定为：使用了旧的 dv 读到了缓存里的旧数据。看来问题不大，喝口水压压惊。CTO 测试会对本地文件和 NAS 上的文件执行相同的操作，并在执行某些操作后检查读到的文件是否一致。这样在读到缓存旧数据的情况下，本地文件（本地 /root 下）和远端文件系统的文件（NAS /mnt1 挂载下）内容是相同的。由于 mnt1 还是通过 EFC 客户端进行挂载，读取数据还是走的缓存，依然存在读到旧数据的可能。因此，为了排除 EFC 缓存的影响，使用 NFS 协议挂载了 NAS 文件系统后（不通过 EFC 进行挂载），通过 diff 比较本地和 NAS 上的文件内容，结果两者竟然不一致。结果表明，文件系统数据被破坏掉了，也宣告着读到缓存中的旧数据的想法破产。写数据错误！调查过程陷入困局，决定看一下错误文件的内容有没有新的发现。由于原始文件存在大量的不可见字符，因此使用 hexdump 将文件转成 16 进制格式，每行显示 16 个字符。左侧为本地文件，右侧为 NAS 上文件，可以看到 NAS 上文件中的字符 f (0x66) 被替换成了空字符 NULL (0x00)。但是 CTO 测试中并不会主动写入空字符，这些空字符是如何产生的呢？计算错误字段的开始位置和结束位置：mismatch start = 0x94250 = 606800，mismatch end = 0x94ee0 + 2 = 610018，对一个 4K 页整除可以发现错误段正好位于一个 page 内。这个 CTO 数据不一致问题几个小时的运行可以复现，每次结果的表现是一致的，均是正常字符被替换为空字符以及错误数据位于同一个 page 内（出现过数据错误开始位置正好 4K 对齐）。这个时候开始把思路转向为：由于缓存的引入写坏了本地的 pagecache，当脏页需要刷到文件系统的时候把 pagecache 里的旧数据一并刷到了文件系统，造成了文件系统数据的不一致。明确了问题后，现在的困扰来到了是什么操作写坏了 pagecache，以及空字符是如何产生的呢？三、日志调查在整个 CTO 测试期间，分析 EFC 缓存的日志，存在 6 条读缓存日志，并且命中缓存的仅有 3 条，错误也就发生在这 3 次读操作中。结合错误数据的 start offset (606208) 和 end offset (606208 + 3908 = 610116) 最终可以定位到第 3 次的读操作出错（606208 < 606800 < 610018 < 610116）。进一步查看 CTO 测试日志，记录了每次读写操作的信息。可以看到，首先通过 op_write_append 操作追加写字符 f (0x66)，写的数据会首先存储在内核的 pagecache 中，然后通过 op_truncate_big 通知文件系统扩充文件长度到 610116，这样还没有被刷到文件系统的数据就是空字符 NULL (0x00)。接着通过op_fsync 将本地 pagecache 中的数据刷到文件系统。之后再通过 op_write_append 追加写字符 g (0x67)。结合缓存的引入造成 pagecache 被写坏，分析第一个 op_write_append 的行为：1.1：向内核 pagecache 中写入数据 f，pagecache 标记为 dirty；1.2：向文件系统 setattr，扩充文件长度，扩充内容用 NULL 填充，文件系统数据的版本 dv1 → dv2；1.3：另一个 EFC 客户端在缓冲不命中的情况下，从文件系统读取了 dv2 版本的 NULL 数据，并写到分布式缓存中；1.4：在某个时刻（可能是主动 fsync 或者内核逻辑），pagecache 中的脏数据被刷到文件系统，NULL 被覆盖为 f，文件系统数据版本 dv2 → dv3；接着分析第二个 op_write_append 的行为：2.1：由于 direct 设置为 0，是一个 buffer 写操作，会先读取数据到 pagecache 中。由于缓存的存在，读取到了 dv2 版本的数据到 pagecache 中，填充为 NULL。2.2：向内核 pagecache 中写入数据 g，pagecache 标记为 dirty。2.3：向文件系统 setattr，扩充文件长度，扩充内容用 NULL 填充，文件系统数据的版本 dv3 → dv4。2.4：pagecache 中的脏数据被刷到文件系统，NULL 被覆盖为 g，但是正确数据 f 被覆盖为 pagecache 中的 NULL，造成了文件系统数据不一致。由于 buffer 写先读后写的行为，从缓存中读取到了旧版本的 dv2 数据，但是文件系统的数据已经更新到 dv3 版本，使用最新的 dv3 读取数据应该会缓存失效，直读文件系统才正确（直读文件系统读取 dv3 数据 f 到 pagecache 中也不会存在 NULL 刷到文件系统造成数据不一致的问题）。而 EFC 客户端对每一个文件都会本地记录一个 dv 号用于读文件系统，推测 dv 发生了回退，查看 EFC 缓存日志也可以观察到 dv 回退的现象（5676 → 5675）。分析后认为漂移在网络上的慢读请求会造成 dv 回退现象发生：假设存在一个 read 请求，从文件系统读到了 dv2，但是迟迟没有返回。而在中途其他的 write 更新了文件系统的 dv3，并通过 RPC 更新本地版本为 dv3。之后，慢 read 带回来 dv2 的数据到缓存中，且又使用 dv2 覆盖了客户端记录的 dv3，后续用 dv2 读取缓存就会读到旧数据。四、问题复原根据上述分析，错误的原因总结为：缓存读到了追加写操作中文件系统填充为 NULL 的数据，这部分数据在下一次 buffer 写操作中被读取到 pagecache 中，再被新数据写脏后刷到文件系统，缓存中的旧数据 NULL 破坏了文件系统数据，造成数据不一致。可以复原出写坏文件系统数据的整个流程：client1 发起 append write，分为 write 和 setattr；write 写数据 f 到 pagecache 中；setattr 请求会发到文件系统扩充文件长度，扩充部分填充为字符 NULL；client2 发起 read，读到数据空字符 NULL 写到缓存中；client1 将 pagecache 中的数据 f 刷到文件系统；client1 再次发起 buffer write，分为 read 和 write；client1 拿到旧的 dv，读缓存读到旧数据 NULL（buffer write 会先读取数据到 pagecache），缓存中的数据读到 pagecache 中；client1 write 了另一部分脏数据 g 到 pagecache 中（位于同一个 page）；client1 将 pagecache 中的数据 NULL + g 刷到文件系统，原来的数据 f 被覆盖为 NULL，造成了文件系统数据的错误；问题的根本原因在于：版本号发生回退，客户端使用了旧版本号从缓存中读到了旧数据。问题分析清楚后，还是比较好修复的，在本地维护了一个递增的缓存版本号，丢弃 RPC 收到的发生回退的版本号即可。使用修复后的版本重新运行 CTO 测试，10 轮次近 30 个小时无数据不一致发生，可以认为问题得到修复。五、部分 POSIX 接口底层揭秘 到此为止，文件系统数据写坏的问题已经分析得差不多了，但是还是对内核发到 EFC 客户端的请求存在一知半解。纸上得来终觉浅，绝知此事要躬行。于是，写了一个简单的 python 程序模拟上述操作，模拟用户对文件进行操作，观察 EFC 客户端收到的内核请求信息：1. open调用 open 打开文件；2. fstat调用 getattr 获取文件大小；3. pwrite在文件结尾（1M）追加写 1K 长度的字符 f。在 26s 执行时并未向 EFC 客户端发送请求，此时将数据 f 写到内核 pagecache 中；在 31s ftruncate执行时调用 setattr 扩充文件系统文件长度，并调用 write 将 pagecache 中数据写到文件系统；4. ftruncate扩充文件长度为 2K，和 pwrite一起仅触发一次 setattr 调用；5. fsync调用 fsync 将 pagecache中数据显式刷到文件系统；6. pwrite继续在文件末尾（1M + 1K）追加 1K 长度的字符 g。在 42s 执行时调用 read 读取数据到内核的 pagecache 中，并将数据 g 写到内核 pagecache 中；在 47s close执行时调用 write 将 pagecache 中数据写到文件系统，调用 setattr 更新文件属性。7. close调用 flush 再次保证 pagecache 中数据刷到文件系统，调用 release 关闭文件；由于内核会对用户的操作进行很多优化，很难将内核的行为一一罗列，这里仅对本次模拟过程中内核行为和用户操作不同的地方进行介绍：setattr 触发机制用户操作：pwrite（写入1K）与 ftruncate（扩展2K）均涉及文件长度扩展。内核行为：仅在 ftruncate 时触发一次 setattr 请求，扩展文件长度至最终值（1M + 2K）。差异点：pwrite 本身不会直接触发 setattr，而是依赖后续 write 或 ftruncate 的操作。pwrite 的 1K 写入被缓存在 pagecache 中，最终与 ftruncate 的 2K 扩展合并为一次 setattr 请求。buffer write 的 pagecache 延迟提交用户操作：pwrite（26s）写入 1K 数据，但未立即触发内核请求。内核行为：数据先写入 pagecache，直到 ftruncate（31s）或 fsync（36s）触发 write 请求时才提交至文件系统。差异点：用户需注意 pwrite 仅为用户态写入，实际落盘需依赖 write 或 fsync。buffer write 先读数据到 pagecache用户操作：第二次 pwrite（42s）在文件末尾追加 1K 数据。内核行为：内核先通过 getattr 和 read 请求读取目标页（4K）到 pagecache，再执行写入。差异点：当写入位置超出当前 pagecache 范围时，内核会主动读取缺失页以保证写入完整性。setattr 与 write 的顺序问题用户操作：ftruncate 扩展文件长度后，pwrite 数据需写入新扩展区域。内核行为：setattr 先扩展文件长度，填充 NULL 字符；write 请求将 pagecache 数据写入文件系统时，才真正填充空洞区域。差异点：若在此期间读取文件，可能读取到未填充的空洞数据（本文 bug 读取到缓存的数据就发生在这次 setattr 和下一次 write 之间）close 的双重作用用户操作：close 仅视为关闭文件。内核行为：触发 flush（47s）确保数据持久化，并调用 release（47s）释放资源。差异点：close 隐含了数据刷盘操作，即使未显式调用 fsync。六、心得体会这个错误从发现到最后解决耗时了半个多月，从开始时发现文件系统错误时的迷茫，到发现空字符的错误数据以及位于一个 page 内，提供了 pagecache 写坏刷到文件系统的想法，之后不断根据日志分析可能存在的写坏文件系统操作，并验证猜想。整个过程还是比较坎坷的，也学到了很多新知识：比如 buffer 写会先读后写，append 写会对文件系统扩充字符先填充为空字符，以及在网络上漂移的慢请求带来的异常影响等。后续在分析问题以及开发过程中，有了这些先验知识，就可以考虑得更为全面，在这里分享给大家。
