一个有趣的和时钟相关的bug

前几天解决了一个bug（6563730），感觉整个解决的过程很有趣，觉得有记录下来的必要。

这个bug的现象很奇怪，某些硬件（主要是Sun Fire X2100 M2/X2200 M2）上运行的Solaris的dom0（简称为：i86xpv平台）上的时间跑的比普通Solaris（直接运行在硬件上的Solaris - i86pc平台）快。经过测试发现，普通的Solaris运行60秒，Solaris dom0的时间过了70秒左右。但是，运行在同一个机器上的Linux dom0并没有发现类似的现象。

一开始，大家对这个bug都有些发懵，觉得有点丈二和尚的感觉。最开始研究这个bug的工程师经过一段时间的调试，发现这个bug和USB的EHCI控制器的驱动有关。而USB驱动的开发小组就在中国，和我在同一个办公楼里，交流方便。于是，这个bug就被转到了我手中（我们小组只有我一个人在中国，其他人都在美国或英国）。

之所以说有可能是EHCI驱动程序的问题是因为我们发现时钟运行速度突变是发生在EHCI驱动加载的时候。具体来说，是当EHCI驱动在初始化的时候将一个EHCI设备寄存器的某一个比特置位时，时钟运行速度突然变快了。看起来确实像是EHCI驱动的问题。但是，我的USB知识有限，只好请USB组的工程师帮忙了。经过了大约两周的忙活（主要是那位被我抓住干活的USB组的工程师在忙活，谢谢啊），我们觉得似乎从USB这边是无法解决这个奇怪的问题了。他都快要把Solaris的EHCI驱动改成和Linux一样了（晕！），但是还是看不到一丝效果。无法理解为什么Linux的dom0没有这个问题。。。

于是我只好把bug拿回来仔细看看。我对于Solaris和Xen里面时间的处理没有什么概念，只好从头看起了。我们重现这个bug的方式是同时在Solaris dom0和普通Solaris里面运行‘date’命令，并重复几次。这样就可以发现时间运行速度的差异了。于是，先看看date命令吧。用truss发现date通过系统调用time来取得系统当前的时间。我找到time系统调用在内核中的处理函数（usr/src/uts/common/os/sysent.c）是gtime()。然后一直跟着代码gtime()->gethrestime_sec()->gethrestime()->gethrestimef()->pc_gethrestime()->gethrtime()->gethrtimef()->dtrace_xpv_gethrtime()。这里需要注意的是，在i86pc上，gethrtime()调用dtrace_gethrtime()，而在i86xpv平台调用的是dtrace_xpv_gethrtime()。

其实，这个地方是我们把Solaris移植到Xen上需要进行的平台相关的改动之一：读取高精度（以纳秒为单位）时间的方式变化了。在i86pc上，事情相对简单些。在dtrace_gethrtime()中，我们读取到CPU的本地TSC计数器的当前值tsc，找到自从上次tsc_last更新后（tsc_tick()每秒钟更新一次tsc_last）的变化量delta（ = tsc – tsc_last）并将其转换成为以纳秒为单位的时间（TSC计数和纳秒的转换关系在CPU启动的时候就确定下来了，存放在nsec_scale中）。于是，在i86pc平台上，Solaris利用BSP的本地APIC（Local APIC）定时器定时产生时钟中断，每秒钟读取TSC计数一次（并写入tsc_last），来跟踪时间至秒的精度。并且在两次tsc_last更新期间，通过读取TSC计数的差值来跟踪时间至纳秒的精度。

Solaris i86pc对时间的处理是基于一个假设：TSC计数器的频率是恒定不变的。这个假设对于在物理机器上运行的Solaris是十分合适的（CPU的运行频率总不会一会儿快一会儿慢吧）。但是对于虚拟机来说就不一定成立了。因为虚拟机运行的真实运行硬件平台是不确定的。OS在运行过程中随时有可能会被迁移（migrate）到另外一个硬件平台上去运行。那么在该OS的生命周期之内CPU的运行频率就无法保持不变了。因此，TSC计数和时间的对应关系就有可能在虚拟机完全不知情的情况下发生变化。因此，时间相关的信息需要Xen来直接告诉虚拟机。

Xen定义了一个时间相关的数据结构（每个虚拟CPU都包含一个）：vcpu_time_info_t（usr/src/uts/common/xen/public/xen.h）。这个数据结构中的内容是由Xen来更新（当虚拟CPU被调度运行的时候更新），OS只是从中读取需要的信息来跟踪时间的流逝。其中system_time是OS到目前为止运行的时间（单位：秒），tsc_timestamp是当Xen更新system_time时候的TSC计数，tsc_to_system_mul是一个因数，用来表示TSC计数和时间的对应关系。于是通过类似dtrace_gethrtime()的算法，dtrace_xpv_gethrtime()也就可以知道当前的时间了。最重要的一点是在读取这个数据结构的时候必须保证数据的一致性（包括所有数据结构的各个成员和当时的TSC计数值）。显然我们无法用一个原子操作来保证一次读取到所有的数据。因此，Xen在这个数据结构中增加了一个成员：version。Xen在更新这个数据结构的时候会改变version的值。因此，只有当我们开始读取这些数据和读取完毕的时候version没有发生过变化，我们才认为数据的读取是可靠的。

代码读到这里，似乎没法从Solaris里面找到问题了（dtrace_xpv_gethrtime()的实现很简单，也没有什么错误）。没办法，只好接着往底下挖了，看看是不是Xen把时间搞错了。。。这里写起来好像是挺简单的决定，但是越走下去心越虚。因为Linux dom0没有出现类似的问题这个事实总是在脑子里面挥之不去。大家都使用的同一套Xen的代码呀，这样看来，问题应该是出现在Solaris内部了。进一步挖掘Xen的代码，是不是在走弯路呢？

万般无奈，只好接着调试一下Xen的代码了，弯路就弯路吧，总比没路可走强。经过一些实验，我发现tsc_to_system_mul这个值在EHCI驱动加载前后发生了较大的变化。加载之前，这个数字虽然也不是恒定的，但是变化比较小（十六进制表示的时候，高5位都不发生变动）。但是在加载后，变动就比较明显了（十六进制表示的时候，最高位都会发生变化）。这里面肯定有问题！！因为TSC计数和时间的对应关系不会有如此大的变动的。否则，Solaris i86pc的时间计算就肯定出错了。在Solaris i86pc中，TSC计数和时间的对应关系是CPU启动的时候进行校准的，之后不再改动了。从这可以看出来Solaris对于TSC的频率的稳定是深信不疑的。Xen的代码对于时间的处理似乎比Solaris更加复杂。它好像并不像Solaris一样对TSC计数器的频率那么相信。Xen使用一个在主板上的外部时钟源每隔一段时间校准（调用local_time_calibration()）一次TSC计数和时间的关系。它的校准算法很简单。首先从外部时钟源读取时钟的计数变化（自从上次校准时的计数变化），再读取TSC计数的变化。将两者进行比较后就得到对应关系。嗯，看上去没有什么问题。那么，唯一可能影响对应关系的计算结果的因素应该是外部的时钟源自身的计数频率出问题了。如果真是这样，那么用一个本身计数频率就不准确的时钟来校准TSC的计数频率，得到的只能是错误的结果。

看来需要研究一下Xen所相信的那个时钟源是不是有问题了。主板上的外部时钟源倒是有好几种，例如PIT时钟和HPET时钟。Xen在这个出问题的硬件平台上所使用的是PIT时钟（HPET看来还是太先进了，目前还不是每个主板都提供的）。PIT时钟硬件上提供三个计数器：计数器0（PIT0）是用来产生整个系统的心跳时钟中断的（IRQ0），计数器1（PIT1）是用来给DRAM提供动态数据刷新的时钟中断的，而计数器2（PIT2）则被Xen用来作为校准用的时钟源。TSC的计数频率是由CPU的运行频率，似乎没有理由出问题。而PIT的1.193MHz的时钟频率更是业界几十年的标准，已经在主板硬件上做死了，谁也没法改，怎么可能忽快忽慢呢？！看来要搞清楚到底是TSC的计数频率出了问题还是PIT2的频率出了问题还真是挺让人头疼的一件事情。现在需要找一个经过验证，绝对没有问题的第三个时钟来校准PIT2了。还好，主板上带的RTC似乎没有受到任何干扰，一直在正常的运行。这是因为当机器上运行Solaris dom0一段时间后，立即重起进入BIOS，发现RTC时钟并没有变快。好，终于有一个可以让人相信的时钟源了！尽管RTC的分辨率低了些，但是作为校准足够用了。于是，我先在IRQ0的中断处理函数中读取RTC的值来校准PIT0，发现PIT0一直都工作在1.193MHz的频率上，没有发生过任何问题。于是，我再在IRQ0的处理函数中读取PIT2的计数值。结果终于出来了，当EHCI驱动加载时修改那个寄存器的瞬间，PIT2的计数频率发生了突变（狐狸尾巴开始显现了，哈）！

但是问题开始变得越来越神秘了。搜索了Xen的整个代码树，自从PIT2在Xen启动的时候被初始化好了以后，没有任何代码再碰过它。那是什么原因使得PIT2的计数频率发生了突变呢？Solaris运行时，它的任何一个应用程序根本不会去修改PIT2的配置。Solaris的内核也从来没有使用过PIT时钟。Xen的代码在初始化后也没有再修改过PIT2的设置。好像是有一个神秘的力量，当EHCI初始化一个寄存器的时候修改了PIT2的配置，导致PIT2的计数频率发生了改变。

如果不是Solaris的应用程序，也不是Solaris的内核，也不是Xen，那么当时有可能进入犯罪现场的就只有BIOS的代码了。可惜，BIOS的代码不对我开放，只好和做主板的公司联系一下了。于是我们开始了近一个月的马拉松式的交流。双方的知识背景相差较大：他们完全不知道Xen，也从来没有使用过Solaris。我也完全看不明白他们发过来的PIT硬件设计图。交流的初期还真叫一个乱。在两个公司领导的大力支持下，在双方工程师彼此之间的相互信任和配合下，我们终于成功的在他们公司内部的一台机器上重现了问题。万里长征迈出了艰难的第一步。之后，我们就找到了共同语言，事情的进展就比较的顺利了。功夫不负有心人，最终，我们发现了罪魁祸首。。。

原来，当EHCI驱动初始化那个寄存器的时候引发了一个SMI中断，系统进入了SMM模式，BIOS的代码开始运行。BIOS的代码要让机器的扬声器发出“哔”的一声（真是没事瞎添乱），因为BIOS侦测到USB设备状态发生了变化。而PIT2的一个重要的职责就是负责给扬声器提供一定频率的方波，来发出所需的声音，所以BIOS改动了PIT2的设置来产生所需要的频率。。。

后来经过一通google才知道，Linux在启动系统的时候就禁掉了SMM。。。

先转过来放着吧，太难了，抽空再研究