Blame for sdq-ling/make_io_audit.py

#!/usr/bin/env python3
"""Turn results/io_audit_raw.log (from sdq-ling/audit_io.sh) into io_audit.{json,md}."""
import json
import re
from pathlib import Path

R = Path('/root/app/results')
raw = (R / 'io_audit_raw.log').read_text()


def seg(marker):
    i = raw.index(marker)
    j = raw.find('[audit]', i + 10)
    return raw[i:j if j > 0 else len(raw)]


def one(s, pat, cast=float):
    m = re.search(pat, s)
    return cast(m.group(1)) if m else None


def allv(s, pat):
    return [float(m.group(1)) for m in re.finditer(pat, s)]


def parse(marker, mode, note):
    s = seg(marker)
    rb = allv(s, r'read_bytes=\s+([\d.]+) GiB')
    res = allv(s, r'model_file_resident=\s*([\d.]+) GiB')
    return {
        'mode': mode,
        'device_read_gib_max': max(rb) if rb else None,
        'device_read_gib_samples': len(rb),
        'model_file_resident_gib_peak': one(s, r'peak model_file_resident in page cache :\s+([\d.]+)'),
        'model_file_resident_gib_final': one(s, r'final model_file_resident\s+:\s+([\d.]+)'),
        'rss_anon_gib_peak': one(s, r'peak process RssAnon\s+:\s+([\d.]+)'),
        'rss_file_gib_peak': one(s, r'peak process RssFile\s+:\s+([\d.]+)'),
        'system_cached_delta_gib_peak': one(s, r'system Cached delta \(peak\)\s+:\s+([+\-][\d.]+)'),
        'sdq_chat_reported_ssd_gb': one(s, r'全程 SSD 實際讀取: ([\d.]+) GB'),
        'samples_tail': [f'read_bytes={b:.3f} GiB model_file_resident={r:.3f} GiB'
                         for b, r in list(zip(rb, res))[-6:]],
        'note': note,
    }


doc = {
    'what': 'I/O honesty audit: are the expert weights really coming from the block device, '
            'or is the page cache quietly serving them?',
    'method': 'per-file page-cache eviction (posix_fadvise(DONTNEED) on both GGUF shards), '
              'then mincore(2) over the whole 71.72 GiB of shard data every 0.5 s while '
              '/proc/<pid>/io read_bytes and /proc/<pid>/status RssAnon/RssFile are sampled.',
    'tools': ['sdq-ling/pagecache_resident.cpp', 'sdq-ling/watch_io.py', 'sdq-ling/audit_io.sh'],
    'settings': {'ram_budget_mb': 8192, 'ctx': 2048, 'ubatch': 128, 'threads': 16,
                 'n_predict': 32, 'temp': 0},
    'results': {
        'A_default_o_direct': parse('A) default (O_DIRECT)', 'O_DIRECT (pager default)',
            'the model file stays at ~2.09 GiB resident, which is exactly the non-expert '
            'weights; the tens of GiB of expert reads leave no page-cache footprint'),
        'B_control_buffered_cache_kept': parse(
            'B) control: buffered reads + page cache kept',
            'SDQ_NO_DIRECT_IO=1 + --no-fadvise',
            'same reads, but the page cache retains them; residency tracks the read '
            'volume ~1:1, which is what a buffered implementation would cost'),
    },
    'conclusion': [
        'The pager reads expert weights with O_DIRECT: read_bytes (real device I/O) grows '
        'while mincore residency of the GGUF stays flat.',
        'The only resident part of the model file is the 2.26 GiB of non-expert weights '
        'that llama.cpp keeps in RAM (1.54 GiB of it file-backed via mmap). Not one byte '
        'of the 69.46 GiB of expert weights reaches the page cache.',
        'The control run proves the measurement is sensitive: with buffered reads the same '
        'file accumulates tens of GiB of page cache.',
        'Memory numbers: an 8 GiB pager budget yields 5.83 GiB anonymous RSS '
        '(3.54 GiB arena + ~2.3 GiB non-expert weights) + 1.73 GiB file-backed RSS '
        '= 7.0 GiB total RSS.',
        'sdq-chat\'s "SSD read" line starts its counter after model load, so it excludes '
        'the ~3.9 GiB the loader itself reads; the watcher numbers above cover the whole '
        'process lifetime.',
    ],
}
(R / 'io_audit.json').write_text(json.dumps(doc, ensure_ascii=False, indent=2) + '\n')

A = doc['results']['A_default_o_direct']
B = doc['results']['B_control_buffered_cache_kept']
md = f"""# I/O 稽核：expert 權重真的有從 block device 讀嗎？

問題：如果 pager 其實是被 page cache 服務的，那「69 GiB 的權重留在 SSD、每次按需讀取」這句話就是假的。

## 方法

1. 用 `posix_fadvise(POSIX_FADV_DONTNEED)` 把兩個 GGUF shard（71.72 GiB）**逐檔案**從 page cache 驅逐
   （不依賴 `/proc/sys/vm/drop_caches`，容器裡也做得到），並用 `mincore` 確認回到 0.000 GiB resident。
2. 開跑 `sdq-chat`，每 0.5 s 抽樣：
   * `/proc/<pid>/io` 的 `read_bytes` = 真正從 block device 讀了多少
   * `mincore(2)` 掃過整個模型檔 = 有多少頁留在 page cache
   * `/proc/<pid>/status` 的 `RssAnon` / `RssFile`
3. 跑兩次，其他設定完全相同：
   * **A（預設）**：pager 用 `O_DIRECT` 讀
   * **B（對照組）**：`SDQ_NO_DIRECT_IO=1` + `--no-fadvise` = buffered 讀且**保留** page cache

B 的存在是為了證明這個量測**有鑑別力**：如果看不出差別，A 的數字也沒有意義。

## 結果

| | A：預設（O_DIRECT） | B：對照組（buffered + 保留 cache） |
|---|---:|---:|
| 真正讀進來的量（read_bytes 峰值） | {A['device_read_gib_max']:.2f} GiB | {B['device_read_gib_max']:.2f} GiB |
| **模型檔留在 page cache 的峰值** | **{A['model_file_resident_gib_peak']:.3f} GiB** | **{B['model_file_resident_gib_peak']:.2f} GiB** |
| 程序 RssAnon 峰值 | {A['rss_anon_gib_peak']:.2f} GiB | {B['rss_anon_gib_peak']:.2f} GiB |
| 程序 RssFile 峰值 | {A['rss_file_gib_peak']:.2f} GiB | {B['rss_file_gib_peak']:.2f} GiB |
| 系統 Cached 增量（峰值） | {A['system_cached_delta_gib_peak']:+.2f} GiB | {B['system_cached_delta_gib_peak']:+.2f} GiB |
| `sdq-chat` 自報「SSD 實際讀取」 | {A['sdq_chat_reported_ssd_gb']:.2f} GB | {B['sdq_chat_reported_ssd_gb']:.2f} GB |

A 的時間序列（最後 6 個抽樣）——`read_bytes` 一路爬到
{A['device_read_gib_max']:.1f} GiB，而模型檔 resident 從 2.09 GiB 之後**完全不動**：

```
{chr(10).join(A['samples_tail'])}
```

## 結論

1. **pager 讀 expert 權重走 `O_DIRECT`**：`read_bytes`（真實裝置 I/O）上升時，
   模型檔的 page cache 用量沒有增加。
2. 模型檔唯一留在 page cache 的部分是 **{A['model_file_resident_gib_peak']:.2f} GiB 的非 expert 權重**
   （shard1 1.54 + shard2 0.55 GiB；非 expert 權重總共 2.26 GiB），
   那是 llama.cpp 本來就該留在 RAM 的東西，其中約 1.54 GiB 以 mmap file-backed 方式存在。
   **69.46 GiB 的 expert 權重一個位元組都沒有進 page cache。**
3. **對照組證明量測有鑑別力**：同樣的讀取量改成 buffered，模型檔會在 page cache 堆到
   {B['model_file_resident_gib_peak']:.1f} GiB。如果量測是瞎的，A 和 B 會一樣。
4. 對記憶體數字的影響：8 GiB 的 pager 預算實際是
   **{A['rss_anon_gib_peak']:.2f} GiB 匿名 RSS（其中 arena 3.54 GiB、非 expert 權重 ~2.3 GiB）
   + {A['rss_file_gib_peak']:.2f} GiB 檔案對映 RSS = 7.0 GiB 總 RSS**。
5. 兩個數字的差異是可解釋的：`sdq-chat` 的「SSD 實際讀取」在**載入模型之後**才開始計，
   所以不含 loader 自己讀的 ~3.9 GiB；watcher 的數字涵蓋整個行程生命週期。

> 順帶修掉一個原本會誤導的報表 bug：`sdq-chat` 的記憶體摘要讀 `/proc/self/smaps_rollup` 的
> `RssFile:`，但本機核心的 `smaps_rollup` **沒有這個 key**（只有 `Anonymous:`），
> 於是長期都印「檔案對映 RSS 0 MB」。已改成讀 `/proc/self/status` 的
> `RssAnon:` / `RssFile:` / `VmRSS:`，並在記憶體實驗裡一併記錄三個數字。

原始輸出：`results/io_audit_raw.log`；結構化資料：`results/io_audit.json`
重跑：`./sdq-ling/audit_io.sh <model.gguf> <sdq-chat> 8192 32`
"""
(R / 'io_audit.md').write_text(md)
print('wrote io_audit.json / io_audit.md')
print('A:', A['device_read_gib_max'], A['model_file_resident_gib_peak'])
print('B:', B['device_read_gib_max'], B['model_file_resident_gib_peak'])