今回はログの出力を抑制する方法を見てみます。ログの出し方は前回の投稿 はじめてな Elixir(23) ログを出力する を御覧ください。
デバッグ中にはログをジャンジャン出したいところです。しかし、ログ出力がアプリケーションの動作に悪影響を与えたりすることもあるでしょう。ログ出力が不要になったときに、もう一切ログの影響を受けたくないけど、でもまたデバッグのときには以前と同じ様にログを出したい… なんてこともあるでしょう。Elixir の Logger はこの辺は良く出来てる感じです。
ログ出力を制御する
Elixir でログの出力を制御するには
- Logger の関数を用いる
- アプリケーションを開始する前にパラメータを設定しておく
- アプリケーションの動作中にパラメータを設定する
という3つのパターンがあり、それぞれ設定できる内容に違いがあります。
ログ機能を on/off する
一番シンプルな方法で単純にログ機能を止めたり再開したりします。
iex(1)> require Logger # Logger モジュールを呼ぶ
Logger
iex(2)> Logger.info("hello world!") # info レベルで出力する
19:19:16.597 [info] hello world! # ログが出力される
:ok
iex(3)> Logger.disable(self()) # ログ機能を無効にする
:ok
iex(4)> Logger.info("hello world!") # 今度はログが…
:ok # …出力されない
iex(5)> Logger.enable(self()) # ログ機能を有効にする
:ok
iex(6)> Logger.info("hello world!") # やってみると…
19:19:38.455 [info] hello world! # …ログが出力される
:ok
これは自分だけでなく他のプロセスのログ機能も（プロセス番号が分かっているなら）on/off できます。
アプリケーションの動作中に設定できる制御
公式マニュアルでは Runtime Configuration というのに分類しています。設定できるパラメータが6種類ほどあります。ここではそのいくつかを試します。
なお、プログラム中でも設定の変更ができますし、config/config.exs に設定を書いておいて起動時に有効にすることもできます。
ログレベルを変える
Logger ではログレベルの概念があり、緊急性の高い方から :error, :warn, :info, :debug の4種類があります（なぜ syslog に完全に合わせないんだ！ 不満）。緊急性の高い方を表示して、そうでないのを表示しないためには :level を設定します。
defmodule Temp4 do
require Logger
def log() do
Logger.error("Error: hello")
Logger.warn("Warn: hello")
Logger.info("Info: hello")
Logger.debug("Debug: hello")
end
end
とかやって実行してみましょう。
iex(1)> c "temp4.ex"
[Temp4]
iex(2)> Temp4.log # 4種類のレベルのログを表示させる
18:21:51.313 [error] Error: hello
18:21:51.316 [warn] Warn: hello
18:21:51.316 [info] Info: hello
18:21:51.316 [debug] Debug: hello
:ok
# 4つのログが全部表示される
iex(3)> Logger.configure(level: :info) # info に制限
:ok:
iex(4)> Temp4.log # 4種類のレベルのログを表示させる
18:22:25.330 [error] Error: hello
:ok
18:22:25.330 [warn] Warn: hello
18:22:25.330 [info] Info: hello
# debug レベルは表示されない
iex(5)> Logger.configure(level: :warn) # warn レベルに制限
:ok
iex(6)> Temp4.log
18:22:37.156 [error] Error: hello
:ok
18:22:37.156 [warn] Warn: hello
# debug, info レベルは表示されない
iex(7)> Logger.configure(level: :error) # error レベルに制限
:ok
iex(8)> Temp4.log
18:22:42.398 [error] Error: hello
:ok
# debug, info, warn レベルは表示されない
iex(9)> Logger.configure(level: :debug) # debug レベルに戻す
:ok
iex(10)> Temp4.log
18:22:48.795 [error] Error: hello
:ok
18:22:48.795 [warn] Warn: hello
18:22:48.795 [info] Info: hello
18:22:48.795 [debug] Debug: hello
# 再び全てのログが表示される
iex(11)>
UNIX syslog の動作と似てますからわかりやすいですね、ね！
タイムゾーンを変える
これは表示の制約じゃないですが、まあ、簡単にできるのでやってみましょう。
iex(12)> require Logger
Logger
iex(13)> Logger.info("good evening world") # ログ表示をすると
18:29:25.236 [info] good evening world # 地元時刻(JST)表示になる
:ok
iex(14)> Logger.configure(utc_log: :true) # という設定を入れると
:ok
iex(15)> Logger.info("good evening world")
09:29:40.946 [info] good evening world # 協定世界時(UTC)表示になる
:ok
iex(16)> Logger.configure(utc_log: :false) # という設定を入れると
:ok
iex(17)> Logger.info("good evening world")
18:29:46.122 [info] good evening world # 地元時刻(JST)表示にもどる
:ok
タイムゾーンが明示されないのがアレですな。表示フォーマットをいじれるのでハックすればできるようになるでしょう。
ログ表示の文字数を制限する
文字数の制限は :truncate に設定します。デフォは 8192 です。先程のモジュールに以下を追加します。
def log_long(n) do
Stream.repeatedly(fn -> "z" end)
|> Enum.take(n) |> Enum.join |> Logger.info()
end
同じ文字を沢山出すってこんな関数で良いんですかね。パッとこれしか思いつかなかった。
iex(1)> c "temp4.ex"
[Temp4]
iex(2)> Temp4.log_long(10) #10文字出力する
18:35:55.925 [info] zzzzzzzzzz
:ok
iex(3)> Temp4.log_long(10000) #10000文字出力する
18:35:59.823 [info] zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz
# 途中は省略します…
zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz (truncated) #長すぎて後ろは切られた
:ok
iex(4)> Logger.configure(truncate: 20) # ログ長を20文字に制限
:ok
iex(5)> Temp4.log_long(10000) # 10000文字出力しようとしても
18:38:07.643 [info] zzzzzzzzzzzzzzzzzzzz (truncated) # 20文字で切られる
:ok
:truncate の値は表示する全体の文字ではなく、引数に渡す文字列に対して利いてます。
ログ表示が追いつかないとき
ログの表示が多いとか、アプリケーションの動作が速いとかで、動作に対してログ表示が追いつかない場合にはアプリケーション側の動作を抑制することができます。sync_threshold に値を入れておくとログのキューがそれを越えたときに同期モードになってアプリ側の動作を止めてログ出力を優先します。ログが出力されてキューが短く（設定値の3/4に）なると非同期モードになり、アプリを止めてたのが解除されます。設定値を 0 にすると常に同期モードになります。
iex(6)> Temp4.log # 4種類のログをいっぺんに表示させる…
:ok # …とアプリ側が先に終了して、その後にログが追いかけてくる
18:49:33.493 [error] Error: hello
18:49:33.493 [warn] Warn: hello
18:49:33.493 [info] Info: hello
18:49:33.494 [debug] Debug: hello
iex(7)> Logger.configure(sync_threshold: 0) # ログのキューに溜まったらアプリを抑制する
:ok
iex(8)> Temp4.log # もう一度、ログをいっぺんに表示させる
18:50:25.851 [error] Error: hello
18:50:25.851 [warn] Warn: hello
18:50:25.851 [info] Info: hello
18:50:25.851 [debug] Debug: hello
:ok # ログ出力が終わるのをアプリが待つようになった
iex(9)>
アプリケーションを開始する前に設定しておく制御内容
ここに示す内容は Logger アプリが立ち上がるより前に設定されてる必要があります。例えば はじめてな Elixir(23) ログを出力する に出てきた :backends の設定もこれに相当します。これらの設定は config/config.exs に書いておきましょう。
コンパイル時にログレベルでの出力抑制を決定する
ログレベルに応じて出力するかどうかは Logger.configure/1 を用いることで実行時にも制御ができました。これはログ出力をする度に毎度チェックすることになります。ここの方法はそうではなくて、コンパイル時にどのレベルまでをログ出力するかを決めてしまいます。これの利点はログ出力しないレベルについては実行時間に全く影響を与えないというところです。
例えば、ソフトウェアの開発時点では error warn info debug を使ってて、リリース時以降は error と warn だけ出力するとしましょう。この場合に Logger.configure で制御すると Logger.info/2 や Logger.debug/2 を呼んでるところでも「ログを表示しない判断」の処理が行われて計算資源を使います。以下の方法を使うと計算資源を使わないように「あたかもその行がなかったかのごとく」コンパイルしてくれます。
以下のプログラムで試してみます。mix new temp してから各ファイルを加筆修正しています。まず、起動するアプリケーションを mix.exs に記述します。
def application do
[
extra_applications: [:logger], # これのあることの確認、そしてカンマ
mod: {Temp.Application, []} # これを追加
]
end
アプリケーションは一定時間ごとにログを出力します。
defmodule Temp.Application do
use Application
require Logger
@behaviour GenServer
@pname :afo
@impl Application
def start(_type, _args) do
Logger.info("server started named #{@pname}")
Logger.debug("There is no supervisor")
GenServer.start_link(__MODULE__, nil, name: @pname)
end
@impl GenServer
def init(_void) do
set_interval()
{:ok, 0}
end
@interval 2000
defp set_interval() do
Logger.debug(fn -> "interval timer set for #{@interval} milli seconds" end)
Process.send_after(self(), :wakeup, @interval)
end
@impl GenServer
def handle_info(:wakeup, num) do
Logger.info("done #{num}th cycle")
set_interval()
{:noreply, num + 1}
end
end
さてこれを素のままで実行してみましょう。（iex のプロンプトが出てきますが、見にくくなるので編集でカットしてます）
$ iex -S mix
Erlang/OTP 21 [erts-10.2.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe] [dtrace]
Compiling 3 files (.ex)
Generated temp5 app
21:27:35.750 [info] server started named afo # info レベルのログが出てます
21:27:35.750 [debug] There is no supervisor # debug レベルのログも出てます
21:27:35.750 [debug] interval timer set for 2000 milli seconds
21:27:37.751 [info] done 0th cycle
21:27:37.751 [debug] interval timer set for 2000 milli seconds
21:27:39.752 [info] done 1th cycle
21:27:39.752 [debug] interval timer set for 2000 milli seconds
21:27:41.753 [info] done 2th cycle
21:27:41.753 [debug] interval timer set for 2000 milli seconds
という :info レベルと :debug レベルのログが2秒ごとに繰り返されて出続けます。
つぎに config/config.exs に以下の設定を入れてみます。
config :logger,
compile_time_purge_matching: [
[level_lower_than: :info]
]
これで実行するとこうなります。
$ iex -S mix
Erlang/OTP 21 [erts-10.2.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe] [dtrace]
Compiling 3 files (.ex)
Generated temp5 app
21:30:04.184 [info] server started named afo
21:30:06.184 [info] done 0th cycle
21:30:08.185 [info] done 1th cycle
21:30:10.186 [info] done 2th cycle
21:30:12.187 [info] done 3th cycle
と :info より優先度の低いログ（この場合は :debug レベルのログ）は出なくなります。これは Logger.configure/1 で抑制しても見た目は同じですが、実行のオーバヘッドが減っています。
この制御はモジュール・関数ごとに設定できます。例えば、起動時のみ :debug レベルのログも出したくて、本体実行中には :info 以上のログしか出したくないような場合は以下のように記述します。
config :logger,
compile_time_purge_matching: [
[module: Temp.Application, function: "start/2", level_lower_than: :debug],
[module: Temp.Application, function: "set_interval/0", level_lower_than: :info]
]
これを実行すると想定どおりに起動時だけ :debug レベルのログが出ました。
$ iex -S mix
Erlang/OTP 21 [erts-10.2.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe] [dtrace]
Compiling 3 files (.ex)
Generated temp5 app
21:38:05.100 [info] server started named afo
21:38:05.100 [debug] There is no supervisor
21:38:07.102 [info] done 0th cycle
21:38:09.103 [info] done 1th cycle
21:38:11.104 [info] done 2th cycle
これ config/config.exs の記述だけでできますので、製品版を出荷するときに Logger.disable や Logger.configure/1 でログを抑制している場合は :compile_time_purge_matching で抑制すると良いでしょう。