# 2025q1 Homework3 (kxo)
contributed by < `LinMarc1210` >
{%hackmd NrmQUGbRQWemgwPfhzXj6g %}
## 開發環境
```shell
$ gcc --version
gcc (Ubuntu 13.3.0-6ubuntu2~24.04) 13.3.0
$ lscpu
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Address sizes: 39 bits physical, 48 bits virtual
Byte Order: Little Endian
CPU(s): 16
On-line CPU(s) list: 0-15
Vendor ID: GenuineIntel
Model name: 12th Gen Intel(R) Core(TM) i7-1260P
CPU family: 6
Model: 154
Thread(s) per core: 2
Core(s) per socket: 12
Socket(s): 1
Stepping: 3
CPU(s) scaling MHz: 21%
CPU max MHz: 4700.0000
CPU min MHz: 400.0000
BogoMIPS: 4992.00
```
## 研讀作業說明的筆記
> [筆記](https://hackmd.io/kN6LFVOcQaKj0YFpOdUm9w)
## Simrupt
先編譯並產生 `simrupt.ko` 檔案並使用以下命令掛載 simrupt 模組，並輸出 `/dev/simrupt` 的內容，可以看到每秒會輸出一個字元。
```shell
$ make
```
```shell
$ sudo insmod simrupt
```
```shell
$ sudo cat /dev/simrupt
```
### 使用 eBPF 追蹤 simrupt 的行為
bpftrace 用來追蹤的命令：`sudo bpftrace [OPTIONS]`
```
OPTIONS:
-e 'program' execute this program
-l [search] list probes
```
先搞懂幾個 bpftrace 的行為：
- `tracepoint`: kernel static tracing
- `kprobe`: kernel dynamic tracing，附加於要追蹤的函式的進入點
- `kretprobe`: 附加於要追蹤的函式的返回點
- `comm`: 目前執行緒的 command name，根據 `comm` 值可區分 deffered work 的執行來源：
- `kworker/uX:Y`：執行於 workqueue context，具備可睡眠能力的獨立核心執行緒 (kernel thread for workqueue)
- `ksoftirqd/N`：代表由 softirq daemon 延後執行 tasklet
- `swapper/N`: idle，`N` 為 `tid`
- 其他行程 (如 `systemd-journal`, `cat` 等）：代表 softirq 被直接執行於該行程的核心脈絡中
#### 追蹤 /dev/simrupt 開啟的狀態
使用以下命令追蹤：
```shell
$ sudo bpftrace -e '
tracepoint:syscalls:sys_enter_openat
/str(args->filename) == "/dev/simrupt"/
{
printf("Opened /dev/simrupt by pid=%d, comm=%s\n", pid, comm);
}'
```
其概念可想成 tracepoint 設在 `/dev/simrupt` 的位置，並且當我們另外開啟新的視窗並輸入 `sudo touch /dev/simrupt` 的時候，可以在原本的視窗看到如以下輸出：
```
Opened /dev/simrupt by pid=9028, comm=touch
Opened /dev/simrupt by pid=9031, comm=touch
Opened /dev/simrupt by pid=9034, comm=touch
```
以上是重複執行三次 `touch` 的輸出，三次的 `pid` 不同但 `comm` 相同是因為三次都用 touch，所以 command name 都是 touch，但每次執行時會被當作不同的行程，因此有不同的 `pid`。
#### 觀察 simrupt 執行過程
使用以下命令觀察在我們輸入命令`sudo cat /dev/simrupt` ，`simrupt` 模組在執行 tasklet 與 workqueue 函式時的實際執行脈絡：
```shell
$ sudo bpftrace -e '
kprobe:simrupt_tasklet_func {
printf("tasklet_func: comm=%s, pid=%d, tid=%d\n", comm, pid, tid);
}
kprobe:simrupt_work_func {
printf("work_func: comm=%s, pid=%d, tid=%d\n", comm, pid, tid);
}'
```
會得到類似以下的輸出（simrupt 每輸出一個字元就有一組）：
```
work_func: comm=kworker/u64:3, pid=9329, tid=9329
tasklet_func: comm=ksoftirqd/9, pid=50, tid=50
work_func: comm=kworker/u64:2, pid=8536, tid=8536
tasklet_func: comm=swapper/9, pid=0, tid=0
```
可觀察到 workqueue 都是執行於獨立核心執行序，由核心統一管理並且可排程。tasklet 則可能直接執行於使用者行程，也有可能由 `ksoftirqd` 延遲處理。
:::info
在 softirq context 中，pid 通常為 0，因其執行於 interrupt context，不屬於一般行程。
:::
#### 使用 bpftrace 分別追蹤 tasklet 和 workqueue
追蹤 `simrupt_tasklet_func` (tasklet) 或 `simrupt_work_func` (workqueue) 都可以在要監控的函式進入點與返回點分別加入 `kprobe` 和 `kretprobe`，如以下命令：
- 追蹤 tasklet
```shell
$ sudo bpftrace -e '
kprobe:simrupt_tasklet_func {
printf("Tasklet started: CPU %d, Time %llu ns, PID %d\n", cpu, nsecs, pid);
}
kretprobe:simrupt_tasklet_func {
printf("Tasklet ended: CPU %d, Time %llu ns, PID %d\n", cpu, nsecs, pid);
}
'
```
- 追蹤 workqueue (真正的 bottom-half / threaded context)
```shell
$ sudo bpftrace -e '
kprobe:simrupt_work_func {
printf("Workqueue started: CPU %d, Time %llu ns, PID %d, Comm %s\n", cpu, nsecs, pid, comm);
}
kretprobe:simrupt_work_func {
printf("Workqueue ended: CPU %d, Time %llu ns, PID %d, Comm %s\n", cpu, nsecs, pid, comm);
}
'
```
用 `kprobe` 加 `kretprobe` 的組合可以得到 CPU 編號、執行開始與結束時間 (單位: ns)、行程 PID、行程名稱 (`comm`，例如 `kworker/1:1`) 等資訊。一樣執行 `sudo cat /dev/simrupt` 以在模組執行時監控函式：
- tasklet:
```
Tasklet started: CPU 12, Time 7810371240793 ns, PID 0
Tasklet ended: CPU 12, Time 7810371285112 ns, PID 0
Tasklet started: CPU 0, Time 7810475261760 ns, PID 0
Tasklet ended: CPU 0, Time 7810475310086 ns, PID 0
```
- workqueue:
```
Workqueue started: CPU 12, Time 7729771508263 ns, PID 7848, Comm kworker/u64:1
Workqueue ended: CPU 12, Time 7729771549360 ns, PID 7848, Comm kworker/u64:1
Workqueue started: CPU 15, Time 7729875156804 ns, PID 9583, Comm kworker/u64:5
Workqueue ended: CPU 15, Time 7729875190097 ns, PID 9583, Comm kworker/u64:5
```
#### 分析由 timer 觸發的執行脈絡
在 simrupt 模組中函式呼叫的關係是 `timer_handler` 呼叫 `simrupt_tasklet_func` ，`simrupt_tasklet_func` 再呼叫 `simrupt_work_func` ，我們用 kprobe 來觀察他們的關係，就算將 `kprobe` 追蹤函式的順序調換，也不影響輸出的順序。
```shell
$ sudo bpftrace -e '
kprobe:simrupt_work_func {
printf("work_func: comm=%s, tid=%d\n", comm, tid);
}
kprobe:simrupt_tasklet_func {
printf("tasklet_func: comm=%s, tid=%d\n", comm, tid);
}
kprobe:timer_handler {
printf("timer_handler: comm=%s, tid=%d\n", comm, tid);
}
'
```
```shell
timer_handler: comm=swapper/0, tid=0
tasklet_func: comm=swapper/0, tid=0
work_func: comm=kworker/u64:3, tid=10027
timer_handler: comm=chrome, tid=4062
tasklet_func: comm=chrome, tid=4062
work_func: comm=kworker/u64:5, tid=9583
```
接下來參考 [2025-04-15 問答簡記](https://hackmd.io/V7bD2XjnQuCZqDMt4ZizGA?view#%E4%BD%BF%E7%94%A8-bpftrace-%E5%88%86%E6%9E%90%E7%94%B1-timer-%E8%A7%B8%E7%99%BC%E7%9A%84%E5%9F%B7%E8%A1%8C%E8%84%88%E7%B5%A1) ，得知 `simrupt` 展現 deffered work 的三層處理：
| 函式名稱 | comm 名稱範例 | TID | Context 類型 | 說明 |
|-----------------------|-----------------------|---------|--------------------|------------------------------|
| `timer_handler` | swapper/0 | 0 | `TIMER_SOFTIRQ` | idle context 中的計時器處理 |
| `simrupt_tasklet_func` | ksoftirqd/0 | 16 | `TASKLET_SOFTIRQ` | softirq handler thread |
| | systemd-journal 等 | 非固定 | direct softirq | softirq 同步執行於現行行程中 |
| `simrupt_work_func` | kworker/u8:2, u8:0... | 多變化 | workqueue (kthread) | workqueue 處理延後工作 |
1. 核心計時器觸發 (`timer_handler`) → TIMER_SOFTIRQ
2. 排程 tasklet 執行 (`simrupt_tasklet_func`) → TASKLET_SOFTIRQ / direct softirq
3. 再排程到 workqueue 執行 (`simrupt_work_func`) → Process Context
有時 `tasklet` 會在非 `ksoftirqd` 的行程中執行，這代表 softirq 以「直接」方式於該行程內立即執行。
#### 彙整工作佇列延遲時間的直方圖
```shell
$ sudo bpftrace -e '
kprobe:simrupt_work_func {
@start[tid] = nsecs;
}
kretprobe:simrupt_work_func /@start[tid]/ {
@latency[pid, comm] = hist(nsecs - @start[tid]);
delete(@start[tid]);
}
'
```
與前面追蹤 `simrupt_work_func` 相同，只是這次將時間戳儲存至雜湊表 `@start` 中，函式返回就會用 `(pid, comm)` 區分不同工作執行緒的延遲行為。
執行完 `sudo cat /dev/simrupt` 並在另一個執行 bpftrace 的視窗按下 `CTRL+C` 就可看到直方圖：
```
@latency[5408, kworker/u64:22]:
[8K, 16K) 2 |@@@@ |
[16K, 32K) 25 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[32K, 64K) 6 |@@@@@@@@@@@@ |
[64K, 128K) 1 |@@ |
@latency[6135, kworker/u64:56]:
[8K, 16K) 2 |@@@@ |
[16K, 32K) 24 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[32K, 64K) 9 |@@@@@@@@@@@@@@@@@@@ |
```
#### 觀察 Top Half 回傳狀態
```shell
$ sudo bpftrace -e '
tracepoint:irq:irq_handler_entry /args->irq == 1/ {
printf("IRQ 1 top half entry: cpu=%d handler=%s\n", cpu, str(args->name));
}
tracepoint:irq:irq_handler_exit /args->irq == 1/ {
printf("IRQ 1 top half return: cpu=%d ret=%d (%s)\n",
cpu, args->ret, args->ret == 1 ? "IRQ_WAKE_THREAD" :
args->ret == 0 ? "IRQ_NONE" : "IRQ_HANDLED");
}
'
```
:::danger
TODO: 藉由 eBPF 觀察 workqueue 排入佇列後，如何由 CPU 排程？當系統存在 real-time (或 deadline) class 的任務時，是否影響 workqueue 的 work 排程呢？
:::
Sign in with Wallet
Connect another wallet