予焦啦!附录:诡异的时间中断(timer interrupt)搁置位元(pending bit)

3.0 那一篇,笔者介绍时间中断与简单的实作。也许也有读者注意到了不太顺畅的部分,那就是直接跳跃到作业系统模式去控制,却没有说明机器模式的中断相关控制暂存器的机制。

是的,本来应当好好地从机器模式开始讲起。然而笔者发现,当 OpenSBI 行进至要进入 ethanol 之前,当时的 mip 状态暂存器竟然已经有非 0 的值。若是其它中断的搁置指示也就罢了,但实际上搁置的是 MTIP 位元,也就是说,已经有机器模式的计时器中断被搁置了!

当时决定先打通作业系统模式,看起来运作上也没有问题,但本篇就用来深入检讨,为什麽会有这种状况。

问题:收敛之後

很容易可以确定 QEMU 在最初始时,给的 mip 是没有搁置的中断的。而且,位在 0x2004000-0x2004020 的 4 组 mtimecmp 控制暂存器也都没有设定初值。位在 0x200bff8 的共享 mtime 状态暂存器则已经透过 QEMU 自己的机制开始计时。以上都符合预期,问题在於为什麽到了 OpenSBI 准备要交棒之时,竟然已经出现了搁置位元

既然出现的是计时器中断,那麽我想,这个搁置位元势必与初始化 mtimecmp 控制暂存器脱不了关系。在 OpenSBI 当中几经查询之後,於 lib/utils/timer/aclint_mtimer.c 之中的 aclint_mtimer_warm_init 函数,找到:

        /* Clear Time Compare */
        mt_time_cmp = (void *)mt->mtimecmp_addr;
        mt->time_wr(true, -1ULL,
                    &mt_time_cmp[target_hart - mt->first_hartid]);

        return 0;

设置初值(透过 time_wr 函数)之後,应当可以将当前的核心(target_hart)的记忆体映射状态暂存器 mtimecmp 设置为全部都是 1 的初值(0xffffffffffffffff,C 语言的话使用 -1ULL 是技巧)。

笔者将这个问题收敛到写入的那一道指令,在该写入指令之前,mip 为 0;在写入之後,则变为 0x80

初步分析

这个初始赋值的意图很明显,就如我们在 3.0 节讲解过的,计时器中断产生的必要条件之一,是 mtime 随着时间增长,超过了 mtimecmp 的值。若是 mtimecmp 的值已经设定为不可超越的最大值,那麽对於系统来说会是比较好的初始条件。

那麽,OpenSBI 的程序码在这里看起来一点错误也没有。

探索规格书

有没有可能是规格书定义上,没有定义明确,这两者之间该怎麽比较呢?因为整数的比较情境中,必须要指定是有号或是无号。如果是有号整数的比对,那麽 -1ULL 当然就反而成为了 -1,而使得 mtime 不可能小於一个负数了。

然而,最新版的规格书中有明确规范这件事情:

A machine timer interrupt becomes pending whenever mtime
contains a value greater than or equal to mtimecmp, treating
the values as unsigned integers.

所以,有可能是 QEMU 做错了吗?也许,变数的型别弄错了?先进行实验看看这个现象是否真的和整数的正负号有关:

(gdb) x/i $pc
=> 0x80011db6:  sd      a1,0(a2)
(gdb) display/x $mip
3: /x $mip = 0x0
(gdb) display/x $a1
4: /x $a1 = 0xffffffffffffffff

先确保初始条件如预期,接着是执行这道指令,使得写入生效:

(gdb) si
0x0000000080011db8 in ?? ()
3: /x $mip = 0x80
4: /x $a1 = 0xffffffffffffffff

这时已经产生了变化!笔者不确定为什麽无法透过 gdb 直接写入 clint 所在的区域,所以这里稍微变化一下:

(gdb) set $pc=0x0000000080011db6
(gdb) set $a1=0x7fffffffffffffff
(gdb) si
0x0000000080011db8 in ?? ()
3: /x $mip = 0x80
4: /x $a1 = 0x7fffffffffffffff

将程序指标挪回去那一道写入指令,然後这里再把想要写入的值设定为最大的有号整数,结果还是一样,机器模式计时器中断的搁置位元遭到设置。

这是怎麽回事?确认一下当前的计时器值,且若是我们将 timecmp 设置的更小一些呢?

(gdb) set $pc=0x0000000080011db6
(gdb) set $a1=0x0000000000070000
(gdb) si
0x0000000080011db8 in ?? ()
3: /x $mip = 0x0
4: /x $a1 = 0x70000
7: x/xg 0x200bff8  0x200bff8:   0x00000000000629bd

确实又符合预期了。正常来讲,计时器值还没有增长到超过比对值,当然就不符合搁置状态的定义。再做了几次实验,发现收敛到个奇怪的值:

(gdb) set $pc=0x0000000080011db6
(gdb) set $a1=0x1fffffffffffffbd
(gdb) si
0x0000000080011db8 in ?? ()
3: /x $mip = 0x80
4: /x $a1 = 0x1fffffffffffffbd
7: x/xg 0x200bff8  0x200bff8:   0x0000000000067388
8: x/xg 0x2004018  0x2004018:   0x1fffffffffffffbd
(gdb) set $pc=0x0000000080011db6
(gdb) set $a1=0x1fffffffffffffbc
(gdb) si
0x0000000080011db8 in ?? ()
3: /x $mip = 0x0
4: /x $a1 = 0x1fffffffffffffbc
7: x/xg 0x200bff8  0x200bff8:   0x000000000006781c
8: x/xg 0x2004018  0x2004018:   0x1fffffffffffffbc

0x1fffffffffffffbd 以上的值,都会有搁置的效果。

追查 QEMU 实作

由於 QEMU 内的抽象层设计对於笔者来说很迂回,因此先简单做几次插入印出讯息的实验,大概抓个方向之後,接下来还是需要 GDB 辅助。当然,这个 GDB 是开发机上的 GDB,用来除错 QEMU 这支程序。

透过搜查关键字的方式,可以定位到 mtimecmp 相关的逻辑在 hw/intc/sifive_clint.c 里面的 sifive_clint_write_timecmp 函数。其中,

...
    if (cpu->env.timecmp <= rtc_r) {
        /* if we're setting an MTIMECMP value in the "past",
           immediately raise the timer interrupt */
        riscv_cpu_update_mip(cpu, MIP_MTIP, BOOL_TO_MASK(1));
        return;
    }
    ...

这个控制区块内,timecmp 的值已经小於时间值,因此需要更新 mip 的值,使用 riscv_cpu_update_mip 函数的功能。然而,在这个区块内若是插入印出讯息或是设置断点,则会发现我们想要追查的 mip 设置为 0x80 的瞬间,实际上不在这里。

所以,笔者以 b riscv_cpu_update_mip if mask == 128 为条件,试图抓取相关的呼叫;除非该次更新与这个函数无关,而是直接窜写 mip 内容。128 代表的是机器模式中断的 0x80;非下条件不可的原因则是,在 ethanol 启动过程中的多次控制台印出字元(console put character)都有外部中断事件搁置且透过这个函数改写 mip,因此并不理想。

结果,针对机器模式的计时器中断搁置位元,可以观测到两个来源。

第一种回溯

这是笔者在试图猎捕的过程中先观测到的使用方式。也就是在 timecmp 有所更新之後,立刻进行的检测。

#0  riscv_cpu_update_mip
    (cpu=cpu@entry=0x7ffff7fb2830, mask=mask@entry=128, value=value@entry=0)
    at ../target/riscv/cpu_helper.c:231
#1  0x0000555555baf3c0 in sifive_clint_write_timecmp
    (cpu=0x7ffff7fb2830, value=4294967295, timebase_freq=10000000)
    at ../hw/intc/sifive_clint.c:60
#2  0x0000555555b79840 in memory_region_write_accessor
    (mr=mr@entry=0x5555567eb0f0, addr=16400, value=value@entry=0x7fffa7ffd1d8, size=size@entry=4
, shift=<optimized out>, mask=mask@entry=4294967295, attrs=...) at ../softmmu/memory.c:492
#3  0x0000555555b77106 in access_with_adjusted_size
    (addr=addr@entry=16400, value=value@entry=0x7fffa7ffd1d8, size=size@entry=8, access_size_min
=<optimized out>, access_size_max=<optimized out>, access_fn=
    0x555555b797c0 <memory_region_write_accessor>, mr=0x5555567eb0f0, attrs=...)
    at ../softmmu/memory.c:554
#4  0x0000555555b7b149 in memory_region_dispatch_write
    (mr=mr@entry=0x5555567eb0f0, addr=addr@entry=16400, data=<optimized out>, 
    data@entry=18446744073709551615, op=op@entry=MO_64, attrs=...) at ../softmmu/memory.c:1511
#5  0x0000555555c417e9 in io_writex
    (env=env@entry=0x7ffff7fbb9a0, iotlbentry=iotlbentry@entry=0x5555567c0bd0, mmu_idx=mmu_idx@e
ntry=3, val=val@entry=18446744073709551615, addr=addr@entry=33570832, retaddr=retaddr@entry=1407
36213287170, op=MO_64) at ../accel/tcg/cputlb.c:1420
#6  0x0000555555c49ea7 in store_helper
    (op=MO_64, retaddr=<optimized out>, oi=<optimized out>, val=<optimized out>, addr=33570832, 
env=0x7ffff7fbb9a0) at ../accel/tcg/cputlb.c:2463
#7  helper_le_stq_mmu
    (env=0x7ffff7fbb9a0, addr=33570832, val=18446744073709551615, oi=<optimized out>, retaddr=14
0736213287170) at ../accel/tcg/cputlb.c:2541
#8  0x00007fffb4000102 in code_gen_buffer ()
#9  0x0000555555c36e0e in cpu_tb_exec
    (cpu=0x7ffff7fb2830, itb=<optimized out>, tb_exit=0x7fffa7ffd8e8)
    at ../accel/tcg/cpu-exec.c:353
#10 0x0000555555c382be in cpu_loop_exec_tb
    (tb_exit=0x7fffa7ffd8e8, last_tb=<synthetic pointer>, tb=0x7fffb4000000 <code_gen_buffer+671
08819>, cpu=0x7ffff7fb2830) at ../accel/tcg/cpu-exec.c:812
#11 cpu_exec (cpu=cpu@entry=0x7ffff7fb2830) at ../accel/tcg/cpu-exec.c:970
#12 0x0000555555c546e0 in tcg_cpus_exec (cpu=cpu@entry=0x7ffff7fb2830)
    at ../accel/tcg/tcg-accel-ops.c:67
#13 0x0000555555c547f7 in mttcg_cpu_thread_fn (arg=arg@entry=0x7ffff7fb2830)
    at ../accel/tcg/tcg-accel-ops-mttcg.c:70
#14 0x0000555555da8439 in qemu_thread_start (args=0x7fffa7ffd9d0)
    at ../util/qemu-thread-posix.c:541
#15 0x00007ffff7567259 in start_thread () at /usr/lib/libpthread.so.0
#16 0x00007ffff71585e3 in clone () at /usr/lib/libc.so.6

从最下层往上看大致可以欣赏模拟器的工夫,但笔者这里就不深究了。从 clone 开始,显然每一个核心应该都是透过开发机上的执行绪来实作的。

到了中间第七层~第九层大约是执行指令之後,将之对应到记忆体行为的过程。第二层~第六层看起来像是通用的写入所需经过的一些抽象,术语上来说与实际的汇流排(bus)类似。到了第二层,已是使用到先前提到的 sifive_clint_write_timecmp 函数了。

值得一提的是,OpenSBI 所进行的初始化写入,看似是一个 64 位元的写入,实际上会被当作两个 32 位元写入,所以这里一样的回溯纪录会看到两次。

但这两次,都不会造成 mip 被写为 0x80 的状况,显然实际上另有原因。

第二种回溯

这种短得多,

#0  riscv_cpu_update_mip (cpu=0x7ffff7fb2830, mask=128, value=4294967295)
    at ../target/riscv/cpu_helper.c:231
#1  0x0000555555dc7659 in timerlist_run_timers (timer_list=0x55555659f770)
    at ../util/qemu-timer.c:573
#2  0x0000555555dc7895 in timerlist_run_timers (timer_list=<optimized out>)
    at ../util/qemu-timer.c:506
#3  qemu_clock_run_timers (type=<optimized out>) at ../util/qemu-timer.c:587
#4  qemu_clock_run_all_timers () at ../util/qemu-timer.c:669
#5  0x0000555555dc383b in main_loop_wait (nonblocking=nonblocking@entry=0)
    at ../util/main-loop.c:542
#6  0x0000555555b76ca3 in qemu_main_loop () at ../softmmu/runstate.c:726
#7  0x0000555555903bfe in main

而且是来自主函数?在 qemu_main_loop 内发生。中间几层看起来是在检查所有的计时器,最後导向 mip 的更新。值得注意的是,这里 mask 值的意思就是 mip 的位元遮罩。第三个参数 value 是 0 的情况下,更新就不会有效力;反之,则会更新。

从第一层的 timerlist_run_timers 函数看来,当前这个模拟的 RISC-V 环境所使用的计时器(Clint)应该是被加到 QEMU 主执行绪管理的计时器列表之中了。这里只是将之提取出来,并呼叫对应的处理函数:

...
        timer_list->active_timers = ts->next;
        ts->next = NULL;
        ts->expire_time = -1;
        cb = ts->cb;
        opaque = ts->opaque;

        /* run the callback (the timer list can be modified) */
        qemu_mutex_unlock(&timer_list->active_timers_lock);
        cb(opaque);
        qemu_mutex_lock(&timer_list->active_timers_lock);
        ...

引用部分包在一个 ts 为回圈变数的回圈之中,不断提取 active_timers

这里应该是因为编译之後的回呼函数(callback function,这里是指 ts->cb)被直接涵盖进去了,以至於没有出现在回溯纪录之中。无论如何,呼叫到的是

static void sifive_clint_timer_cb(void *opaque)
{
    RISCVCPU *cpu = opaque;
    riscv_cpu_update_mip(cpu, MIP_MTIP, BOOL_TO_MASK(1));
}

也就是说,只要走进来这里,就理当是要将 0x80 的搁置位元设定起来了。

这表示,当初的 timecmp 的赋值,想必还是会经过某个会将这个计时器放入 QEMU 的 timerlist 的时机。然後不知道为什麽,放入与否竟然与 timecmp 的值有关系。

追查 timerlist

我们回头观察 sifive_clint_write_timecmp 可以发现:

    /* otherwise, set up the future timer interrupt */
    riscv_cpu_update_mip(cpu, MIP_MTIP, BOOL_TO_MASK(0));
    diff = cpu->env.timecmp - rtc_r;
    /* back to ns (note args switched in muldiv64) */
    next = qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) +
        muldiv64(diff, NANOSECONDS_PER_SECOND, timebase_freq);
    timer_mod(cpu->env.timer, next);

这里的 timer_mod,虽然不是很清楚这是什麽意思,但 mod 毕竟有可能是代表修改(modify)的意思,所以更进一步看看这个函数:

void timer_mod(QEMUTimer *ts, int64_t expire_time)
{
    timer_mod_ns(ts, expire_time * ts->scale); 
}

因为有些计时器可能不是与现实时间一比一的,所以这里经过一个转手之後,呼叫 timer_mod_ns 函数

/* modify the current timer so that it will be fired when current_time >= expire_time. The corresponding callback will be called. */
void timer_mod_ns(QEMUTimer *ts, int64_t expire_time)
{
    QEMUTimerList *timer_list = ts->timer_list;
    bool rearm;
    
    qemu_mutex_lock(&timer_list->active_timers_lock);
    timer_del_locked(timer_list, ts);
    rearm = timer_mod_ns_locked(timer_list, ts, expire_time);
    ...

注解描述了这个函数的目的。这些计时器列表都是排序过的,所以要根据传入的到期时间(expire_time)来重新插入列表。

是的,接着就在最後这一段关键区段(critical section)里面,将当前的计时器自 timer_list 这个计时器列表中移除;而後呼叫 timer_mod_ns_locked,将当前的计时器加入。

揪出错误

这里其实有两个造成错误的因素。第一个是

next = qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) +
        muldiv64(diff, NANOSECONDS_PER_SECOND, timebase_freq);

这个叙述。前半段由 qemu_clock_get_ns 取得的是当前时间,这我没有什麽意见。後半段的 muldiv64 函数,计算的是 a*b/c 的计算。可是,我们今天的这个 RISC-V 虚拟系统上来讲,相当於上述运算符号 ctimebase_freq 都是 10^7 = 10000000;但相当於 bNANOSECONDS_PER_SECOND 当然是 10^9,一秒有十亿奈秒。

这样就注定会有变数装不下的问题。muldiv64 回传的值是无号的 64 位元整数,是很大没有错。但 diff 的值,会是 OpenSBI 试图初始化的最大无号整数减去当前的时间读数,这还会是一个很大的数。也就是说,muldiv64 实际上的值应该是接近最大无号整数的 100 倍,但当然,这里的变数没有办法装得下这个实际的值

第二个问题是,这个 next,传入给 timer_mod 之後,

void timer_mod(QEMUTimer *ts, int64_t expire_time)

好不容易计算出来当作计时器到期值的这个值,竟然是有号的 64 位元整数!这样的话,要是不小心超过了最大的有号整数,也就是任何一个最高位元为 1 的数字,都会被解读成负数而置放到计时器列表的最前列。QEMU 的主回圈将计时表最前列的计时器取出之後,当然也就会决定要将 mip 的计时器中断搁置位元设置起来了。

解决方案

diff --git a/hw/intc/sifive_clint.c b/hw/intc/sifive_clint.c
index 0f41e5ea1c..24307ed59c 100644
--- a/hw/intc/sifive_clint.c
+++ b/hw/intc/sifive_clint.c
@@ -44,6 +44,7 @@ static void sifive_clint_write_timecmp(RISCVCPU *cpu, uint64_t value,
 {
     uint64_t next;
     uint64_t diff;
+    uint64_t now;
 
     uint64_t rtc_r = cpu_riscv_read_rtc(timebase_freq);
 
@@ -59,9 +60,9 @@ static void sifive_clint_write_timecmp(RISCVCPU *cpu, uint64_t value,
     riscv_cpu_update_mip(cpu, MIP_MTIP, BOOL_TO_MASK(0));
     diff = cpu->env.timecmp - rtc_r;
     /* back to ns (note args switched in muldiv64) */
-    next = qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) +
-        muldiv64(diff, NANOSECONDS_PER_SECOND, timebase_freq);
-    timer_mod(cpu->env.timer, next);
+    now = qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL);
+    next = now + muldiv64(diff, NANOSECONDS_PER_SECOND, timebase_freq);
+    timer_mod(cpu->env.timer, (next <= now) ? (int64_t)((1ULL<<63) - 1) : next);
 }
 
 /*

这里我们在真正让计时器列表重新加入过期时间之前,我们先做一点处理,如果一个值加了之後变得更小了,那显然有溢位(overflow)出现,这时我们就改成给我们所能够要求的最大值。

当然,更根本的问题是,到底为什麽这个过期时间是有号整数?笔者猜测也是一些与先前版本的相容问题。事实上 timer_mod 等函数都是许多其他模拟硬体在使用的通用函数,确实也不容易改动吧。还是说,有时候,QEMU 这种模拟器会需要向前调整计时器?这就需要更多考证了。

後续

就在笔者整理完上述修补并送出之後,立刻很惊讶地发现,也有另外一位已经捷足先登了。原来这个问题已经被记录在官方的错误列表之中,而别人的修补已经修改到第 4 版了。

小结

实在很瞎,本以为可以顺便缴出第一次贡献 QEMU 的成绩单,结果还是晚了别人一步。不过自己追踪过的才是自己的,本来就是学习学习。而且後来还收到上游维护者 Alistar 的感谢函

Hello,

Thanks for the patch!

As David's was sent first I am going to apply that instead of this
one. Sorry about that.

Please feel free to send more QEMU patches in the future or to review
other people's patches.

Hopefully we will see you again :)

Alistair

他应该不知道我是谁吧,想到就好笑。当初我们在 2018 年底的 Linux 水电工研讨会(Linux Plumbers Conference)的酒会有过一面之缘;那时给他的名片当然是写 Alan 而非这里用的拼音,email 也是给公司的。题外话,那是在温哥华的旧港口仓库改建的酒吧,当时被 LPC 包场,满满的都是 Linux 贡献者,委实壮观。当时正在与还没有转职到 Google 的 Palmer 攀谈,Alistair 就加入进来。他是 WDC 的工程师,口音很有趣的澳洲人;当时他说他正在拼 H 权限指令集扩充,也就是虚拟机器管理员 Hypervisor 的相关功能。

其实这些开源专案的维护者也都是人,甚至大多相当平易近人且乐於协助。当时他还不是 QEMU 维护者,只是 RISC-V 国际现在的技术长上任之前,有些流程还不完备,导致他也是硬着头皮在做 H 扩充指令集。没有模拟器,怎麽验 H spec?没有 spec,怎麽做模拟器、怎麽写 KVM?我还记得他拿着啤酒杯无力地描述这个鸡蛋问题的样子。快要三年多之後的现在,世界又很不一样了。

无论如何,真的要贡献的话,还是下次有机会再说罗。


<<:  Day 26 : LightGBM 与 GridSearch

>>:  【程序】说是说不 转生成恶役菜鸟工程师避免 Bad End 的 30 件事 - 25

App 在发布到play商店後 Firebase Authentication 无法登入问题解决

身为一个App的开发新手常常会遇到一些莫名其妙又难以解决的问题,直到找到问题答案才发现根本是自己愚蠢...

在国外的我如何跟客户联系

关於联系方式,我分成三种等级: 即时:line/messenger 通话、电话、已读的 line 等...

ISO 27001 资讯安全管理系统 【解析】(二十二)

识别威胁 在前面的概论中,我们知道威胁是外来的,他必须配合资产才会产生风险,所以资产与威胁是相互之...

常见的隧道协议(Common Tunneling Protocols)

常见的隧道协议 以下是常见的隧道协议: .GRE(协议 47):通用路由封装 .SSTP(TCP 端...

2021最新Canonical终极指南,短短的语法让你的SEO功力倍增提升网站能见度

Canonical 是什麽 图片来源:https://www.samunderwood.co.uk/...