EPUBビルダの処理時間が多くなった（V3.2.0→V5.9.0 約6倍）

[Yuki-book]

EPUBビルダの処理時間

Ver3.2.0で作成した文章をVer5.9.0でEPUBビルドすると、処理時間が多くなりました。

Ver	Time	マシン
3.2.0	12.050秒	WSL Ubuntu 18.04
5.9.0	75.681秒	WSL2 Ubuntu 22.04

同じPCですが、環境が異なります。
環境の問題ならあきらめますが、もう少し速くならないものでしょうか。

DEBUGログ

DEBUGログを見ていると、最初の.re（preface.re）を処理した後に44秒かかっています。
preface.reをcatalog.ymlから外すとchapter_01.reの後で処理時間がかかっています。
すなわち、最初の.reを処理した後に処理時間がかかっているように見えます。
ここでは、どんな処理を行っているのでしょうか。

$ time rake epub
review-epubmaker  config.yml
• DEBUG   2024-08-08 10:29:43 +0900 Loaded yaml file (config.yml).
• DEBUG   2024-08-08 10:29:43 +0900 book03.epub will be created.
• DEBUG   2024-08-08 10:29:45 +0900 Created first temporary directory as /mnt/c/MyBook/review5/03_review-book/review-review/book03-epub.
• DEBUG   2024-08-08 10:29:45 +0900 Create preface.xhtml from re_content/preface.re.

　　　　★ここで44秒かかっている

• DEBUG   2024-08-08 10:30:29 +0900 Create chapter_01.xhtml from re_content/chapter_01.re.
• DEBUG   2024-08-08 10:30:31 +0900 Create chapter_02.xhtml from re_content/chapter_02.re.
• DEBUG   2024-08-08 10:30:33 +0900 Create chapter_03.xhtml from re_content/chapter_03.re.
• DEBUG   2024-08-08 10:30:35 +0900 Create chapter_04.xhtml from re_content/chapter_04.re.
• DEBUG   2024-08-08 10:30:36 +0900 Create chapter_05.xhtml from re_content/chapter_05.re.
• DEBUG   2024-08-08 10:30:39 +0900 Create chapter_06.xhtml from re_content/chapter_06.re.
• DEBUG   2024-08-08 10:30:41 +0900 Create chapter_07.xhtml from re_content/chapter_07.re.
• DEBUG   2024-08-08 10:30:43 +0900 Create chapter_08.xhtml from re_content/chapter_08.re.
• DEBUG   2024-08-08 10:30:46 +0900 Create chapter_09.xhtml from re_content/chapter_09.re.
• DEBUG   2024-08-08 10:30:49 +0900 Create chapter_10.xhtml from re_content/chapter_10.re.
• DEBUG   2024-08-08 10:30:51 +0900 Create appendix.xhtml from re_content/appendix.re.
• DEBUG   2024-08-08 10:30:53 +0900 Create postface.xhtml from re_content/postface.re.
• DEBUG   2024-08-08 10:30:55 +0900 Create bib.xhtml from re_content/bib.re.
• DEBUG   2024-08-08 10:30:57 +0900 Create index.xhtml from re_content/index.re.
• DEBUG   2024-08-08 10:30:59 +0900 Create revision.xhtml from re_content/revision.re.
• DEBUG   Call hook_afterbackmatter. (/mnt/c/MyBook/review5/03_review-book/review-review/index/bin/fook_index.sh)
• DEBUG   2024-08-08 10:31:01 +0900 Push titlepage.xhtml to ePUB contents.

　・・・省略・・・

• DEBUG   2024-08-08 10:31:07 +0900 Call ePUB producer.
• DEBUG   2024-08-08 10:31:16 +0900 Finished.
✔ SUCCESS built book03.epub

real    1m33.337s
user    0m7.125s
sys     0m3.284s

DEBUGログの改造

DEBUGログに時間を追加するために下記のように改造しています。

/var/lib/gems/3.2.0/gems/review-5.9.0/lib/review/loggable.rb

    def debug(msg, location: nil)
      now = Time.now
      logger.debug("#{now} #{msg}", location: location)
    end

[Yuki-book]

画像ファイルの処理に時間を要している？

config.ymlのimagedir:を変更してcover.jpg以外をない状態にすると格段に速くなります。

Ver	Time	マシン	備考
3.2.0	12.050秒	WSL Ubuntu 18.04
5.9.0	75.681秒	WSL2 Ubuntu 22.04
5.9.0	9.693秒	WSL2 Ubuntu 22.04	画像なし

$ time rake epub
review-epubmaker  config.yml
• DEBUG   2024-08-08 18:10:34 +0900 Create preface.xhtml from re_content/preface.re.
• DEBUG   2024-08-08 18:10:35 +0900 Create chapter_01.xhtml from re_content/chapter_01.re.

・・・省略・・・
⚠ WARN postface.re:23: image not bound: TheEnd
✔ SUCCESS built book03.epub

real    0m9.693s
user    0m6.560s
sys     0m0.350s

preface.re直後の44秒が1秒となりました。
ほとんどの処理時間を画像の確認?に要しているのかもしれません。

[Yuki-book]

WSL2 Windowsファイルアクセスに時間を要している？

WSL2からWindowsファイルにアクセスすると遅いらしいです。
ファイル一式をLinuxにコピーすると速くなります。

Ver	Time	マシン	備考
3.2.0	12.050秒	WSL Ubuntu 18.04	Win file
5.9.0	75.681秒	WSL2 Ubuntu 22.04	Win file
5.9.0	10.413秒	WSL2 Ubuntu 22.04	Linux file

Ver3.2.0の時は、Windowsファイルにアクセスしていも速いけど、Ver5.9.0では6倍必要。

$ time rake epub
review-epubmaker  config.yml
✔ SUCCESS built book03.epub

real    0m10.413s
user    0m9.286s
sys     0m0.556s

[kmuto]

過去にimage finderが遅い #1896 ということでチューニングはしたものの、類似の現象が発生しているのかな…と推測はしました。

• 公開可能な範囲かつ影響が顕在化するくらいまでにしたサンプルをいただくことは可能ですか？
• 画像ファイルはどのくらいの数がありますか？

[Yuki-book]

サンプルでの計測

現象が発生している原稿から公開できない部分を削除しました。
また、一部の画像ファイルも四角形の画像に置換しました。

Ver	Time	マシン	備考
3.2.0	12.050秒	WSL Ubuntu 18.04
5.9.0	75.681秒	WSL2 Ubuntu 22.04
5.9.0	23.743秒	WSL2 Ubuntu 22.04	サンプル

画像ファイルは、192個あります。

本文がないことと画像ファイルが小さくなったことで幾分速くなってしまいましたが、V3.2.0に比べて2倍の処理時間を要しています。
サンプルは、Windowsファイル格納してWSL2からにアクセスしています。

$ time rake epub
review-epubmaker  config.yml
✔ SUCCESS built book03.epub

real    0m23.743s
user    0m0.673s
sys     0m0.909s

サンプルの提供

book03x.zip

[kmuto]

Re:VIEW 5からIndexBuilderを導入しています https://review-knowledge-ja.readthedocs.io/ja/latest/releases/review500.html#58f2b4008c87db7e7d85a9f5e993c209 。
それ以前はreファイルの変換の都度、参照を探しにいっていたのですが、IndexBuilderでは最初に各参照を構成した後で変換に進みます。初手のprefaceで時間がかかるのはそのためです。画像についてもいったんimagesフォルダを探索するのでそこに時間がかかります。

ただ、いただいた情報で拝見すると、そもそもの3.2の時間も妙にかかっていますし、real-(user+sys)が22.161秒ということはCPUを使わない処理、おそらくI/O待ちが予想され、WSLのI/Oパフォーマンスに問題があるのではないかと予想します。
LinuxのDocker環境(i7コア)で3.2.0と5.9.0それぞれサンプルに対してtime rake clean epubを試したところでは、3.2.0では平均1.6秒、5.9.0では平均1秒でした。

https://learn.microsoft.com/ja-jp/windows/wsl/compare-versions によると、WSL/WSL2はマウントされたファイル(おそらく/mnt)についてI/Oパフォーマンスの低下が生じる仕様に見えます。試しにサンプルフォルダの内容を/mntでない別の場所(Windowsマウントでない場所)にコピーし、そこで実行してみることで、WSL I/O起因かどうかを判断できるかと思います。

WSL I/O起因だった場合はRe:VIEW側では手立てはなく、Dockerを試してみていただくなどの代替手段となりそうです。

[Yuki-book]

お手数おかけして申し訳ありませんでした。
原因は、WSL2からWindowsファイルアクセスとのこと了解です。

IndexBuilder導入により先に参照を構成して、都度参照しないようにした結果、6倍遅くなってしまったことは残念です。
Re:VIEWの進化において大事なターニングポイントだと思うので了解です。

どうもありがとうございました。

[kmuto]

あくまでも推測なので、

• /mnt以外にプロジェクトフォルダをコピーしてビルド計測してみる
• Dockerでビルドを試してみる

もしてみていただければと思います。
/mnt以外に置いたら速くなる & WSL2で使い続けたい ということであれば、たとえばビルド時にはビルド用フォルダにrsyncで同期させてビルドする、みたいな対処もできるのではないかと考えました(ただrsyncが数ファイルでも結局めちゃくちゃ遅い可能性はあります)。

[Yuki-book]

アドバイス、ありがとうございました。
説明不足でしたが、この10.413秒というのが、/mnt以外にプロジェクトファイルをコピーしたものです。

提供したサンプルプロジェクトを/mnt以外に配置すると 0m1.315sでEPUBビルドできました。

なんとなく、WSL2の問題なのかと推測していましたが、Ver3.2.0に比べて遅くなってしまった原因が不明でした。
　→　IndexBuilder導入が原因で、WSL2ファイルアクセス問題が発生。

EPUBビルドをLinux側で行う方針に変更します。
幸いWSL2は、Windows側からLinuxファイルを操作できることがわかりました。
プロジェクトをLinux側に配置することができそうです。

このたびは、ありがとうございました。

[kmuto]

はい、ご報告ありがとうございました!