Clever Geek Handbook

フェニックスのデータベースクエリプロファイラー。 Elixir / Erlangでのスタックトレースの仕組みについて少し説明します

当社では、Phoenix and EctoフレームワークであるElixirを使用しています。 そして最近、職場で、最適化すべきシステムのボトルネックを見つけるために、データベースにクエリプロファイラーを作成するタスクが与えられました。 したがって、タスクは次のとおりでした。







  1. データベースで最も頻繁に使用される関数を見つけます（クエリ呼び出し）
  2. どの関数が最も長くて最も遅いクエリを作成するかを調べる（クエリ時間）
  3. 結果を蓄積し、リスト/グラフとして表示する必要があります。


他の皆と同じように、最初に既存のソリューションを試すことにしました。 簡単なGoogle検索で、いくつかの記事といくつかの解決策がありました。







https://github.com/parroty/exprof

http://erlang.org/doc/man/fprof.html

https://github.com/proger/eflame

https://github.com/TheRealReal/new-relixir







その他







迅速な検査により、既存のソリューションが適切でないことがすぐに明らかになりました。 結果の蓄積を許可しないものもあれば、一般的な課題を考慮するものもあり、データベースが存在するかどうかは関係ありません。何かが支払われ、必要な機能もありません。 カブをひっかいた後、自分のカスタムプロファイラーを作成する必要があることに気付きました。







画像








幸いなことに、Ecto（データベースを操作するためのDSL）には、次のように、ロガーを構成し、要求の実行後にすべての情報を表示する機能があります。 







config :my_greap_app, MyGreatApp.Repo, loggers: [{EctoProfiler, :log, []}]


これは、 EctoProfilerという名前で独自のモジュールを作成できることを意味します。このモジュールには、1つの引数を取るパブリックログ関数が必ず必要です。 そして、この関数の中で何か面白いことをしてください。 特に、この引数に含まれる情報を見るには、 多くのものと必要なほぼすべてのものが含まれていますが、残念ながら呼び出し元の情報は含まれていません。







スタックトレース



その後、スタックトレースがシーンに入ります。 さまざまな方法で、エリクサーでその情報を呼び出して表示できます。 Processモジュールのメソッドを使用します。 







 Process.info(self(), :current_stacktrace)


しかし、いくつかのニュアンスがあります。 以下のモジュールをご覧ください。 







 defmodule StacktraceTest do @moduledoc false def a do b() end def b do fn -> c() end.() end def c do {:ok, d()} end def d do e() after {:ok, f()} end def e do raise "fail" rescue _ -> g() end def f do IO.inspect Process.info(self(), :current_stacktrace) end def g do Process.info(self(), :current_stacktrace) end end


問題は百万ドルです。 StacktraceTest.a



実行すると、ポイントfとgで何が得られますか？







すべての経験豊富なエリキシル奏者がそれを正しく答えるとは限りません。







このモジュールを実行し、関数を呼び出すと、次の結果が得られます。 







 iex(2)>{:current_stacktrace, [ {Process, :info, 2, [file: 'lib/process.ex', line: 646]}, {StacktraceTest, :f, 0, [file: 'iex', line: 29]}, {StacktraceTest, :"-d/0-after$^0/0-0-", 0, [file: 'iex', line: 19]}, {StacktraceTest, :d, 0, [file: 'iex', line: 16]}, {StacktraceTest, :c, 0, [file: 'iex', line: 13]}, {:erl_eval, :do_apply, 6, [file: 'erl_eval.erl', line: 670]}, {:elixir, :eval_forms, 4, [file: 'src/elixir.erl', line: 233]} ]} {:ok, {:current_stacktrace, [ {Process, :info, 2, [file: 'lib/process.ex', line: 646]}, {StacktraceTest, :d, 0, [file: 'iex', line: 17]}, {StacktraceTest, :c, 0, [file: 'iex', line: 13]}, {:erl_eval, :do_apply, 6, [file: 'erl_eval.erl', line: 670]}, {:elixir, :eval_forms, 4, [file: 'src/elixir.erl', line: 233]}, {IEx.Evaluator, :handle_eval, 5, [file: 'lib/iex/evaluator.ex', line: 245]}, {IEx.Evaluator, :do_eval, 3, [file: 'lib/iex/evaluator.ex', line: 225]} ]}}


関数fの推定値より上、 -gの下。 すべてがクールなようで、情報は網羅的ですが、ありません。 注意深い読者は、関数a 、 bの呼び出しはどこにあるのかすぐに尋ねます。







ここで最も興味深いことになります。







関数aが関数b （テールチェーン）が返す値と同じ値を返す場合、関数aはスタックトレースに入りません。 これは、最後の呼び出し、いわゆるErlang / Elixirの末尾再帰の最適化の結果です。 末尾の各関数呼び出しは、呼び出し元関数のスタックフレームが破棄されることを意味します。 これがBEAM（Erlang VM）の動作です。 そして、仮想マシンのコードを書き換えずにここで何かを変更することは不可能です。 詳細な議論はこちらhttps://github.com/elixir-lang/elixir/issues/6357







したがって、 e関数もスタックトレースに入りませんでした。 rescue/catch



-終了呼び出しですがafter



（関数dで ）-いいえ。







残念ながら、Stacktraceには関数と呼ばれる引数も含まれていません。 これは、 handle_info



の情報や、 handle_info



れているメッセージに関する他のコールバックをhandle_info



できないことを意味します。 その理由は、Erlangがスタックを操作する方法にもあります。 しばらく保存され、引数が任意に大きくなる可能性があるため、この場合のスタックトレースはすべてのメモリを使い果たします。 ちなみに、これがエラーの場合にErlangが呼び出しスタックの処理と保存をやり直す計画を立てている理由です（引数はそこに保存されます）。 これについての議論があります。







誰かが標準debugger



使用しなかった理由を尋ねるでしょう。標準debugger



はErlangですぐに使用debugger



、引数を保存します。 私はそれについて考えましたが、 debugger



は呼び出しトレースを変数に保存してから、このデータを何らかの方法で処理することを許可しません。 ファイルまたはコンソールのみ。 したがって、彼との決定はすぐに失われました。







そのため、呼び出しのスタックトレースを受け取りました。 関連するすべての情報。 それを処理する時間。







プロファイラー



これらすべての情報を使用して、独自のプロファイラが作成されました。 ここでは、コード例とともに彼の作品の詳細な説明を提供しません。 誰が気にする-githubで彼と知り合うことができます







ここでは、動作原理について簡単に説明します。







  1. データベース内のクエリに関する情報を取得します（特に、クエリ時間はquery_time



    ）。これはquery_time



    によって送信されます。
  2. スタックトレースの取得
  3. スタックトレースから、アプリケーション内で作成されたモジュールのみを残します（すべての依存モジュールとElixir自体は除外されます）
  4. 受信したデータを2つのMnesiaテーブルに保存します（データはディスクに保存されず、メモリにのみ保存されます）：

    • Module.function/arity



      型の一意のキーを持つ
    • 受信したスタックレースに等しい一意のキーを持つ
  5. 両方のテーブルにはキーと属性が含まれていますquery_time



    クエリの数、 query_time



    クエリの合計時間。 トレースを含むテーブルには、スタックで最初に呼び出しが行われた関数に関する情報も含まれています。
  6. 新しい呼び出しごとに、 calls



    とquery_time



    増加しcalls



    。
  7. データはフォーマットされ、Webインターフェースを介してリストとして表示されます（インターフェースにはquery_time / callsに等しい平均クエリ時間に関する情報も含まれています）。


合計



残念ながら、このソリューションには、上記のスタックトレースの動作に関連する欠点があります。 ただし、アプリケーションがどのように機能するかについての情報を取得し、最適化に関する結論を引き出すことはできます。







PSプラグイン自体に関しては。 私はどんな追加やPRにも満足しています。 たぶん誰かがいくつかのグッズを追加し、素敵なインターフェイスを作る:)







More articles:


All Articles