Emacs のトレース情報を Mackerel(Vaxila) に送りたかった……

この記事ははてなエンジニア - Qiita Advent Calendar 2024 - Qiita と Mackerel - Qiita Advent Calendar 2024 - Qiita 6日目の記事です。昨日は id:pokutuna さんのわんぱくな JSON ストリームパーサーを見る日 - ぽ靴な缶と id:kmuto さんの https://mackerel.io/ja/blog/ entry/2024/12/05/090000 でした。

Mackerel は最近オブザーバビリティに力を入れているので、それに絡めたことをやろうとしたのですが、いいネタが出るところまで出来なかった、、という記事を書きます。

やりたかったこと
Emacs の lsp 拡張機能のログを取る
分散トレーシングサービスに送りたい……
敗因
この後試してみたいこと
感想

やりたかったこと

普段 Emacs を使っているが、lsp 周りの動作がなんかひっかかる時があり、ボトルネックを調べたい
Emacs にもProfiling機能はあるけど、もっといい感じの可視化出来ないだろうか
関数呼び出しを分散トレーシングに見立ててやると、その辺りのツールを使えて便利なんじゃないか
OpenTelemetry 周りの技術や概念にあまり触れてこなかったし、いい機会だし学びながらやってみよう

こんな気楽な感じにとらえてネタを考えていました。

Emacs の lsp 拡張機能のログを取る

送る情報を作らないことには始まらないので、送りたい情報のログを出すところから始めていました。基本的には、Emacs の lsp 拡張の関数が呼び出された時の実行開始・終了時刻、引数や実行結果がわかるとよいだろうとして以下の関数を用意しました。

ちなみに、普段 Emacs を使っていますが、Lisp については初心者なので今回のコードはほぼ ChatGPT ベースですなので、妥当な Lisp コードになっているとは限りません*1。

(defun my/create-otel-trace-json (trace-id span-id parent-id function-name args result start-time end-time)
  (json-encode
   `(("resourceSpans" . [
                         (("resource" . (("attributes" . [
                                                          (("key" . "service.name")
                                                           ("value" . (("stringValue" . "emacs-logger"))))])))
                          ("scopeSpans" . [
                                           (("scope" . (("name" . "log-function-call")
                                                        ("version" . "1.0.0")))
                                            ("spans" . [
                                                        (("traceId" . ,trace-id)
                                                         ("spanId" . ,span-id)
                                                         ("parentSpanId" . ,(or parent-id ""))
                                                         ("name" . ,function-name)
                                                         ("startTimeUnixNano" . ,start-time)
                                                         ("endTimeUnixNano" . ,end-time)
                                                         ("attributes" . [
                                                                          (("key" . "function.args")
                                                                           ("value" . (("stringValue" . ,(format "%s" args)))))
                                                                          (("key" . "function.result")
                                                                           ("value" . (("stringValue" . ,(format "%s" result)))))
                                                                          ])
                                                         )]))]))]))))

最終的には OpenTelemetry の仕様に沿ったデータを送るので、ログフォーマットは以下を参考にしました。

次に、関数を呼び出したらログを記録する関数を用意します。デバッグのためにバッファに出力させています。

ID 生成関数は ChatGPT に投げたらそれっぽいのを返してくれて、便利ですね。

(defvar my/log-current-span-id nil)
(defvar my/log-current-trace-id nil)

(defun my/generate-random-id ()
  (let ((id-length 16))
    (apply 'concat
      (mapcar (lambda (_) (format "%x" (random 16)))
        (make-list id-length nil)))))

(defun my/log-function-call (original-function &rest args)
  (let* ((trace-id (or my/log-current-trace-id (my/generate-random-id)))
         (span-id (my/generate-random-id))
         (parent-id my/log-current-span-id)
         (start-time (current-time-unix-nano))
         (function-name
          (if (symbolp original-function)
              (symbol-name original-function)
            (if (subrp original-function)
                (subr-name original-function)
              "unknown-function")))
         (result (let ((my/log-current-trace-id trace-id)
                       (my/log-current-span-id span-id))
                   (apply original-function args)))
         (end-time (current-time-unix-nano))
         (trace-json (my/create-otel-trace-json trace-id span-id parent-id function-name args result start-time end-time))
         ;; デバッグ用にバッファに出力
         (log-buffer (get-buffer-create "*Function Call Log*")))
    (with-current-buffer log-buffer
      (goto-char (point-max))
      (insert trace-json)
      (insert "\n"))
    result))

これを計測したい関数が呼ばれたら実行するようにしていきます。 Emacs には advice という関数呼び出しにフックして処理を追加できる機能があるのでそれを使います。

(defun my/trace-functions-by-prefix (prefix)
  (interactive "sPrefix: ")
  (let ((count 0))
    (mapatoms
     (lambda (symbol)
       (when (and (functionp symbol)
                  (string-prefix-p prefix (symbol-name symbol))
                  (not (advice-member-p #'my/log-function-call symbol)))
         (advice-add symbol :around #'my/log-function-call)
         (setq count (1+ count)))))
    (message "Tracing enabled for %d functions with prefix '%s'." count prefix)))

この関数により M-x my/trace-functions-by-prefix で呼び出したい関数の prefix を入力することで計測処理を追加できます。例えば lsp-mode であれば lsp- の prefix を入力します。

以下は適当な React プロジェクトのファイルを開いたときのログを抜粋です。

{"resourceSpans":[{"resource":{"attributes":[{"key":"service.name","value":{"stringValue":"emacs-logger"}}]},"scopeSpans":[{"scope":{"name":"log-function-call","version":"1.0.0"},"spans":[{"traceId":"53b5ecdedb7b3931","spanId":"b680e98d20ca1f0c","parentSpanId":"f7d4bdd02c75fb5f","name":"lsp-enable-which-key-integration","startTimeUnixNano":113601885044340118973000,"endTimeUnixNano":113601885044340119445000,"attributes":[{"key":"function.args","value":{"stringValue":"nil"}},{"key":"function.result","value":{"stringValue":"((tsx-ts-mode))"}}]}]}]}]}
{"resourceSpans":[{"resource":{"attributes":[{"key":"service.name","value":{"stringValue":"emacs-logger"}}]},"scopeSpans":[{"scope":{"name":"log-function-call","version":"1.0.0"},"spans":[{"traceId":"53b5ecdedb7b3931","spanId":"0ac6c341cd4cd825","parentSpanId":"f7d4bdd02c75fb5f","name":"lsp-ui-mode","startTimeUnixNano":113601885044340168280000,"endTimeUnixNano":113601885044340168401000,"attributes":[{"key":"function.args","value":{"stringValue":"nil"}},{"key":"function.result","value":{"stringValue":"t"}}]}]}]}]}
{"resourceSpans":[{"resource":{"attributes":[{"key":"service.name","value":{"stringValue":"emacs-logger"}}]},"scopeSpans":[{"scope":{"name":"log-function-call","version":"1.0.0"},"spans":[{"traceId":"53b5ecdedb7b3931","spanId":"f7d4bdd02c75fb5f","parentSpanId":"","name":"lsp","startTimeUnixNano":113601885044338343217000,"endTimeUnixNano":113601885044340172594000,"attributes":[{"key":"function.args","value":{"stringValue":"nil"}},{"key":"function.result","value":{"stringValue":"LSP :: Connected to [ts-ls:69060/starting /home/benevolent0505/develop/tmp/react/react-sample][graphql-lsp:69061/starting /home/benevolent0505/develop/tmp/react/react-sample]."}}]}]}]}]}

それっぽくなってきた。ここまで出来たら後は送るだけのはず。

分散トレーシングサービスに送りたい……

Mackerel は分散トレースサービスである Vaxila が使えるようになっています。 Vaxila に今回のトレースデータを送って可視化してみたいですが、当然 Emacs Lisp に OpenTelemetry の SDK はないので、HTTP リクエストを送る関数を書いて簡易でやってみることにしました。

(defun my/send-to-vaxila (trace-data)
  (let* ((url "https://otlp-vaxila.mackerelio.com/v1/traces")
         (url-request-method "POST")
         (url-request-extra-headers '(("Content-Type" . "application/json")
                                      ("Accept" . "*/*")
                                      ("Mackerel-Api-Key" . "API_KEY")))
         (url-request-data trace-data))
        (message "Sending data to vaxila: %s" trace-data)
    (condition-case err
      (let ((response-buffer (url-retrieve-synchronously url)))
        (if response-buffer
          (with-current-buffer response-buffer
            (goto-char (point-min))
            (if (re-search-forward "^HTTP/[0-9.]+ \\([0-9]+\\)" nil t)
              (let ((status-code (string-to-number (match-string 1))))
                (if (= status-code 202)
                  (message "Successfully sent data to vaxila.")
                  (message "Failed to send data: HTTP %d" status-code)))
            (message "Failed to parse HTTP response.")))
          (message "No response from vaxila.")))
          (error (message "Error occurred while sending to vaxila: %s" err)))))

しかし、送る部分が上手く成功せず断念しました……。

敗因

全体的にネタが見切り発車過ぎたのはありますが、Otel 周りの技術をわかっていなかったこと、Emacs Lisp との格闘に時間をかけすぎたことが敗因かと思います。Emacs Lisp のコードもミスっている可能性があり、流石に準備不足でした……

この後試してみたいこと

調べている内に otel-cli という cli で OpenTelemetry に対応しているサービスにテレメトリーを送るツールを見つけたので、これを利用して、外部コマンド呼び出しで送るのを試してみるのはよいかと思いました。

github.com

また otel-collector に集約させると Emacs 側の実装もシンプルになる? 一般的には otel-collector を経由して送ることが多そうなので、この方法も試してみたいと思います。

あと今回は流石に ChatGPT に頼りすぎたと思ったので、Lisp 力は上げたいですね……。

感想

最終的な目的は果せませんでしたが、デバッグのためにログを出している際も裏側の関数呼び出しの様子や、そもそも呼び出されている関数の多さがわかり、そこは面白かったです。このように普段見れていない情報を見れるようにするだけででも気づきがあるので、まず見れるようにすることだけでも第一歩なのだと思いました。

自分達が普段運用しているサービスだけでなく、身近なツールのオブザーバビリティを上げていきたいですね。

*1:今回の敗因の一つは ChatGPTに頼りすぎたこともありそう……