PHP の Hello World を strace したら 2335 行出てきた話

echo "Hello"; だけの PHP スクリプトを strace にかけたら、ログが 2335 行になった。 C で同じことをすると 35 行。この 66 倍の差はどこから来るのか、というのが今回の話。

結論から言うと、犯人の 6 割は PHP ではなくバージョン管理ツールの shim で、さらにその原因は自分の設定ミスではなく、ディストリの設定ファイルが同じファイルの中で矛盾したことをしていた、というオチだった。

環境

Omarchy (Arch Linux ベース、Hyprland + uwsm)
PHP 8.x (Arch のシステムパッケージ、/usr/bin/php)
mise 2026.8.6

発端

対象はこれだけ。

<?php
echo "Hello";

strace -o hello.php.log php hello.php
wc -l hello.php.log
# 2335

C 版も用意して比べる。

#include <stdio.h>
int main(){ puts("Hello"); }

gcc -o h h.c
strace -o /dev/stdout ./h | wc -l
# 37

2335 対 37。さすがに差がありすぎる。

そもそも strace とは

プログラムは自分だけでは何もできない。ファイルを読む、画面に文字を出す、メモリを確保する——こうした「自分の外側」に関わる操作はすべて OS(カーネル)に依頼する必要がある。この依頼が システムコール で、 strace はそれを横から全部盗み見て記録するツールだ。

1 行の構造はこうなっている。

openat(AT_FDCWD, "/etc/php/php.ini", O_RDONLY) = 3
└──┬─┘ └──────────────┬───────────────────┘   └┬┘
 syscall名           引数                    返り値

「このファイルを読み込み専用で開いて」と頼み、OS が「番号 3 で開けた」と返した記録。失敗するとこうなる。

openat(AT_FDCWD, "/etc/php/php-cli.ini", O_RDONLY) = -1 ENOENT (No such file or directory)

「探したけど無かった」がそのまま見えるのが strace の面白いところで、設定ファイルの探索順序を調べるにはこれが一番確実だ。

実装として ptrace(デバッガが使うカーネル機能)で対象を毎回止めて覗くので、 実行速度は数倍〜数十倍遅くなる。strace した時間を性能の実測値にしてはいけない。 strace は回数を数える道具であって、速度計ではない。

ログを分割する

まず全体の内訳を数える。

grep -oP '^[a-z_0-9]+(?=\()' hello.php.log | sort | uniq -c | sort -rn | head

    664 statx
    313 readlink
    292 mmap
    199 read
    143 openat
    120 close
     89 fstat

statx 664 回と readlink 313 回が突出している。両方ともファイルの情報を調べるシステムコールで、「何かを大量に探している」形跡だ。PHP がスクリプト 1 行を実行するのにファイルを 600 回も調べる理由はない。

ここで execve を探すと、決定的なものが見つかる。

grep -n 'execve' hello.php.log

1:    execve("$HOME/.local/share/mise/shims/php", ["php", "hello.php"], ...) = 0
1498: execve("/usr/bin/php", ["/usr/bin/php", "hello.php"], ...) = 0

execve は「今のプロセスの中身を別のプログラムでまるごと置き換える」システムコール。これが 2 回あるということは、このログは 2 つの別プログラムの記録が連結したものだ。

1〜1497 行 … mise の shim (全体の 64%)
1498〜2335 行 … 本物の /usr/bin/php (36%)

php を叩いたつもりが、実際に起動していたのは mise の shim だった。

前半 1497 行の中身

shim が何を探しているのか、statx の対象を集計する。

sed -n '1,1497p' hello.php.log \
  | grep -oP 'statx\(.*?"\K[^"]+' | sed 's|/[^/]*$||' | sort | uniq -c | sort -rn | head

     74 $HOME/.local/share/mise/installs/gh
     74 $HOME/.local/share/mise/installs/codex
     74 $HOME/.local/share/mise/installs/claude
     30 $HOME/.local/share/mise/installs/go

PHP とまったく関係のない gh / codex / claude / go のディレクトリを延々と舐めている。mise が「どのツールのどのバージョンを使うか」を解決する処理だ。

しかも自分の mise 設定はこうなっている。

# ~/.config/mise/config.toml
[tools]
claude = "latest"
codex  = "latest"
gh     = "latest"
go     = "1.26.6"

php は mise の管理対象に入っていない。 実際ログ中に installs/php は 1 件も出てこず、最終的に起動したのはシステムの /usr/bin/php だ。

つまり shim は、「mise 配下に php はあるか?」を確認するために全ツールを走査して、「無いのでシステムのを使う」という最初から決まっている結論を出すためだけに、実行時間の半分近くを使っていたことになる。

後半 838 行の中身

こちらは PHP 本体の正当な起動処理。

読み込んでいる共有ライブラリは 62 本。

libxml2, libssl, libcrypto, libpcre2, libonig, libargon2, libicuuc,
libcurl, libnghttp2, libkrb5, libzip, libsqlite3, ...

さらに ini と拡張モジュールの探索。

openat("/usr/bin/php-cli.ini", O_RDONLY) = -1 ENOENT
openat("/etc/php/php-cli.ini", O_RDONLY) = -1 ENOENT
openat("/usr/bin/php.ini",     O_RDONLY) = -1 ENOENT
openat("/etc/php/php.ini",     O_RDONLY) = 3        ← ここで発見
openat("/etc/php/conf.d",      O_DIRECTORY) = 3
openat("/etc/php/conf.d/xdebug.ini", O_RDONLY) = 3

そして xdebug, bcmath, curl, iconv, intl, pdo_mysql, pdo_sqlite, zip を dlopen。ログ全体で ENOENT(ファイルが無い)が 349 回出ているが、その大半はこの手の探索の空振りだ。

strace -c で集計すると、面白いものが見える。

strace -c -f /usr/bin/php hello.php

socket  1 回
bind    1 回
listen  1 回

echo "Hello"; しかしていないのに、ソケットを作って待ち受けを開始している。 Xdebug がデバッガの接続を待つためのものだ。ソースを読んでも気づきにくい事実が、 strace だとそのまま出てくる。

ちなみに本命の 1 行はログの 2305 行目にある。

write(1, "Hello", 5) = 5

2335 行のうち、実際に仕事をしているのは 1 行だけだった。

余談: 終了間際に munmap が並ぶ理由

ログの末尾はこうなっている。

munmap(0x7f64b678f000, 45280)  = 0
munmap(0x7f64b67d4000, 614016) = 0
... (26 回) ...
exit_group(0)                  = ?

mmap がメモリ領域の確保(またはファイルの貼り付け)で、munmap がその解放。ただプロセスが終了すればメモリは OS が全部回収するので、本来この片付けは要らない。

実際 C 版は mmap 8 回に対して munmap は 0 回。貼りっぱなしで死ぬ。一方 PHP は mmap 220 回に対して munmap 28 回、うち 26 回が終了直前に集中している。拡張モジュールを dlclose() で律儀に 1 つずつ閉じているためだ。

「動的にモジュールをロードする言語」と「静的な小さいバイナリ」の性格差が、そのまま数字に出ていて面白い。

他の言語と比べる

ここで気になるのは「839 回って多いのか?」という点。並べてみた。

	syscall 数	起動時間
C	35	0 ms
Go	242	1 ms
PHP	839	13 ms
PHP (`-n`: ini/拡張なし)	445	8 ms
Python	3079	20 ms
Ruby	4595	40 ms
Node.js	3624	33 ms

意外なことに、PHP はスクリプト言語の中でいちばん軽い。 Ruby の 1/5、Node.js の 1/4 以下だ。

PHP は「1 リクエストで起動して処理して死ぬ」使い方を前提に起動を削り込んできた歴史があり、必要なものが C 拡張として .so に固めてある。Python や Ruby が起動時に大量の標準ライブラリを .py / .rb として探索・読み込みするのとは対照的だ。

Go の 242 回も味わい深い。静的リンクなのでライブラリ探索はゼロなのに、 GC やスケジューラの初期化だけでこれだけ使う。 「ランタイムを持つ」というだけでコストがかかることがよく分かる。

そして——PHP 本体 839 回より、その手前の shim 1497 行のほうが重かった。言語のランタイムコストを心配する前に、ツールチェーンのほうを疑うべきだった。

犯人探し

さて、なぜ mise 管理外の php まで shim を経由するのか。 PATH を見ると答えは明白だった。

10  $HOME/.local/share/mise/shims   ← こっちが先に見つかる
15  /usr/bin

shims が /usr/bin より前にいる。だから php と打つと shim が引かれる。

仮説 1: `mise activate` が犯人 → ハズレ

自分の .bashrc は Omarchy 標準の rc を読んでいて、その中で eval "$(mise activate bash)" が走る。これが PATH を再構成する際に shims を前に持ってきているのでは、と考えた。

検証。最小の PATH を作って activate してみる。

env -i HOME=$HOME PATH="/usr/local/bin:/usr/bin:/bin:$HOME/.local/share/mise/shims" bash -c '
  eval "$(mise activate bash)"
  echo "$PATH" | tr ":" "\n"'

$HOME/.local/share/mise/installs/claude/latest
$HOME/.local/share/mise/installs/codex/latest/bin
$HOME/.local/share/mise/installs/gh/latest/gh_2.98.0_linux_amd64/bin
$HOME/.local/share/mise/installs/go/1.26.6/bin
/usr/local/bin
/usr/bin
/bin
$HOME/.local/share/mise/shims      ← 末尾のまま。動いていない

mise activate は installs を先頭に足すだけで、shims の位置は動かさない。仮説はハズレ。

仮説 2: `.bashrc` の追記が犯人 → これもハズレ

.bashrc には export PATH="$HOME/.symfony5/bin:$PATH" のような追記がいくつもある。これらが順序を壊しているのでは、と考えた。

クリーンな環境で対話シェルを起動して確認する。

env -i HOME=$HOME USER=$USER TERM=xterm PS1='$ ' bash --rcfile ~/.bashrc -i <<'EOF'
echo "$PATH" | tr ':' '\n' | grep -n -E 'mise/shims$|^/usr/bin$'
EOF

16:/usr/bin
17:$HOME/.local/share/mise/shims    ← 正しい順序

正常。.bashrc も無罪だった。

ということは、汚染はシェルより手前——セッションの起動時点で起きている。

真犯人: uwsm のセッション環境

Omarchy は Hyprland を uwsm 経由で起動する。systemd の user セッションの環境変数を見てみる。

systemctl --user show-environment | grep ^PATH= | tr ':' '\n' | grep -n -E 'mise/shims|/usr/bin$'

 3  $HOME/.local/share/mise/shims   ← ここが有効になる
10  /usr/bin
11  $HOME/.local/share/mise/shims   ← 二重登録

shims が 2 回登録されていて、しかも /usr/bin より前が勝っている。

出どころは Omarchy パッケージが提供するこのファイル。

# /usr/share/uwsm/env.d/10-omarchy

# 冒頭: env-bootstrap を読む → shims を PATH の【末尾】に append
[ -r /usr/share/omarchy/default/bash/env-bootstrap ] && . /usr/share/omarchy/default/bash/env-bootstrap

...

# 最終行: shims を PATH の【先頭】に prepend
omarchy-cmd-present mise && eval "$(mise activate bash --shims)"

--shims モードの実体はこれだけだ。

$ mise activate bash --shims
export PATH="$HOME/.local/share/mise/shims:$PATH"

同じファイルの中で、末尾に足したものを先頭にもう一度足している。

しかも append 側の意図は、Omarchy 自身のコメントに明記されている。

# /usr/share/omarchy/default/bash/env-bootstrap
# User-level tool paths, appended so system binaries keep precedence. This is
# what lets login shells (ssh, bash -lc) and the uwsm session find mise-managed
# tools without an interactive rc.

appended so system binaries keep precedence

「システムのバイナリを優先させるため、末尾に追記する」と書いてある。その 20 行下で prepend しているので、意図と実装が真っ向から矛盾している。

この壊れた PATH が Hyprland セッション全体に継承され、ターミナル → bash → .bashrc と流れていく。.bashrc 側の env-bootstrap は「shims はもう PATH にある」と判断してスキップするため、誰も直せない。

Omarchy における shim 方式と activate 方式

そもそも mise には 2 つの導入方式がある。

shim 方式 … PATH に置いた symlink 経由。実体は mise 本体で、毎回起動してバージョンを解決してから本物を exec する。シェルを経由しない場所でも効くのが利点
activate 方式 … シェルの hook で PATH を書き換える。プロンプトごとに 1 回解決するだけなので、コマンド実行時のオーバーヘッドはゼロ

Omarchy はこれを併用する設計になっている。

方式	担当範囲	PATH 上の位置
activate	対話シェル(普段のターミナル)	主役
shims	ssh コマンド実行、`bash -lc`、uwsm セッション、GUI ランチャー	末尾(保険)

同じ思想は PAM の設定にも現れている。

# /etc/security/pam_env.conf
PATH DEFAULT=/usr/local/sbin:/usr/local/bin:/usr/bin:@{HOME}/.local/share/mise/shims:@{HOME}/.local/bin

ここでもちゃんと /usr/bin が shims より前だ。 設計は一貫して正しく、uwsm の 1 行だけがそこから外れている。

影響を受ける条件

Omarchy を使っている(10-omarchy は omarchy パッケージ提供)
Hyprland を uwsm 経由で起動している(Omarchy の標準構成)
mise がインストールされている
mise 管理外のツールをシステムにも入れている ← 実害が出るのはここ

4 番目が効いている。mise で全部管理している人は shim を通るのが正しい動作なので、誰も困らない。だから今まで表面化していなかったのだと思う。 Arch のシステム PHP と mise を併用しているという構成が、たまたま炙り出した形だ。

回避策

根本的には upstream が直すべきだが、それまでの対症療法として .bashrc の末尾で shims を末尾に押し戻す。

# mise の shims を PATH 末尾へ戻す
# omarchy の env-bootstrap は shims を PATH 末尾に追記してシステムバイナリを
# 優先させる設計だが、uwsm の `mise activate bash --shims` が先頭にも足すため
# 順序が壊れる。cd のたびに mise hook-env が PATH を作り直すので、
# PROMPT_COMMAND でも実行して順序を維持する。
_mise_shims_last() {
  local shims="$HOME/.local/share/mise/shims" p=":$PATH:"
  [[ $p == *":$shims:"* ]] || return 0
  p="${p//:$shims:/:}"
  p="${p#:}"
  p="${p%:}"
  export PATH="${p:+$p:}$shims"
}
_mise_shims_last
if [[ "$(declare -p PROMPT_COMMAND 2>/dev/null)" == "declare -a"* ]]; then
  [[ " ${PROMPT_COMMAND[*]} " == *" _mise_shims_last "* ]] ||
    PROMPT_COMMAND+=(_mise_shims_last)
else
  [[ ";${PROMPT_COMMAND:-};" == *";_mise_shims_last;"* ]] ||
    PROMPT_COMMAND="${PROMPT_COMMAND:+$PROMPT_COMMAND;}_mise_shims_last"
fi

mise activate は cd のたびに mise hook-env で PATH を作り直すため、一度並べ替えるだけでは戻される可能性がある。PROMPT_COMMAND に登録して毎回維持する。

検証結果。

起動直後        : shims=#19 /usr/bin=#16 -> php=/usr/bin/php
cd 1 回目       : shims=#19 /usr/bin=#9  -> php=/usr/bin/php
cd 2 回目       : shims=#19 /usr/bin=#9  -> php=/usr/bin/php
mise ls 後      : shims=#19 /usr/bin=#9  -> php=/usr/bin/php

shims は常に末尾を維持。mise 管理下の go も installs/go/1.26.6/bin/go から正しく解決され、go version も通る。 activate の速さと shims の保険を両取りできている。

効果

	修正前	修正後
`php hello.php` の strace 行数	2335	848
起動時間	約 28 ms	約 17 ms

statx 664 回・readlink 313 回のツール走査が丸ごと消えた。

計測値は実行ごとに数 ms ぶれる(直接叩いた場合で 13〜17 ms 程度の幅がある)。桁の話として読んでほしい。

まとめ

strace は「プログラムが OS に出した注文票」を全部プリントアウトする機械。ソースを読まずに実行の実態が掴める
execve を探すとログをプロセス単位に割れる。まずここを見ると全体構造が分かる
PHP の Hello World は 839 syscall。スクリプト言語としてはむしろ軽い (Ruby 4595、Node.js 3624、Python 3079)
2335 行のうち、実際に write していたのは 1 行だけ
そして 64% は PHP と無関係な shim だった。 言語のランタイムを疑う前に、その手前のツールチェーンを疑うべき
原因は自分の設定ミスではなく、ディストリビューションの設定ファイルが同じファイル内で append と prepend をしていたこと

「Hello World が遅い」は普通どうでもいい話だが、strace で分解すると PATH の設計思想からディストリのバグまで芋づるで出てくる。何か遅いと感じたら、まず strace -c を通してみるといい。

参考

man 1 strace
strace -c … syscall を集計。まずこれ
strace -e trace=file … ファイル関連だけ。設定ファイル探索の調査に
strace -f … 子プロセスも追う
strace -p PID … 動作中のプロセスに後から張り付く

注意: strace の出力には read / write の中身や環境変数が平文で載る。

環境

発端