システム出力

Linux ゲストの出力面

Related: system output, Linux, linux troubleshooting, kernel patch, virtualized time.

システム出力はログだけではない。仮想化された環境で Linux ゲストを調べるとき、有効な証跡は寿命の異なる複数の面に分かれる。

• 生きている間に読めるカーネルメッセージ
• ftrace、perf、BPF などのトレース
• core dump
• pstore / ramoops のような RAM に残る記録
• host や hypervisor 側のイベント
• 失敗後に残った raw RAM

目的は全部集めることではない。システムが正常から異常へ移った瞬間に、失敗した資源をどの層が所有していたのかを答えられる証跡を残すことだ。

ログだけを見ると、早すぎる失敗と低すぎる層の失敗を見落とす。userspace が起動する前に再起動することがある。ゲストは driver timeout を報告していても、実際には virtual interrupt が入っていないことがある。RAM だけが最後の記録を持っていることもある。

証跡モデル

このノートでは出力を四つに分ける。

それぞれ故障の仕方が違う。journal は遅れる。userspace buffer は循環する。trace はタイミングを変える。ramoops は次の crash に上書きされる。host trace は、guest が「走っている」と思っていた vCPU が実際には走っていなかったことを示す。証跡には必ず、どの面から来たものかを残す。

調査は次の順序で広げる。

1. Event count: 何が何回起きているかを数える。
2. Profiling: 時間がどこで使われているかを見る。
3. Tracing: timestamp 付きのイベントで順序を復元する。
4. Postmortem: live system が消えた後に RAM や dump に残ったものを見る。

最初から一番強い道具を使わない。今の仮説に答えられる一番安い面から始める。

printk, dmesg, kmsg

boot、driver、panic では kernel message が最初の証跡になる。kernel code は printk、pr_*、dev_* で message を出す。

pr_info("driver init\n");
pr_warn("retrying register read\n");
dev_err(dev, "probe failed: %d\n", ret);

driver では可能なら dev_* を使う。device context が付くので、同じ driver instance が複数あるときに効く。

経路はこうなる。

kernel call site
  -> printk record
  -> kernel log buffer
  -> /dev/kmsg
  -> dmesg, journald, collector

基本コマンド:

dmesg --time-format=iso --decode
dmesg --level=err,warn
dmesg --follow
journalctl -k -b --no-pager
cat /proc/sys/kernel/printk
sysctl kernel.printk

console_loglevel は console に出る message を制御する。kernel buffer に record が残っているかとは別問題だ。boot loop では console visibility は見た目ではなく debug interface になる。

cat /proc/sys/kernel/printk
# console_loglevel default_message_loglevel minimum_console_loglevel default_console_loglevel

古い経路や互換性のある読み方では、dmesg -s または --buffer-size もまだ意味がある。

dmesg --buffer-size 262144

modern system では /dev/kmsg が重要な interface になることが多い。ただし実務上の規則は実装詳細より古い。noisy な failure では、原因を書いた earlier message が後続出力で上書きされる。instrumentation を足す前に complete output を保存する。

pstore と ramoops

crash 後に残る媒体として RAM は強い。pstore は crash record のための kernel interface で、ramoops は予約した RAM 領域に記録を書く pstore backend だ。

普通の log は userspace と storage を必要とする。ramoops record は reset 後に次の boot が読める程度に RAM が保たれていれば残る。

mount -t pstore pstore /sys/fs/pstore 2>/dev/null || true
ls -l /sys/fs/pstore
cat /sys/fs/pstore/console-ramoops-0
cat /sys/fs/pstore/dmesg-ramoops-0
cat /sys/fs/pstore/ftrace-ramoops-0

device tree での reserved region は概念的にはこうなる。

reserved-memory {
    #address-cells = <2>;
    #size-cells = <2>;
    ranges;

    ramoops@8f000000 {
        compatible = "ramoops";
        reg = <0 0x8f000000 0 0x100000>;
        record-size = <0x4000>;
        console-size = <0x4000>;
        ftrace-size = <0x4000>;
        pmsg-size = <0x4000>;
    };
};

確認するもの:

cat /proc/iomem | grep -iE 'ramoops|pstore|reserved'
cat /proc/cmdline | tr ' ' '\n' | grep -iE 'ramoops|pstore|memmap'
zcat /proc/config.gz 2>/dev/null | grep -E 'PSTORE|RAMOOPS'
grep -R . /sys/module/ramoops/parameters 2>/dev/null

pstore が空でも panic しなかったとは限らない。予約アドレス、他の firmware carveout との重なり、reset で RAM が保たれるか、ECC や firmware が RAM を scrub していないか、次の crash で上書きされていないかを見る。

late panic や shutdown path では ftrace を pstore に残すと効く。

mount -t debugfs debugfs /sys/kernel/debug 2>/dev/null || true
echo 1 > /sys/kernel/debug/pstore/record_ftrace
reboot -f
tail /sys/fs/pstore/ftrace-ramoops-0

最後の live console が rebooting だけでも、RAM 側に function path が残っていることがある。

crash dump と raw RAM

pstore は小さい。memory corruption、page allocator、use-after-free、長い状態蓄積後の panic では大きな dump が必要になる。

Linux の代表的な path:

cat /proc/vmcore
crash vmlinux vmcore
makedumpfile -d 31 /proc/vmcore vmcore.filtered

guest / hypervisor では path が分かれる。

• firmware または monitor からの RAM dump
• hypervisor 側の guest physical memory dump
• offline memory capture
• crashkernel= で予約した capture kernel
• platform minidump
• core dump、pstore、platform RAM dump の組み合わせ

raw RAM を取るなら metadata を横に置く。

machine / SKU / revision
kernel image build id
vmlinux or unstripped symbols
System.map and /proc/kallsyms if available
guest physical address layout
reserved memory map
hypervisor version
reset reason
clock source and boot id

address layout と symbols がなければ RAM image はただの bytes だ。揃っていれば、どの task が走っていたか、どの lock が保持されていたか、どの interrupt が pending だったか、どの page が壊れていたか、userspace が flush できなかった buffer が残っているかを調べられる。

crash 前に取れる live memory state:

cat /proc/iomem
cat /proc/meminfo
cat /proc/vmallocinfo | head
cat /proc/slabinfo | head
cat /proc/buddyinfo
cat /proc/pagetypeinfo 2>/dev/null | head
cat /proc/zoneinfo | head

kernel を作れるなら有効な debug feature:

CONFIG_KASAN
CONFIG_KFENCE
CONFIG_KCSAN
CONFIG_DEBUG_PAGEALLOC
CONFIG_PAGE_OWNER
CONFIG_DEBUG_VM
CONFIG_SLUB_DEBUG
CONFIG_PSTORE
CONFIG_PSTORE_RAM
CONFIG_PSTORE_FTRACE
CONFIG_KEXEC_CORE
CONFIG_CRASH_DUMP

これらは無料ではない。timing、memory pressure、cache behavior を変える。使ったことを記録して、目的を決めて入れる。

GDB の core / live state 調査

GDB は core dump、live process、制御された再現 crash、または大きな失敗から切り出した小さな machine state に強い。pstore、ftrace、BPF、vmcore reader の代わりではない。symbols、registers、mappings があり、control flow や data state について具体的な問いがあるときに使う。

capture の基本は、実行ファイル、shared libraries、debug files、build ID、core file、command line を一緒に保存することだ。matching symbol のない backtrace は、時刻の付いた推測になりやすい。

core を開く

gdb -q /path/to/program /path/to/core

最初に見るもの:

set pagination off
set print pretty on
set print frame-arguments all
set disassemble-next-line on
info files
info proc mappings
info sharedlibrary
info threads
thread apply all bt full

symbols が target root の外にあるなら path を明示する。

set sysroot /path/to/sysroot
set solib-search-path /path/to/sysroot/lib:/path/to/sysroot/usr/lib
set debug-file-directory /path/to/debug
sharedlibrary

再現 run では環境も記録する。

set args --config /tmp/repro.conf
set environment RUST_BACKTRACE=1
run

よく使うコマンド

crash triage

native crash ではまず全 thread の stack と mapping を保存する。

set pagination off
thread apply all bt full
info registers
info proc mappings
info files

crash frame を選び、argument、local、PC 付近、stack を見る。

thread 1
frame 0
info args
info locals
p/x $pc
x/8i $pc-16
x/32gx $sp

PC が shared object 内にあり symbol が足りない場合:

info proc mappings
info symbol 0x7f1234567890

stripped binary では build ID と mapping base が重要になる。matching symbol を load する。

add-symbol-file /path/to/libfoo.so.debug 0x7f1234500000

data corruption

data corruption では、その値が invalid なのか、stale なのか、free 済みなのか、所有者が違うのかを分ける。

p object
ptype object
p/x object->state
x/64gx object
info symbol object->callback

list や queue では container と element の両方を見る。pointer が正しそうでも lifetime が違うことがある。

p/x node
x/4gx node
info proc mappings

address がどの mapping にも入らないなら、core と binary だけでは足りない。pstore、vmcore、allocator debug、page owner、KASAN、KFENCE、RAM image に移る。

live attach

停止してよいときだけ attach する。

gdb -q -p "$(pidof target-service)"

set pagination off
info threads
thread apply all bt
continue

短い probe なら collect して続行する breakpoint command にする。

break suspicious_function
commands
  silent
  printf "hit suspicious_function arg=%p\n", arg
  bt 4
  continue
end

attach で timing が変わりすぎるなら、GDB をやめて ftrace、perf、BPF に移る。

kernel に近い使い方

kernel vmcore ではまず crash など kernel を理解する道具を使う。GDB は raw symbol や disassembly は見られるが、多くの kernel data structure をそのまま理解するわけではない。

それでも GDB が効く場面はある。

• system failure で出た userspace core を読む
• 小さい repro program を確認する
• driver helper を ordinary code として検証する
• trace に出た address や disassembly を確認する
• kgdb が有効な kernel に接続する

kgdb 系では symbol file を必ず一致させる。

gdb -q vmlinux
target remote /dev/ttyS0
info registers
bt
lx-symbols

lx-* commands は kernel の GDB scripts と debug environment に依存する。使えないなら view は不完全だと扱う。crash、vmcore analysis、ftrace、BPF、RAM-backed records に戻る。

userspace の出力面

Linux guest の userspace は full logging stack を持つことも、minimal initramfs だけのことも、ほとんど存在しないこともある。userspace logs を kernel evidence の代わりにしない。

基本 capture:

dmesg --time-format=iso --decode > dmesg.txt
journalctl -b --no-pager > journal.txt
journalctl -k -b --no-pager > journal-kernel.txt
ls -l /sys/fs/pstore
cp -a /sys/fs/pstore ./pstore
coredumpctl list 2>/dev/null

userspace logs は構造化され、buffer され、filter され、rate-limit され、遅れる。native crash の core や crash handler record も、handler と storage path が生きていた場合にだけ残る。

hypervisor 上では userspace symptom をさらに層に分ける。

application or service symptom
  -> native service, IPC, or syscall path
  -> guest kernel driver / irq / scheduler
  -> virtual device model or hypervisor event
  -> physical device / firmware

service が止まっているとき、userspace log は symptom しか示さないことがある。IPC state、scheduler trace、guest interrupt、host 側の virtual device event を合わせる。

event count, profiling, tracing

有効な順序はこれだ。

1. Event counting: event class が異常かを見る。
2. Profiling: 時間の使い場所を見る。
3. Tracing: event の順序を見る。

どの signal が重要かわからないうちに巨大 trace を取ると、調査は進まず data だけ増える。

Event count:

perf stat -e task-clock,context-switches,cpu-migrations,page-faults -a -- sleep 10
perf stat -e cycles,instructions,branches,branch-misses -a -- sleep 10
perf stat -e cache-references,cache-misses -a -- sleep 10

Profiling:

perf record -F 99 -a -g -- sleep 10
perf report
perf script > out.perf

Tracing:

trace-cmd record -e sched:sched_switch -e irq:* -e workqueue:* sleep 5
trace-cmd report

guest OS では可能なら両側で数える。guest は CPU 使用率が低いと言っていても、host では vCPU が schedule されていないかもしれない。guest は block timeout を報告していても、host では backend queue が止まっているかもしれない。

ftrace と tracefs

ftrace は kernel 内蔵の tracing framework で、通常 /sys/kernel/tracing に tracefs として出る。

mount -t tracefs nodev /sys/kernel/tracing 2>/dev/null || true
cd /sys/kernel/tracing
cat available_tracers
cat available_events | head
cat tracing_on

function graph tracing は関数 family がわかっているときに強い。

echo 0 > tracing_on
echo function_graph > current_tracer
echo '*read*' > set_ftrace_filter
echo 1 > tracing_on
cat /path/to/file >/dev/null
echo 0 > tracing_on
cat trace > /tmp/read.trace

event tracing はより安定している。

echo 0 > tracing_on
echo > trace
echo 1 > events/sched/sched_switch/enable
echo 1 > events/irq/irq_handler_entry/enable
echo 1 > events/irq/irq_handler_exit/enable
echo 1 > tracing_on
sleep 3
echo 0 > tracing_on
cat trace > /tmp/events.trace

boot 問題では boot-time tracing が shell より早く始められる。latency 問題では kernel 6.x の tracing には osnoise、timerlat、hwlat などがある。missed latency budget が failure になる環境では、単なる performance noise ではない。

低層 trace では最低限これを見る。

• scheduler switch
• IRQ entry / exit
• softirq
• workqueue
• power / clock event
• I/O 症状なら block or network tracepoint
• driver-specific tracepoint
• vCPU scheduling と virtual interrupt の host / hypervisor event

BPF as controlled instrumentation

printk が粗すぎ、ftrace が広すぎ、GDB が system を止めすぎるときに BPF を使う。

仕組みはこうだ。

1. BPF program を compile する。
2. bpf syscall で load する。
3. verifier が safety を確認する。
4. tracepoints、kprobes、uprobes、perf events などへ attach する。
5. maps、perf buffers、BPF ring buffers で結果を出す。

quick experiment では bpftrace が速い。

bpftrace -l 'tracepoint:syscalls:sys_enter_*'
bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }'
bpftrace -e 'tracepoint:syscalls:sys_enter_openat { printf("%s %s\n", comm, str(args->filename)); }'

read latency:

bpftrace -e 'kprobe:vfs_read { @start[tid] = nsecs; } kretprobe:vfs_read /@start[tid]/ { @ns[comm] = hist(nsecs - @start[tid]); delete(@start[tid]); }'

kernel stack profile:

bpftrace -e 'profile:hz:99 { @[kstack] = count(); }'

よい BPF debug は request setup と completion に attach し、request pointer を map で持ち回り、latency と operation type を出す。modern kernel では存在するなら tracepoint を優先する。kprobe target は version で変わる。内部関数そのものが仮説であるときだけ kprobe を使う。

block I/O:

bpftrace -e 'tracepoint:block:block_rq_issue { @bytes = hist(args->bytes); }'
bpftrace -e 'tracepoint:block:block_rq_complete { @lat[args->dev] = count(); }'

reusable tool では runtime kernel headers を埋め込むより、libbpf、BTF、CO-RE を使う。

ls -l /sys/kernel/btf/vmlinux
bpftool btf dump file /sys/kernel/btf/vmlinux format c > vmlinux.h
bpftool prog list
bpftool map list

CO-RE は kernel 6.x や変更された kernel で効く。構造体 layout が違っても field access を移植しやすくする。ただし unstable probe point を stable にするわけではない。

BPF ring buffer は cross-CPU order が重要なときに使う。per-CPU perf buffer と違い、共有 ring buffer は fork、exec、exit、request issue、completion のような逐次 event の順序を保ちやすい。guest debug では cross-CPU order そのものが bug であることがある。

BPF の制約

managed or restricted guest では BPF surface は kernel config、security policy、operator restriction に依存する。BPF は production でいつでも使えるものではなく、platform engineering tool として扱う。

debug build で見るもの:

mount -t tracefs nodev /sys/kernel/tracing 2>/dev/null
cat /sys/kernel/tracing/available_events | head
bpftool prog list
cat /sys/kernel/btf/vmlinux >/tmp/vmlinux.btf

platform bug では次を組み合わせる。

• userspace log で service や native symptom を特定する
• native crash は core dump や crash record を読む
• scheduler、IPC、IRQ、block、driver timing は ftrace or BPF で見る
• reboot / panic は pstore / ramoops で見る
• guest が観測できない event は host or hypervisor trace で見る

syscall trace だけでは service がなぜ blocked なのか説明できないことがある。userspace tag、IPC state、scheduler event、kernel wait path を合わせる。

hypervisor guest debugging

hypervisor 上の guest OS では、record に層を付ける。

guest だけを信じるのは危ない。guest の block timeout は guest driver の bug かもしれないが、backend が completion を返していない、virtual interrupt が inject されていない、vCPU が schedule されていない、guest clock が跳んだ、という意味かもしれない。

failure report では最低限これが欲しい。

guest dmesg with monotonic timestamps
guest pstore after reboot
core dump or crash record, if native crash
guest /proc/interrupts and /proc/iomem
host/hypervisor event trace covering the same window
virtual device queue or backend logs
reset reason
clocksource and timestamp basis for each log

Playbooks

userspace 前の boot loop

userspace を必要としない面を使う。

earlycon
serial console
dmesg from firmware or monitor capture
/sys/fs/pstore/console-ramoops-0 after reboot
hypervisor reset reason
host virtual console capture

問い:

• kernel は始まったか
• console は始まったか
• init は始まったか
• panic か watchdog か reset か
• reset 前の最後の timestamp はどの clock か

native service crash

まず crash record と同じ boot の journal を保存する。

journalctl -b --no-pager > journal.txt
coredumpctl list
coredumpctl info <PID-or-COREDUMP>
coredumpctl dump <PID-or-COREDUMP> > core.dump

その後、matching build artifacts で symbolize する。最後の userspace log 行で止まらない。crash record または core dump が実際の crash artifact だ。

gdb -q /path/to/bin core.dump

GDB で見る:

thread apply all bt full
info proc mappings
info sharedlibrary
info registers

その後、service log、kernel log、scheduler / IPC trace を合わせる。crash は結果であって原因とは限らない。

I/O latency or timeout

まず count と profile で大きさを見る。

perf stat -e task-clock,context-switches,cpu-migrations -a -- sleep 10
cat /proc/interrupts
cat /proc/softirqs

次に trace する。

dmesg --time-format=iso --decode | grep -iE 'timeout|reset|stall|I/O error'
trace-cmd record -e block:block_rq_issue -e block:block_rq_complete -e irq:* sleep 10
bpftrace -e 'tracepoint:block:block_rq_issue { @bytes = hist(args->bytes); }'

guest では、同じ window の host / hypervisor queue event と合わせる。guest 側の request issue に対して host 側の completion がないなら、境界の問題として扱う。

vCPU starvation

guest symptom:

• soft lockup
• RCU stall
• timer jump
• delayed workqueue
• long scheduling gap

guest evidence:

dmesg | grep -iE 'soft lockup|rcu|watchdog|sched|clocksource'
trace-cmd record -e sched:sched_switch -e irq:* sleep 10
cat /proc/schedstat
cat /proc/interrupts
cat /proc/softirqs

host evidence:

vCPU run/exit trace
physical CPU load
IRQ routing
virtual interrupt injection
timer event delivery
hypervisor scheduling class

RAM corruption

live:

cat /proc/slabinfo | head
cat /proc/buddyinfo
cat /proc/vmstat | grep -E 'pgfault|oom|compact|allocstall'
cat /sys/kernel/debug/page_owner 2>/dev/null | head

postmortem:

pstore panic record
vmcore
raw RAM dump
KASAN report
KFENCE report
page_owner snapshot
hypervisor stage-2 fault trace

raw RAM では exact kernel image と symbols を残す。KASLR が有効なら load offset を記録するか dump から取り出す。reserved region があるなら firmware table または device tree と /proc/iomem を一緒に残す。

Minimal capture sets

Linux guest

uname -a
cat /etc/os-release 2>/dev/null
cat /proc/cmdline
cat /proc/iomem
cat /proc/interrupts
cat /proc/softirqs
dmesg --time-format=iso --decode > dmesg.txt
journalctl -b --no-pager > journal.txt 2>/dev/null
journalctl -k -b --no-pager > journal-kernel.txt 2>/dev/null
ls -l /sys/fs/pstore 2>/dev/null
cp -a /sys/fs/pstore pstore 2>/dev/null || true
findmnt
lsblk -f
coredumpctl list 2>/dev/null

BPF readiness

zcat /proc/config.gz 2>/dev/null | grep -E 'BPF|BTF|KPROBE|FTRACE|TRACEPOINT'
ls -l /sys/kernel/btf/vmlinux
bpftool feature probe kernel
bpftool prog list
bpftool map list
bpftrace -l 'tracepoint:sched:*' | head

pstore readiness

zcat /proc/config.gz 2>/dev/null | grep -E 'PSTORE|RAMOOPS'
cat /proc/iomem | grep -iE 'pstore|ramoops|reserved'
ls -l /sys/fs/pstore
grep -R . /sys/module/ramoops/parameters 2>/dev/null

出力の読み方

出力 record は原因ではない。ある層が、ある時刻に、ある面を通して出した statement だ。

読むときは次を確認する。

1. どの層が出したか。
2. その層は出力時点でまだ正常だったか。
3. timestamp は guest time、host time、monotonic time、wall time のどれか。
4. それ以前の record は上書きされていないか。
5. instrumentation は timing を変えていないか。
6. 別の層が同じ transition を示しているか。
7. failure 後の symptom か、最初に観測できる state change か。

正しい証跡は failure mode を生き残る。userspace が死ぬなら kernel と RAM-backed records を使う。kernel が死ぬなら pstore、serial、hypervisor、dump を使う。guest が走っていないなら、host と hypervisor trace を使う。

References

• Linux tracing documentation
• Ramoops oops/panic logger
• BPF ring buffer
• libbpf overview and BPF CO-RE
• BTF documentation
• dmesg(1)