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

## 前回からのあらすじ

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

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

* **[wbthomason/packer.nvim](https://github.com/wbthomason/packer.nvim) がオワコン化して [folke/lazy.nvim](https://github.com/folke/lazy.nvim) が覇権を取った。**

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

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

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

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

* 方法(1)
    - Neovim の [`--startuptime` オプション](https://neovim.io/doc/user/starting.html#--startuptime)を指定して自分で測る。
* 方法(2)
    - [rhysd/vim-startuptime](https://github.com/rhysd/vim-startuptime) を利用して複数回の起動速度の平均値を得る。
* 方法(3)
    - [dstein64/vim-startuptime](https://github.com/dstein64/vim-startuptime) でどのスクリプトの処理に時間が掛かっているか調べる。

厳密には、「方法(3)」は起動速度を測る方法ではありません。また、「方法(2)」についても、[ソースを見ると](https://github.com/rhysd/vim-startuptime/blob/e805bd8f255835a2940233a99eeb2601871aa9a1/vim.go#L55-L66) `--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 のソースを見てみましょう[^1]。

[^1]: 以下、Neovim のソースは記事執筆時点の HEAD のものを利用しています。

### 起動速度の正体

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

https://github.com/neovim/neovim/blob/cc38630d39d2aa99183756d55849117daf6dfbfa/src/nvim/profile.c#L977-L991

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

https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/profile.h#L10-L12

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

* [`time_msg()`](https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/profile.c#L919-L948)
* [`profile_start()`](https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/profile.c#L51-L57)
* [`os_hrtime()`](https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/os/time.c#L25-L35)

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

* [`uv_hrtime()`](https://github.com/libuv/libuv/blob/ec5a4b54f7da7eeb01679005c615fee9633cdb3b/src/unix/core.c#L152-L154)（UNIX 系のもの）

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

* [`uv__hrtime()`](https://github.com/libuv/libuv/blob/ec5a4b54f7da7eeb01679005c615fee9633cdb3b/src/unix/darwin.c#L60-L63)（macOS）
    - [`mach_continuous_time()`](https://developer.apple.com/documentation/kernel/1646199-mach_continuous_time) を使っています。
* [`uv__hrtime()`](https://github.com/libuv/libuv/blob/ec5a4b54f7da7eeb01679005c615fee9633cdb3b/src/unix/linux.c#L1622-L1656)（Linux）
    - [`clock_gettime(2)`](https://ja.manpages.org/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` オプション](https://neovim.io/doc/user/starting.html#-%2Bc)、及び [ `-S` オプション](https://neovim.io/doc/user/starting.html#-S)は以下の部分で処理されます。

https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/main.c#L581-L584

`+q` 付きで起動した場合ここで Neovim が終了しまいます。周辺のソースを見ると、[`BufEnter` イベント](https://neovim.io/doc/user/autocmd.html#BufEnter) は[実行される](https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/main.c#L551-L551)ものの、[`VimEnter` イベント](https://neovim.io/doc/user/autocmd.html#VimEnter)と [`UIEnter` イベント](https://neovim.io/doc/user/autocmd.html#UIEnter)は[実行されない](https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/main.c#L597-L601)ことが分かります[^2]。

[^2]: これ以降を読み進めるためにはこれで十分なのですが、念のため、実際に `+q` で `--- NVIM STARTED ---` が表示されるロジックを追っておきます。`:quit` コマンドの実装は[この部分](https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/ex_docmd.c#L4713-L4776)にあります。最後の方で実行されている `getout(0)` が実際にプロセスを終了させる関数です。[ここ](https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/main.c#L701-L701)で `time_finish()` が呼ばれています。

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

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

https://github.com/rhysd/vim-startuptime/blob/e805bd8f255835a2940233a99eeb2601871aa9a1/vim.go#L24-L53

`-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` の後に[実行される](https://github.com/folke/lazy.nvim/blob/7e6c863bc7563efbdd757a310d17ebc95166cef3/lua/lazy/core/util.lua#L167-L196)ようです。人気のディストリビューション [LazyVim](http://www.lazyvim.org) のレポジトリを[「`VeryLazy`」で検索した](https://github.com/search?q=repo%3ALazyVim%2FLazyVim+language%3Alua+path%3Aplugins+VeryLazy&type=code)所、結構な数のプラグインがヒットしましたので、この事象に該当する人も多いのではないでしょうか。

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

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

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

| プラグイン     | イベント名              | ソース                                                                                                                                                                           |
|----------------|-------------------------|----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| snacks.nvim    | `SnacksDashboardOpened` | [`lua/snacks/dashboard.lua#L229`](https://github.com/folke/snacks.nvim/blob/c06f50e8950850c094244b985a45b69acf08992a/lua/snacks/dashboard.lua#L229-L229)                       |
| dashboard-nvim | `DashboardLoaded`       | [`lua/dashboard/theme/hyper.lua#L534-L537`](https://github.com/delphinus/dashboard-nvim/blob/b81485946fbf396c1f569f7d628465a0f14527b5/lua/dashboard/theme/hyper.lua#L534-L537) |

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

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

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

```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` に記録されます。

```bash
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()` の呼び出し時までの間です。

https://github.com/neovim/neovim/blob/022449b5223659d515b78bada7de2fac8718820a/src/nvim/main.c#L454-L454

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

[^3]: ちなみに、`nvim --startuptime` の起点も厳密には「Neovim プロセスの開始時点」ではありません。main.c の[この部分](https://github.com/neovim/neovim/blob/cc38630d39d2aa99183756d55849117daf6dfbfa/src/nvim/main.c#L275-L275)で値が初期化されていますので、この部分より前の時間は計測できていないことになります。

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

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

https://gist.github.com/delphinus/c72417c685fc1c2a8e35ca596cfa8fc3

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

```bash
~ ❯❯❯ 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 と実行結果を比較してみます。

```bash
~ ❯❯❯ 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`）はどのようにして計測しているのでしょうか。

![LazyVim.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/8880/53ba1606-3ae3-afcf-51cf-f78dd5f7dc67.png)

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

https://github.com/folke/snacks.nvim/blob/972c61cc1cd254ef3b43ec1dfd51eefbdc441a7d/lua/snacks/dashboard.lua#L1061-L1062

https://github.com/delphinus/dashboard-nvim/blob/b81485946fbf396c1f569f7d628465a0f14527b5/lua/dashboard/utils.lua#L122-L128

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

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

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


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

https://github.com/folke/lazy.nvim/blob/7e6c863bc7563efbdd757a310d17ebc95166cef3/lua/lazy/stats.lua#L34-L70

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

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

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


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

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

https://github.com/folke/lazy.nvim/blob/7e6c863bc7563efbdd757a310d17ebc95166cef3/lua/lazy/core/config.lua#L324-L329

https://github.com/folke/lazy.nvim/blob/7e6c863bc7563efbdd757a310d17ebc95166cef3/lua/lazy/stats.lua#L22-L26

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 回をすることを誓って、この記事を終わりたいと思います。