Crystal言語を使ってみる(nginxログ集計編)

毎度、ググっても出てこない小ネタを取り扱っております。
本記事は個人的な見解であり、筆者の所属するいかなる団体にも関係ございません。

0. はじめに

Crystal言語っておもしろそうなので使ってみたのnginxログ集計編になります。
以下のインストール編の続編です。

Crystal言語を使ってみる(インストール編) - Qiita
https://qiita.com/ynott/61ec5c8fad5e78c58fa2

実際にnginxのログ集計スクリプトを作成して、ファイルを読み込んで集計する時間を以下の3パターンで計測してみます。

1. Crystalでインタプリター実行した場合
2. Crystalでビルドして実行した場合
3. Crystalでリリースビルドして実行した場合
4. Ruby 3.0で実行した場合

動作環境は、以下の通りです。

Windows: 10 Pro(21H1)
WSL: Ubuntu 20.04.3 LTS
Crystal Version: 1.2.1
ログ: nginx access
ログファイルサイズ: 61MB

エディターは、VSCodeで書いておりVSCodeのコンソールから実行しています。

1. nginxのログ集計スクリプトを作成する

こんな風になりました(Crystal初学者なので変な書き方をしていたら突っ込み歓迎！)
最後のppがコメントアウトされているのは、標準出力をすると出力時間に影響されて
Crystal言語のスピードと無関係になってしまうかと思い計測時にはコメントアウトしています。

log-statics.cr

#! /bin/bin/crystal
require "option_parser"

time_static = Hash(String, Int32).new(0)
file_name = ""

OptionParser.parse do |parser|
  parser.banner = "Usage: log-statics [arguments]"
  parser.on("-f FILE", "--file FILE", "Log file") { |file| file_name = file }
  parser.on("-h", "--help", "Show this help") do
    puts parser
    exit
  end
  parser.invalid_option do |flag|
    STDERR.puts "ERROR: #{flag} is not a valid option."
    STDERR.puts parser
    exit(1)
  end
end

f = File.open(file_name)
f.each_line { | ln |
  time_st = ln.match(/[0-9.]* - .* (\[.*\]) .*/).try &.[1].to_s
  time_static["#{time_st}"] += 1
}
f.close

# pp time_static

2. 実行時間の計測

2-1. インタプリター(？)実行時

以下のようにtimeコマンドで実行時間を計測しました。

$ time crystal run ./log-statics.cr  -- -f access.log-20211109

real    0m3.608s
user    0m2.975s
sys     0m0.319s

3.6秒ぐらいですね。
複数回実行してみましたが、3.6～3.8秒でした。

2-2. コンパイルしてから実行

ビルドする時間

$ time crystal run ./log-statics.cr  -- -f access.log-20211109

real    0m3.608s
user    0m2.975s
sys     0m0.319s

ビルドした実行バイナリで実行してみます。

$ time ./log-statics -f ./access.log-20211109 

real    0m2.838s
user    0m1.954s
sys     0m0.179s

こちらはバラツキは少なく、2.8秒前後でした

2-3. リリースビルドしてから実行

リリースビルドする時間

$ time crystal build --release ./log-statics.cr 

real    0m12.486s
user    0m12.409s
sys     0m0.134s

リリースビルドの方が時間がかかりますね。

$ time ./log-statics -f ./access.log-20211109 

real    0m2.108s
user    0m1.295s
sys     0m0.145s

さらに早くなって2.1秒前後でした。

3. Rubyで実行

Rubyでも動かしてみます。

動かすRubyのバージョンはRuby2の3倍速いと言われる3.0.2です。

Rubyで書くとこんな感じです。

log-statics.rb

#!/usr/bin/ruby

require "optparse"

time_static = Hash.new(0)
file_name = ""

opts = OptionParser.new
opts.on("-f","--file FILE","Log file"){|v| file_name = v } 
opts.parse!(ARGV)


f = File.open(file_name)
f.each_line { | ln |
  time_st = ln.match(/[0-9.]* - .* (\[.*\]) .*/)[1].to_s
  time_static["#{time_st}"] += 1
}
f.close

# pp time_static

動かしてみます。

$ time ruby ./log-statics.rb -f ./access.log-20211109 

real    0m2.349s
user    0m1.451s
sys     0m0.069s

おや？
なんと！Ruby3の方が早いという結果が出てしまいました。

何回か実行してみましたが、2.38秒～2.48秒の間でした。

4. 結果とまとめ

実行言語	実行時間中央値(秒)
Crystalインタプリター実行	3.6秒
Crystalビルド実行	2.8秒
Crystalリリースビルド実行	2.1秒
Ruby3	2.4秒

Ruby3もあなどれないですね(というかファイルサイズが小さいですし、あまり差が出ないテストでしたね)。
Crystalでもリリースビルドでは面目躍如でRuby3のスピードを上回りました。

WSLで実行しているのでファイルIOスピードが律速している可能性もありますが、そこそこのスピードで動くのが確認できました。
また、Crystalはビルドする事によりシングルバイナリでサイズも小さいことがよいポイントですね。Dockerイメージ等に入れやすくなります。また、静的型付けによるバグ混入(NullPoバグ)が避けられるのもメリットです。

CrystalのコードからRubyのコードはほとんど手直しなしで動いたのも好材料です。
シーンに応じて使い分けていきたいと思います。