(1) eval編では、Spinelでコンパイルしたプログラムの中にRubyのインタプリタを組み込むツール、Fluxpinel¹を紹介しました。この記事は、ユーザがRubyで書いたプラグインを、コンパイル済みのプログラムが実行時に読み込む例を紹介します。

アクセスログを解析するCLI、logqを作りました。Fluxpinelのリポジトリのexamples/logqにあります。

ログの読み込み、絞り込み、集計といった重いループはSpinelがコンパイルします。そして「何を調べるか」は、ユーザがRubyでファイルに書いておき、CLIが実行時にそれを読み込みます。

ファイル構成

examples/logq/
├── app.rb                  # カーネル: Spinelがコンパイルする
├── dsl.rb                  # DSLの土台: 実行のたびにFluxpinelが読む
├── gen.rb                  # サンプルのログを作る
└── queries/
    ├── errors.rb           # クエリ: ユーザが書く
    └── per_row_block.rb    # 同じ種類のクエリを、行ごとのブロックで書いたもの

build/logq/
└── logq                    # app.rbとFluxpinelをひとつにしたバイナリ

それぞれのファイルの役割は次のとおりです。ここで「ユーザ」とは、ログに対して具体的な調査をしたい人です。

app.rbだけがコンパイルされて、バイナリbuild/logq/logqになります。このバイナリには、Fluxpinel（インタプリタ）も入っています。dsl.rbとqueries/*.rbはふつうのRubyのファイルのまま、実行のたびにバイナリが読み込みます。

ビルドは一度だけです。

$ make host HOST=build/logq HOST_NAME=logq KERNEL=examples/logq/app.rb KERNEL_MAIN=Logq.main \
    KERNEL_ENTRIES=Logq.main,Logq.all,Logq.where,Logq.slower,Logq.where_block,Logq.top,Logq.count_by

KERNEL_ENTRIESは、スクリプトから呼べるようにエクスポートするメソッドです。KERNEL_MAINは、バイナリの起動時に呼ぶメソッドです。

あとは何度でも実行できます。

$ ruby examples/logq/gen.rb 1000000 > access.log
$ build/logq/logq access.log examples/logq/queries/errors.rb

つまりユーザが触るのはqueries/の下だけです。クエリを書き換えて、すぐにもう一度実行できます。dsl.rbの場所は、コンパイル時の__dir__（examples/logq）が決めます。そのため、いまはFluxpinelのトップディレクトリから実行します。

ユーザが書くクエリ

queries/errors.rbはこんなファイルです。

# queries/errors.rb
report "slow 5xx" do
  where_status(500..599).slower_than(1.0).top(5, by: :duration)
end

report "POST by path" do
  where_verb("POST").count_by_path
end

report "API errors" do
  where_path(%r{\A/api/}).where_status(400..).size
end

where_statusやcount_by_pathというメソッドは、どこにも定義されていません。method_missingが名前を見て、カラムに対する操作に読み替えます。そして初回の呼び出しでdefine_methodしてメソッドを生やし、2回目からはふつうのメソッド呼び出しになります。Rubyピーポーが好きなやつです。

DSLの土台

これもFluxpinelが実行時に読み込むRubyだから、再ビルドなしにlogqの語彙を増やせます。

# dsl.rb
class Query
  def initialize(sel) = @sel = sel

  def size = @sel.size
  def slower_than(sec) = Query.new(Logq.slower(@sel, sec))
  def where(&blk) = Query.new(Logq.where_block(@sel, blk))
  def top(n, by:) = Logq.top(@sel, n, by.to_s)

  def method_missing(name, *args)
    case name
    when /\Awhere_(\w+)\z/
      field = $1
      self.class.define_method(name) { |cond| Query.new(Logq.where(@sel, field, cond)) }
    when /\Acount_by_(\w+)\z/
      field = $1
      self.class.define_method(name) { Logq.count_by(@sel, field) }
    else
      return super
    end
    send(name, *args)
  end

  def respond_to_missing?(name, include_all = false) = name.match?(/\A(where|count_by)_\w+\z/) || super
end

class Reports
  def initialize = @list = []
  def add(title, blk) = @list << [title, blk]

  # the title and the result of each report; a Query answers its size
  def run
    @list.map do |title, blk|
      result = Query.new(Logq.all).instance_eval(&blk)
      [title, result.is_a?(Query) ? "#{result.size} rows" : result]
    end
  end
end

REPORTS = Reports.new

def report(title, &blk) = REPORTS.add(title, blk)

REPORTS

Queryが持っているのは、選んだ行の番号の配列（@sel）だけです。Logq.all、Logq.where、Logq.count_by、Logq.topは、コンパイル済みのコードのエントリです。100万行のループはCの速さで回ります。DSLの側では、次のことが起きます。

• method_missingが受ける
• 実行時に組み立てた名前のメソッドを、define_methodが生やす
• sendが呼び直す
• instance_evalが、ブロックのselfを差し替える

Queryはスクリプトで定義したクラスです。where_statusの呼び出しを解決し、見つからなければmethod_missingに回すのは、SpinelではなくFluxpinelです。

カーネルとスクリプトの境界

こちらはSpinelでコンパイルする側です。ログを列ごとの配列に読み込み、dsl.rbとユーザのクエリを読ませ、結果を表示します。抜粋です。

# app.rb（抜粋）
require_relative "../../kernel/fluxpinel"

module Logq
  class Table
    attr_reader :verbs, :paths, :statuses, :durations
    # ...
  end

  TABLE = Table.new

  # the rows of sel whose field takes cond with ===: a value, a Range, a
  # Regexp or a class
  #: (Array[Integer], String, untyped) -> Array[Integer]
  def self.where(sel, field, cond)
    out = []
    case field
    when "verb" then sel.each { |i| out << i if cond === TABLE.verbs[i] }
    when "path" then sel.each { |i| out << i if cond === TABLE.paths[i] }
    when "status" then sel.each { |i| out << i if cond === TABLE.statuses[i] }
    when "duration" then sel.each { |i| out << i if cond === TABLE.durations[i] }
    else raise ArgumentError, "no field #{field}"
    end
    out
  end

  def self.main(args)
    n = load(args[0])
    puts "#{n} rows"
    dsl = Fluxpinel.load(File.join(__dir__, "dsl.rb"))
    Fluxpinel.load(args[1])
    Fluxpinel.call(dsl, "run", []).each do |title, result|
      puts "== #{title}"
      print_result(result)
    end
  end
end

#: (Array[Integer], String, untyped) -> Array[Integer]は、Spinelが読むインラインのRBSです。whereはスクリプトからしか呼ばれず、コンパイル済みのコードの中には呼び出し元がありません。呼び出し元がない引数は、Spinel上では型のない値になります。RBSを付けると、selは整数の配列として扱われ、ループが型付きのCになります。

エントリが返す整数の配列は、スクリプトの側でもそのまま持てます。それをまた次のエントリに渡すので、行の番号の配列はコピーされずに、カーネルとスクリプトの間を行き来します。

カーネルとスクリプトの間の行き来は、次のとおりです。

• カーネルがスクリプトを読み込む：Fluxpinel.load
• カーネルがスクリプトのメソッドを呼ぶ：Fluxpinel.call(dsl, "run", [])
• スクリプトがカーネルのエントリを呼ぶ：Logq.where(...)など

Fluxpinelの効かせ方

ここで疑問が湧くと思います。Fluxpinelは素朴なインタプリタです。ログ100万行が毎回ユーザのクエリを呼んだら、全体はインタプリタの速さになってしまうのでは？

そのとおり。だからlogqは、行のループ内でスクリプトが走らないように作ってあります。

where_status(500..599).slower_than(1.0).top(5, by: :duration)

このクエリでFluxpinelがエントリを呼ぶのは、3回だけです。たとえばwhere_status(500..599)は、Logq.where(@sel, "status", 500..599)を1回呼びます。100万行のループはエントリの中、つまりコンパイル済みのコードで回ります。条件の500..599は値のままカーネルに渡って、カーネルが各行でcond === vを評価します。これはランタイムのRange#===だから、ネイティブの速さです。

queries/errors.rb（Fluxpinel）        app.rb（AOT）
  where_status(500..599)   ---1回--->   Logq.where:  100万行のループ
  .slower_than(1.0)        ---1回--->   Logq.slower: 残りの行のループ
  .top(5, by: :duration)   ---1回--->   Logq.top:    ソート

スクリプトの仕事は「操作の数」に比例し、「行の数」には比例しません。動的な部分のコストは誤差になります。pandasやNumPyと似た形です。Pythonが操作を組み立てて、ループはCが回すんですよね？（あんまりわかってない）

逆に、行ごとのブロックを許すと遅くなります。dsl.rbのwhereはブロックを取り、こう書くこともできます。

# queries/per_row_block.rb これはダメな例です
report "API errors (block)" do
  where { |row| row["path"].start_with?("/api/") && row["status"] >= 400 }.size
end

errors.rbの”API errors”と同じことを調べるクエリです。カーネルのLogq.where_blockは、各行でこのブロックを呼びます。

#: (Array[Integer], untyped) -> Array[Integer]
def self.where_block(sel, blk) = sel.select { |i| Fluxpinel.call(blk, "call", [TABLE.row(i)]) }

ログが100万行なら、インタプリタに100万回入ってしまいます。どこまでを動的にして、どこからをAOTにするか。その線引きが、Fluxpinelの使いどころです。

結果

100万行のログにerrors.rbを実行した結果:

$ build/logq/logq access.log examples/logq/queries/errors.rb
1000000 rows
== slow 5xx
  {"verb" => "GET", "path" => "/api/users", "status" => 500, "duration" => 2.997}
  {"verb" => "GET", "path" => "/", "status" => 503, "duration" => 2.997}
  {"verb" => "DELETE", "path" => "/static/app.js", "status" => 502, "duration" => 2.997}
  {"verb" => "GET", "path" => "/static/app.css", "status" => 502, "duration" => 2.997}
  {"verb" => "GET", "path" => "/", "status" => 500, "duration" => 2.997}
== POST by path
  /static/app.css: 12590
  /static/app.js: 12581
  /cart: 12509
  /logout: 12496
  /api/users: 12451
  /api/orders: 12417
  /api/items: 12388
  /search: 12377
  /: 12338
  /login: 12294
== API errors
  24843

kernel/fluxpinel_cruby.rbは、Fluxpinel.loadなどのCRuby版の実装です。ruby -rがこれを読み込めば、同じapp.rb、dsl.rb、クエリがCRubyの上でも動きます（Logq.main(ARGV)を呼ぶ小さなファイルも要ります。手順はREADMEにあります）。出力も一致します。

時間を比べます。100万行、7回ずつ実行した中央値です。揺れを減らすため、どれもCPUのコアを1つに固定しています。CRubyは4.0.9。YJITとZJITを有効にした場合も測りました。

操作を組み立てるDSL（errors.rb）なら、全体でCRubyのインタプリタの約2.8倍、YJITやZJITと比べても約2.6倍の速さです。method_missingとdefine_methodが動いているのに。

その一方、行ごとのブロック（per_row_block.rb）にすると、全体の時間はCRubyとほとんど変わりません。per_row_block.rbのクエリは、errors.rbの3つのレポートのうちの1つと同じなのに、全体で1.4秒ほど余計にかかっています。読み込みで稼いだぶんを、100万回インタプリタに入ることによって使い果たしてしまいました。

このようにlogqを作り直さずに、ユーザは好きなクエリを書けます。RakefileやGemfileと同じ、「ツールの設定や拡張をRubyのDSLで書く」という作法を、コンパイル済みのツールに持ち込めるわけです。

つぎはいよいよRails

AOTコンパイラだから、Rubyの動的なところはあきらめる。そんなふうに考えていた時期が筆者にもありました。でもlogqを作ってみると、問題は「動的か、速いか」ではなく「どこに線を引くか」でした。ホットパスはコンパイル済みのコードに置く。操作を組み立てるところには、method_missingやdefine_methodを書いていい。この線をうまく引ければ、速さはほとんど落ちません。

(3) Railsコンソール編では、動いているRailsバイナリにソケット接続するコンソールを作ります。