iT邦幫忙

2021 iThome 鐵人賽

DAY 29
2
Software Development

予焦啦!Hoddarla 專案起步:使用 Golang 撰寫 RISC-V 作業系統的初步探索系列 第 29

予焦啦!附錄:詭異的時間中斷(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?我還記得他拿着啤酒杯無力地描述這個雞蛋問題的樣子。快要三年多之後的現在,世界又很不一樣了。

無論如何,真的要貢獻的話,還是下次有機會再說囉。


上一篇
予焦啦!附錄:旅途拾貝
下一篇
予焦啦!附錄:那些作業系統的巨人們與參考資料
系列文
予焦啦!Hoddarla 專案起步:使用 Golang 撰寫 RISC-V 作業系統的初步探索32

尚未有邦友留言

立即登入留言