VimAdvent Calendar 2024

あなたは多分、Neovim の本当の起動速度を知らない

neovim

Posted at 2024-12-19

前回からのあらすじ

以前アドベントカレンダーで「爆速で起動する Neovim を作る」という記事を書いたことがありました。あれから Neovim 界では様々なことがありましたが、みなさんも僕と同じように感謝の起動速度測定 10000 回を日課としておられることと思います。

この 2 年間で起こった、起動速度測定界隈（そんなものがあるの？）での一番重要な事件はこれでしょう。

wbthomason/packer.nvim がオワコン化して folke/lazy.nvim が覇権を取った。

思わず太字にしてしまいましたが、前回の記事が出てすぐに packer.nvim がオワコン化したことはショックでした。「packer.nvim では init.lua をコンパイルしてバイトコードで保存してるから起動速度が爆速～」なんて書いてたのに、そんな複雑な機構が存在しない lazy.nvim の方がより早く、より変更に強い init.lua を書けたのです。これは起動速度測定界隈（そんなものが（略））にとっては驚天動地の大事件でした。

それは本当に起動速度なの？

さて、本題に入ります。今日も日課の Neovim HEAD インストールからの nvim --startuptime をやって起動速度が変化しないか見る作業をしていたのですが、ふと気になりました。この値、本当に正しいの？

前回の記事で「起動速度を測る方法」として列挙したのは以下の 3 つです。

方法(1)
- Neovim の --startuptime オプションを指定して自分で測る。
方法(2)
- rhysd/vim-startuptime を利用して複数回の起動速度の平均値を得る。
方法(3)
- dstein64/vim-startuptime でどのスクリプトの処理に時間が掛かっているか調べる。

厳密には、「方法(3)」は起動速度を測る方法ではありません。また、「方法(2)」についても、ソースを見ると --startuptime オプションを利用していることが分かります。つまり、--startuptime オプションの実装を調べればこの「起動速度」が何を指しているのか判別できそうです。

`--startuptime` オプションの結果は何を表しているのか

まず、計測方法をおさらいしましょう。この方法では、nvim --startuptime hoge.log +q のように指定すると、hoge.log に Neovim の起動プロセスについて詳細なログを吐いて終了するのでした。この時 hoge.log には以下のような文字列が書き込まれています（最後の部分だけ表示します）。

……

148.366  001.148: opening buffers
148.851  000.346  000.346: sourcing /Users/jinnouchi.yasushi/.local/share/nvim/lazy/direnv.vim/autoload/direnv/extra_vimrc.vim
148.955  000.243: BufEnter autocommands
148.957  000.002: editing files in windows
148.975  000.019: --- NVIM STARTED ---

この 148.975 が起動速度です。この文字列はどのようにして吐かれているのか Neovim のソースを見てみましょう¹。

起動速度の正体

このファイルの文字列をどこで吐いているのか調査するため、--- NVIM STARTED --- という文字列でリポジトリを検索してみました。すると、吐いているのは、profile.c の time_finish() という小さな関数です。

TIME_MSG というのはマクロですね。これの展開元を見てみると、

以下、実際に左側の時刻（148.975）を生成しているコードを調べていきます。

最後に、uv_hrtime() に辿り着きました。これは libuv の関数です。その実装は libuv/libuv にあります。uv_hrtime() の実装は OS によって引数が異なるものの、uv__hrtime() に引き継がれています。

uv_hrtime()（UNIX 系のもの）

そして uv__hrtime() ですが、これは Linux や macOS では以下のようなロジックです（Windows は詳しくないのでパス）。

uv__hrtime()（macOS）
- mach_continuous_time() を使っています。
uv__hrtime()（Linux）
- clock_gettime(2) に、CLOCK_MONOTONIC_COARSE か CLOCK_MONOTONIC を指定して時刻を得ています。

やっと分かりました。CLOCK_MONOTONIC は単調増加する時刻で、ベンチマーク用途などに良く使われます（mach_continuous_time() も似たようなもんです）。ある時点でこれの差分を取って起動速度（148.75）を出していたのです。

`--- NVIM STARTED ---` の正体

ではこの、--- NVIM STARTED --- はどこで吐かれているのでしょう。time_finish() という関数が吐いているのは分かったのですが、この関数の呼び出し元は複数あって分かりにくいです。

結論から言うと、このメッセージは Neovim の起動方法によって出力箇所が異なります。つまり、--- NVIM STARTED --- が示す「起動速度」をそのまま使うと、実際に体感できるそれとは違った値を指している可能性があります。

`+q` 付きで起動する場合（「方法(1)」）

「方法(1)」では --startuptime の後ろに +q を付けて、測定が終わったら即時に Neovim を終了していました。起動時に指定された +, -c オプション、及び -S オプションは以下の部分で処理されます。

+q 付きで起動した場合ここで Neovim が終了しまいます。周辺のソースを見ると、BufEnter イベントは実行されるものの、VimEnter イベントと UIEnter イベントは実行されないことが分かります²。

`vim-startuptime` の場合（「方法(2)」）

vim-startuptime コマンドの場合は更に事情が異なります。Neovim を起動しているソースは以下の部分です。

-c qall! を付けて起動しているのは上記の +q と同じですので、time_finish() の呼び出し箇所は同じです。もう一つ重要なことは --headless を付けて実行しているため、UI プロセス自体がアタッチされていません。ベンチマークを取るという目的なら問題無いかも知れませんが、その計測された値は実際に Neovim を利用する際の感覚とはズレてしまう可能性があります。

`--startuptime` は実際に Neovim を操作する時の実態を表していない（かも知れない）

という訳で、あなたの init.lua に少なくとも VimEnter や UIEnter を契機として実行されるコードがある場合、--startuptime に示される値は実際の使用感とは懸け離れたものになっている恐れがあります。例えば lazy.nvim を利用している場合、以下のような記述をしているプラグインが該当します。

event = { "VimEnter" }
event = { "UIEnter" }
event = { "VeryLazy" }

最後の VeryLazy イベントは lazy.nvim 独自のものですが、これは UIEnter の後に実行されるようです。人気のディストリビューション LazyVim のレポジトリを「VeryLazy」で検索した所、結構な数のプラグインがヒットしましたので、この事象に該当する人も多いのではないでしょうか。

「本当の起動速度」を測る

じゃあどうしたらいいのか。となるのですが、これに関して簡単な解決法はありません。起動処理が完了し、プラグインの初期化処理が終わった時点というのを判定する方法が無いからです。

ただし先ほど例に挙げました LazyVim のように、ダッシュボード（起動画面）を表示している人はこれを判定できる可能性があります。例えば LazyVim は folke/snacks.nvim（以前は nvimdev/dashboard-nvim）というダッシュボードプラグインを利用していました。これらのプラグインはダッシュボードの表示が完了した際、以下のようなイベントを実行するようになっています。

プラグイン	イベント名	ソース
snacks.nvim	`SnacksDashboardOpened`	`lua/snacks/dashboard.lua#L229`
dashboard-nvim	`DashboardLoaded`	`lua/dashboard/theme/hyper.lua#L534-L537`

ダッシュボードの表示が完了しているんだったら、ユーザーが操作可能になっていると見做して良いのではないでしょうか。以下では例として、dashboard-nvim で「本当の起動速度」を測定する方法を見ていきましょう。

「本当の起動速度」をファイルに保存するスクリプト

最初に、init.lua の冒頭に以下のコードを挿入します。

if vim.env.LOGFILE or vim.env.WARMUP then
  local start = vim.uv.hrtime()
  vim.api.nvim_create_autocmd("User", {
    once = true,
    -- snacks.nvim の場合はここを
    -- "SnacksDashboardOpened" とします。
    pattern = "DashboardLoaded",
    callback = function()
      if vim.env.LOGFILE then
        local finish = vim.uv.hrtime()
        vim.fn.writefile({ tostring((finish - start) / 1e6) }, vim.env.LOGFILE, "a")
      end
      vim.schedule_wrap(vim.cmd.qall) { bang = true }
    end,
  })
end

これを以下のようにして使うと、「本当の起動速度」が /tmp/hoge.log に記録されます。

env LOGFILE=/tmp/hoge.log nvim

init.lua 冒頭で起動時刻を保存し（local start = vim.uv.hrtime()）、ダッシュボードの表示が完了した時起こるイベント DashboardLoaded までの時間を環境変数 $LOGFILE に指定されたファイルに保存しています。全部終わったら :qall! を実行して Neovim を終了します。環境変数 $WARMUP が指定された時はファイルに保存する操作を行わず、DashboardLoaded に到達したらすぐに終了するようにしています。

これにより start と finish の差で表される「本当の起動速度」が分かるという訳です。ただし init.lua を使う以上しょうがないことなのですが、この値には Neovim が起動してから init.lua の評価が始まるまでの時間が含まれません。ソースコードで言うと source_startup_scripts() の呼び出し時までの間です。

nvim --startuptime の結果によると、ここまでの時間は僕の環境では 5ms 程度です（init default mappings & autocommands が出力されるまでの間です）。最終的な結果にこの程度の時間は上乗せされることを覚えておきましょう³。

保存した「本当の起動速度」を集計する

普通に env LOGFILE=/tmp/hoge.log nvim やるだけだと 1 回実行して終わりです。これを vim-startuptime のように複数回実行して集計するスクリプトを作りました。

特に複雑なことはしていないので中身は解説しません。以下のようにして使います。

~ ❯❯❯ bench-nvim -h
Usage:
        bench-nvim
        # Run nvim 10 times after 1 warmup

        bench-nvim -c 100 -w 5
        # Run nvim 100 times after 5 warmups

        bench-nvim -l /tmp/foo.log
        # Store results into /tmp/foo.log

        bench-nvim -h
        # See this help

vim-startuptime と実行結果を比較してみます。

~ ❯❯❯ vim-startuptime -vimpath nvim -count 100 | head -20
Extra options: []
Measured: 100 times

Total Average: 69.743620 msec
Total Max:     79.262000 msec
Total Min:     66.035000 msec

~ ❯❯❯ bench-nvim -c 100
Measured 100 times

Total Average: 138.887355 msec
Total Max:     185.870666 msec
Total Min:     129.550209 msec

随分違った値になりましたね。僕の環境では VimEnter / UIEnter / VeryLazy で起動するプラグインが多いため、このような結果になったのでしょう。Min と Max の差が大きいことも含めて実際の使用感にあった値になっていると思います。

ダッシュボードに表示される起動速度の正体

さて、前節でこの記事の目的はあらかた達したのですが、一つここで疑問があります。LazyVim で利用されているダッシュボード（snacks.nvim や dashboard-nvim によるもの）には起動速度と思しき値が表示されています。この値（下記の画像では 34.51ms）はどのようにして計測しているのでしょうか。

これは snacks.nvim、dashboard-nvim、共に、lazy.nvim の一機能である require("lazy.stats").stats().startuptime という値を利用しています。

この値は startuptime という名前をしていますが、実は、以下の二つの理由から「起動速度」と言える値ではありません。

理由(1) 実時間ではなく CPU 時間を計測している
理由(2) 計測終了時点が UIEnter イベントである

理由(1) 実時間ではなく CPU 時間を計測している

lazy.nvim のソースを見てみますと、この値は C の clock_gettime(2) を直接呼んで取得しています。

これ、「起動速度の正体」の節で見た、uv__hrtime() の実装に似ていますね。しかし大きな違いがありまして、uv__hrtime() は CLOCK_MONOTONIC を使っていたのに、ここでは CLOCK_PROCESS_CPUTIME_ID を利用しています。これらの間には man ページによると以下のような違いがあります。

	説明（抜粋）
`CLOCK_MONOTONIC`	ある開始時点からの単調増加の時間で表現されるクロック
`CLOCK_PROCESS_CPUTIME_ID`	プロセス単位の CPU タイムクロック

つまり、ダッシュボードに表示される起動速度のような数値（lazy.nvim の startuptime）は実時間では無く、それまでに CPU が消費した時間を表しています。具体的には、プラグインが外部のファイルを実行していたり、ストレージ、ネットワークによる I/O が発生していたとしても、掛かった時間は計測されないのです。

理由(2) 計測終了時点が `UIEnter` イベントである

これも lazy.nvim のソースを見ると分かります。startuptime の値は UIEnter イベントで記録されています。

snacks.nvim や dashboard-nvim といったダッシュボードは UIEnter で描画を開始します。そのため、startuptime の値にはダッシュボードの表示、また、他の UIEnter イベント（及び VeryLazy イベント）で起動するプラグインで掛かった時間は含まれていないことになります。

これらの実装仕様は意図的なものだと思われます。lazy.nvim はプラグインマネージャであって、require "lazy.stats" はその動作速度を計測するモジュールです。lazy.nvim 自身のプロファイリングに使えるようなデータを提供するのが目的なのでしょう。

という訳で、ダッシュボードに表示される startuptime はあくまで参考程度、本当の起動速度を知りたい時は前節のようなスクリプトを利用した方が良いという結論になります。

まとめ

本記事では Neovim の --startuptime オプションについて動作を実装レベルで理解し、それが「本当の起動速度」と異なる可能性について説明しました。また、snacks.nvim や dashboard-nvim などのダッシュボードプラグインで表示される値が Neovim のチューニングに役立たないことも分かりました。

これからもみなさんが vim-startuptime で計測した値や、ダッシュボードに表示される値に振り回されることなく、「真に高速に起動する Neovim」を求めて精進されるよう、日々感謝の Neovim 起動 10000 回をすることを誓って、この記事を終わりたいと思います。

以下、Neovim のソースは記事執筆時点の HEAD のものを利用しています。 ↩
これ以降を読み進めるためにはこれで十分なのですが、念のため、実際に +q で --- NVIM STARTED --- が表示されるロジックを追っておきます。:quit コマンドの実装はこの部分にあります。最後の方で実行されている getout(0) が実際にプロセスを終了させる関数です。ここで time_finish() が呼ばれています。 ↩
ちなみに、nvim --startuptime の起点も厳密には「Neovim プロセスの開始時点」ではありません。main.c のこの部分で値が初期化されていますので、この部分より前の時間は計測できていないことになります。 ↩

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up