xen tapdisk2 装机重启关闭磁盘过程中发生错误

前不久调到虚拟化这边，主要做xend底层的东西。上来就遇到一个难搞的问题，搞了三周到现在基本还是一点头绪都没有，头都大了，有点无语。

 

在虚拟机安装win2008的过程中，第一次系统安装完成后重启时，发生磁盘I/O读写错误，后面虚拟机安装就直接出错了，领导非常重视，认为这是一个严重的BUG，可能开源xen项目的关机流程有一些问题。写这篇文章时，问题还是没有搞定，先写点，看看有没有大牛做过。先不说了，直接上日志：

Aug 20 11:53:17 localhost tapdisk2[30916]: received 'close' message (uuid = 2)
Aug 20 11:53:17 localhost tapdisk2[30916]: sending 'close response' message (uuid = 2)
Aug 20 11:53:17 localhost tap-ctl: tap-err:__tap_ctl_close: close failed: 11
Aug 20 11:53:17 localhost tapdisk2[30916]: received 'close' message (uuid = 2)
Aug 20 11:53:17 localhost tapdisk2[30916]: sending 'close response' message (uuid = 2)
Aug 20 11:53:17 localhost tap-ctl: tap-err:__tap_ctl_close: close failed: 11
Aug 20 11:53:17 localhost tapdisk2[30916]: received 'close' message (uuid = 2)
Aug 20 11:53:17 localhost tapdisk2[30916]: /opt/zxve/vm/ba42d937-9be5-48ae-b17e-99fcb23dc7b0/faa6cde1-dd08-4958-ae73-8bf0448a526f: b: 10240, a: 3583, f: 3565, n: 14704712
Aug 20 11:53:17 localhost tapdisk2[30916]: closed image /opt/zxve/vm/ba42d937-9be5-48ae-b17e-99fcb23dc7b0/faa6cde1-dd08-4958-ae73-8bf0448a526f (0 users, state: 0x00000000, type: 4)
Aug 20 11:53:17 localhost tapdisk2[30916]: sending 'close response' message (uuid = 2)
Aug 20 11:53:17 localhost tapdisk2[30916]: received 'detach' message (uuid = 2)
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133368
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016671
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016672
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016673
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016674
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016675
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016676
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016677
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016678
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016679
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133456
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133544
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133632
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133720
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133808
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133896
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133984
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16134072
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16134160
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16134248

Aug 20 11:53:18 localhost tapdisk2[30916]: sending 'detach response' message (uuid = 2)
Aug 20 11:53:18 localhost tapdisk2[21101]: received 'pid' message (uuid = 0)
Aug 20 11:53:18 localhost tapdisk2[21101]: sending 'pid response' message (uuid = 0)
Aug 20 11:53:18 localhost tapdisk2[21109]: received 'pid' message (uuid = 0)

 

可以明显看到，tapdisk2 接收一个 detach 消息后，发生I/O错误，此时tapdisk2 进程并没有结束，因为后面还是返回了 detach response，但怎么就会导致I/O错误，而且这个现象也不是必现，有一定的概率，当然事情的前提的是测试环境不存在问题。看看代码里面，tapdisk2 attach 所做的工作：

 

void
tapdisk_vbd_detach(td_vbd_t *vbd)
{
 tapdisk_vbd_unregister_events(vbd); 

 tapdisk_vbd_unmap_device(vbd);
 vbd->minor = -1;
}

 

static int
tapdisk_vbd_unmap_device(td_vbd_t *vbd)
{
 int psize;

 psize = getpagesize();

 if (vbd->ring.fd != -1)
  close(vbd->ring.fd);
 if (vbd->ring.mem > 0) {
  munmap(vbd->ring.mem, psize * BLKTAP_MMAP_REGION_SIZE);
  vbd->ring.sring=NULL;
 }
 return 0;
}

看看这个detach的流程，tapdisk_vbd_unregister_events 只是取消对ring 读写事情的监测，可以排除其导致问题。那么问题就应该是出现在那个该死的tapdisk_vbd_unmap_device中了。初步看看上面tapdisk_vbd_unmap_device干的粗活，也没啥，就一个 munmap ，把映射到自家共享环的内存给释放了，这怎么就导致dom 0 发生 I/O 错误呢，实在是不得其解。

 

在装机的过程中，由于虚拟机此时还没有半虚拟化驱动，虚拟机内部的读写请求都是由 qemu 代理完成，没有 “前段-后端”的概念。此时，qemu 的 I/O 请求最后也是挂接到 blktap 这个虚拟设备上，blktap 和 tapdisk2 直接的 I/O 交换通过 共享环来实现。由于在装机的过程中，会有大量的数据从虚拟机光驱拷贝到虚拟机磁盘，即有可能发生大量请求等待在 blktap 中的可能，此时虚拟机关机后，tapdisk2 收到 close - detach 执行 关闭磁盘镜像、关闭共享映射后，如果 blktap 依旧往一个 不存在的共享环进行读写，又或者blktap 本身也map了该共享环设备/dev/xen/blktap-2/blktap ，但是大量数据写入环，tapdisk2 已经不再读取这些消息，会不会导致内核写入消息发生 I/O错误呢，现在还不得而知。

 

重新看看上面的出错点：

Aug 20 11:53:17 localhost tapdisk2[30916]: received 'detach' message (uuid = 2)
Aug 20 11:53:17 localhost kernel: end_request: I/O error, dev tdc, sector 16133368
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016671
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc
Aug 20 11:53:17 localhost kernel: Buffer I/O error on device tdc, logical block 2016672
Aug 20 11:53:17 localhost kernel: lost page write due to I/O error on tdc

可以非常明显的看出，收到detach 并处理后，内核突然对 tdc （虚拟机磁盘）写错误，xen对虚拟机关机的流程肯定存在问题，而且该问题比较隐藏的比较深。

 

close 的时候已经关闭了磁盘的 img ， detach 的时候仅仅去把共享环干掉，按照逻辑，close前就要保证所有写磁盘的请求全部flush完毕。现在比较疑惑的是，为什么错误没有立刻出现在close后，而是出现在detach的处理中，难道是有一些时间上的延迟，这点有可能，但是不应该这样认为，毕竟出错是立刻出现在detach过程中。

 

这些代码比较多，而且有些恶心，特别是涉及驱动和内核相关的部分，以前虽然也学过一些，但始终没有真正的去做项目。初步感觉非常吃力，但是这个问题一定要解决，这是死命令，思路和头绪都不够清晰，先把问题贴出来。

——————————————————————————————————————————————————

从头到尾将xen 中与tapdisk2 有关的代码都看了一遍。目的tapdisk2关闭磁盘的流程基本是 close-detach-free。在 close 的时候 ，根据 pending_request 来判断是否还有请求没有出来完，当 pending_request = 0 时，此时会调用close ，然后detach ,在 detach的时候会销毁共享环，老大说做个实验，看看 pending_request的值在关机前后的变化。

于是将tapdisk2代码改了改，添加了一些打印函数，最后复现几次装机第一次重启的过程，终于发现在装机时有一定的概率，关机执行 close 磁盘的操作后，pending_request 的确会变成0，但是之后在detach的时，由于我添加了延时处理，以每秒1000次的速度打印出 pending_request 的值，发现该值又变成了 1 。这里看来真的有问题，看来pending_request的值为0不足以说明此刻可以关闭磁盘。因为后面还有数据过来，此后如果执行了 detach ，就会发生错误。

第二天参加了讨论，结果却被同事否决了，说我的复现方法有问题，因为我把close的动作移到 了 detach 里面，而且在 detach 里面添加了延时，以观察 pending_request 的值，如此改变了xen的流程，我顿时哑口无言了，因为我并没有完全搞明白这中间的流程。但是可以肯定的是，目前关闭磁盘的条件是有问题的，既然 以 pending_request为0 作为关键的条件，那么之后就不应该让 pending_request的值又变成非0 。

——————————————————————————————————————————————————

有过了一周多了，目前这个问题还在研究中，主要是看这部分代码。今天终于有点头绪了，请求是从共享环中取出，经过 new_request----- pendding_request 的，说明 pending_request 就是目前没有处理的IO请求，当dom 0完成处理后，内核回调tapdisk2的函数，将请求从 pendding_request 取出，移除到 失败或者完成的链表。而在关机时候，看到 pending_request 为0 ，就关闭了磁盘，说明此时请求都已经处理完毕。但是此后，共享环中又来了数据，导致pending_request 非0，而此时已经走到环销毁的后面了，就导致上面的某个地方会发生访问错误。。

之前，我一直认为是异步IO发生了错误，即异步IO已经提交了，但是磁盘已经关闭，但是提交的异步IO并没有完成，此时当内核真真处理异步IO时，就会发生内核访问错误。而且代码中也的确没有看到对异步IO进行销毁和回收的处理，于是写了一篇分析文档就了事。大致的意思就是说，虚拟机关机后，还是有请求下来，或者关机之前的异步IO并没有全部完成，导致关闭磁盘后，又发生磁盘访问错误。

——————————————————————————————————————————————

有过了两天，在一位师兄对全局流程的疏导下，我终于有了全新的认识。我一直认为是因为内核访问虚拟机磁盘的时候，磁盘已经关闭出错，现在看来我错了，如果是那样，就不应该是tdc 报错，而应该是 sda 什么报错。又分析了一遍代码，关机时，之前的异步IO肯定是全部处理完成了的，因为每次异步IO完成都会回调去处理pending_request ，只有当pending_requset 为0时，才会执行关闭磁盘的动作，说明所有的异步IO都进行了处理，没有残留。那只有一种可能，就是关闭磁盘后，虚拟机内部又来了新的请求，而且这些请求又进入了共享环，此时tapdisk2已经接收到了。但是，之后会不会才提交IO请求导致错误现在还不得而知 ？ 因为 tdc 报错不是下面内核访问磁盘时报错，而刚好相反，却是虚拟机上面操作tap 块设备时报错！！ 一开始我的注意力就看反了，虽然原理都是大致相同，但是方向却相反。不是下面dom 0 访问虚拟机磁盘时出错，而是上面 dom u 访问 tap 块设备时，由于tap 块设备挂的共享环已经消耗，而导致 dom u 访问 tap 块设备报错。。

晕了。。。。看来内核还有驱动设计的书籍还要多看几本。。

——————————————————————————————————————————————

不知不觉，这个问题断断续续的已经过去一个月了，中间经历了国庆。今天已经是十月十二号了，上午老大们又讨论了这个问题。一个比较厉害的老同事来了，问了下我这个问题。在我确信pending_request 从整数变成0，又会变成整数后，他终于确认了。tapdisk2 这个地方处理的的确有问题，tapdisk2只关注了自己队列上面的数据是否已经全部完成，然后就关闭了磁盘。但是此时 xen 虽然已经关闭了 qemu ，但是不能排除 qemu 还有未完成的数据一直在 flush 到 tap 块，但是由于 tap 块是和共享环息息相关的，共享环销毁后，这一个时间段内，qemu flush 的数据就会访问 tap 块失败，内核打印出 kernel tdc error 的错误。

下午老同事已经确认了解决问题的方式，修改了tapdisk2 关机时的判断条件，具体的方案不方便透露。但是有一点就是，在关闭 虚拟机磁盘的时候，一定要保证vbd 的队列和共享环中都已经没有数据，否则不仅会发生内核访问错误，而严重的是，有一些数据在关机时没有被保存到磁盘，那样问题就大了，测试的问题就是装机第一次关闭时数据没有全部保存到磁盘，导致装机后系统无法重启了。

哎，终于分析出了一个可以接受的答案，下一步准备清晰的写下 xen io 的交互流程。我想，这些错误思杰公司是肯定知道的，但是它们却不去解决，因为当xen从开源组织到公司后，为了打败竞争对手，保持思杰的产品有优势，那么这些潜在的BUG它们就不会再去解决了，如果真是这样，那真是开源xen的损失。