Skip to content

Latest commit

 

History

History
692 lines (514 loc) · 23.3 KB

logging.md

File metadata and controls

692 lines (514 loc) · 23.3 KB

シンボルでのロギング

このセクションでは、極めて軽量なロギングを行うために、シンボルとELFフォーマットを利用する方法をお見せします。

任意のシンボル

クレート間で、安定したシンボルインタフェースが必要な場合、no_mangleアトリビュートを主に使用し、 時には、export_nameアトリビュートを使用します。 export_nameアトリビュートは、シンボル名になる文字列を引数に取ります。 一方、#[no_mangle]は、基本的に#[export_name = <item-name>]のシンタックスシュガーです。

引数に取れる文字列は、1単語の名前だけに限定されないことがわかりました。 例えば、文のような任意の文字列をexport_nameアトリビュートの引数として使うことができます。 少なくても出力形式がELFの場合、nullバイトを含まないものならば何でも構いません。

そのことを確認してみましょう。

$ cargo new --lib foo

$ cat foo/src/lib.rs
#[export_name = "Hello, world!"]
#[used]
static A: u8 = 0;

#[export_name = "こんにちは"]
#[used]
static B: u8 = 0;
$ ( cd foo && cargo nm --lib )
foo-d26a39c34b4e80ce.3lnzqy0jbpxj4pld.rcgu.o:
0000000000000000 r Hello, world!
0000000000000000 V __rustc_debug_gdb_scripts_section__
0000000000000000 r こんにちは

これがどこに繋がるか、わかりますか?

エンコードする

やることは、次の通りです。ログメッセージごとにstatic変数を1つ作りますが、 メッセージをその変数の中に格納せずに、変数のシンボル名にメッセージを格納します。 ログ出力するものは、static変数の内容ではなく、そのアドレスです。

static変数のサイズがゼロでない限り、各変数は異なるアドレスを持ちます。 ここで行うことは、各メッセージを一意の識別子(変数のアドレスになります)に効率的にエンコードすることです。 ログシステムの一部は、この識別子をメッセージにデコードしなければなりません。

このアイデアを実現するコードを書いていきましょう。

この例では、I/Oが必要なため、cortex-m-semihostingクレートを使用します。 セミホスティングは、ターゲットデバイスがホストのI/O機能を借りられるようにするための技術です。 今回の場合、QEMUは細かい設定なしでセミホスティングが使えるため、デバッガは不要です。 実機の場合、シリアルポートのようなI/Oが必要になります。 QEMU上でI/Oを使う最も簡単な方法であるため、今回はセミホスティングを使います。

コードは次のとおりです。

{{#include ../ci/logging/app/src/main.rs}}

プログラムがQEMUプロセスを終了できるようにするため、debug::exitも使えるようにしてあります。 QEMUプロセスを手動で終了しなくて良いため、便利です。

そして、こちらはCargo.tomlのdependenciesセクションです。

{{#include ../ci/logging/app/Cargo.toml:7:9}}

これでプログラムをビルドできます。

$ cargo build

実行するためには、QEMU起動時に、--semihosting-configフラグを付け加えます。

$ qemu-system-arm \
      -cpu cortex-m3 \
      -machine lm3s6965evb \
      -nographic \
      -semihosting-config enable=on,target=native \
      -kernel target/thumbv7m-none-eabi/debug/app
{{#include ../ci/logging/app/dev.out}}

注記 これらのアドレスは、あなたが得たアドレスと異なるかもしれません。 static変数のアドレスは、 ツールチェインが更新された時(例えば、最適化が改善されるかもしれません)に変わる可能性があるからです。

コンソールに2つのアドレスが表示されました。

デコードする

どのようにして、このアドレスを文字列に変換するのでしょうか? 答えはELFファイルのシンボルテーブルです。

$ cargo objdump --bin app -- -t | grep '\.rodata\s*0*1\b'
{{#include ../ci/logging/app/dev.objdump}}
$ # 1列目はシンボルのアドレス、最終列はシンボル名です。

objdump -tはシンボルテーブルを表示します。このテーブルは全てのシンボルを含んでいますが、 .rodataセクションの中にある1バイトの大きさ(変数の型はu8です)のアドレスだけを詳しく見ていきます。

プログラムを最適化すると、シンボルのアドレスが変わる可能性があるため、注意して下さい。 確認してみましょう。

専門家によるアドバイス target.thumbv7m-none-eabi.runnerを、 長いQEMUコマンド(qemu-system-arm -cpu (..) -kernel)に設定することができます。 Cargo設定ファイル(.cargo/config)にコマンドを書くことで、 cargo runがそのランナーを使ってバイナリを実行します。

$ head -n2 .cargo/config
{{#include ../ci/logging/app/.cargo/config:1:2}}
$ cargo run --release
     Running `qemu-system-arm -cpu cortex-m3 -machine lm3s6965evb -nographic -semihosting-config enable=on,target=native -kernel target/thumbv7m-none-eabi/release/app`
{{#include ../ci/logging/app/release.out}}
$ cargo objdump --bin app --release -- -t | grep '\.rodata\s*0*1\b'
{{#include ../ci/logging/app/release.objdump}}

常に実行したELFファイル内の文字列を探すようにして下さい。

もちろん、ELFファイルに含まれるシンボルテーブル(.symtabセクション)を解析するツールを使うことで、 ELFファイル内の文字列を探すプロセスを自動化することが可能です。 そのようなツールを実装することは、本書のスコープ外です。 そのため、読者の演習とします。

ゼロコストにする

より良いものにできるでしょうか?もちろんできます!

現在の実装は、static変数を.rodataに配置しています。これは、その変数の値を決して使わないにも関わらず、 Flashの容量を専有することを意味します。 リンカスクリプトの魔法を少し使うことで、Flashの使用量をゼロにできます。

$ cat log.x
{{#include ../ci/logging/app2/log.x}}

static変数を新しい.log出力セクションに配置します。 このリンカスクリプトは、入力オブジェクトファイルの.logセクションにある全てのシンボルを集め、 .log出力セクションに置きます。 このパターンは、メモリレイアウトの章でやりました。

少し新しい部分は、(INFO)の部分です。これは、リンカに、このセクションは割当不可セクションであることを教えます。 割当不可セクションは、ELFバイナリにメタデータとして残りますが、ターゲットデバイスにはロードされません。

また、この出力セクションの開始アドレスを.log 0 (INFO)0に指定しています。

他に改善点は、フォーマットされたI/O(fmt::Write)から、バイナリI/Oに切り替えることです。 つまり、文字列としてではなく、バイトとしてホストにアドレスを送ります。

バイナリシリアライゼーションは、複雑になる可能性がありますが、各アドレスを1バイトとしてシリアライズすることで、 極めて簡潔になります。この方法により、エンディアネスやフレーム化について悩まなくて済みます。 この形式の欠点は、1バイトは256のアドレスしか表現できないことです。

これらの変更を加えましょう。

{{#include ../ci/logging/app2/src/main.rs}}

実行する前に、リンカに渡す引数に-Tlog.xを追加しなければなりません。 Cargo設定ファイルで、追加できます。

$ cat .cargo/config
{{#include ../ci/logging/app2/.cargo/config}}

これで実行することができます!今回、出力はバイナリ形式であるため、 xxdコマンドにパイプし、16進数の文字列に再変換します。

$ cargo run | xxd -p
{{#include ../ci/logging/app2/dev.out}}

アドレスは、0x000x01です。では、シンボルテーブルを見てみましょう。

$ cargo objdump --bin app -- -t | grep '\.log'
{{#include ../ci/logging/app2/dev.objdump}}

目的の文字列があります。今回は、アドレスがゼロから開始していることに気づくでしょう。 これは、.log出力セクションに、開始アドレスを設定したためです。

u8を型として使っているため、各変数は1バイトの大きさです。 もしu16のような型を使った場合、全てのアドレスは偶数になり、全てのアドレス空間(0...255)を、 効率的に利用することができないでしょう。

パッケージする

文字列をログ出力するステップは、常に一緒です。そこで、 クレート内でだけ利用可能なマクロにリファクタリングします。 また、I/O部分をトレイトで抽象化することで、ロギングライブラリをより再利用可能にできます。

$ cargo new --lib log

$ cat log/src/lib.rs
{{#include ../ci/logging/log/src/lib.rs}}

このライブラリが.logセクションに依存することを考えると、このライブラリがlog.xリンカスクリプトの提供に責任を持つべきです。 それでは、そうしましょう。

$ mv log.x ../log/
$ cat ../log/build.rs
{{#include ../ci/logging/log/build.rs}}

それでは、log!マクロを使って、アプリケーションをリファクタリングしましょう。

$ cat src/main.rs
{{#include ../ci/logging/app3/src/main.rs}}

新しいlogクレートへの依存を、Cargo.tomlに追加するのを忘れないようにしましょう。

$ tail -n4 Cargo.toml
{{#include ../ci/logging/app3/Cargo.toml:7:10}}
$ cargo run | xxd -p
{{#include ../ci/logging/app3/dev.out}}
$ cargo objdump --bin app -- -t | grep '\.log'
{{#include ../ci/logging/app3/dev.objdump}}

以前と同じ出力になりました!

おまけ:複数のログレベル

多くのログフレームワークは、異なるログレベルでメッセージをロギングする方法を提供しています。 これらのログレベルは、メッセージの重要度を告げています。「これはエラーです」、「これはただの警告です」、など。 これらのログレベルは、例えばエラーメッセージを検索する時に、重要でないメッセージを除去するために使用されます。

私達のログライブラリを、フットプリントの増加なしに、ログレベルをサポートするように拡張できます。 やることは、次の通りです。

メッセージ用に、0以上、255以下のフラットなアドレス空間があります。 簡単化のために、エラーメッセージと警告メッセージを区別したいだけ、としましょう。 全てのエラーメッセージをアドレス空間の最初に置き、警告メッセージをエラーメッセージのに置きます。 デコーダが最初の警告メッセージのアドレスを知っていれば、メッセージを分類可能です。 このアイデアは、3つ以上のログレベルをサポートするときに拡張できます。

logマクロを、error!warn!の2つの新しいマクロで置き換えて、このアイデアを試してみましょう。

$ cat ../log/src/lib.rs
{{#include ../ci/logging/log2/src/lib.rs}}

メッセージを異なるリンクセクションに配置することでエラーと警告を区別します。

次にやらなければならないことは、エラーメッセージを警告メッセージの前に配置するように、 リンカスクリプトを更新することです。

$ cat ../log/log.x
{{#include ../ci/logging/log2/log.x}}

エラーと警告との境界に、__log_warning_start__という名前をつけています。 このシンボルのアドレスは、最初の警告メッセージのアドレスになります。

次に、これらの新しいマクロを使うように、アプリケーションを更新します。

$ cat src/main.rs
{{#include ../ci/logging/app4/src/main.rs}}

出力は、それほど変わりません。

$ cargo run | xxd -p
{{#include ../ci/logging/app4/dev.out}}

相変わらず2バイトの出力が得られています。 しかし、警告が最初にログ出力されているにも関わらず、エラーが0番地、警告が1番地になっています。

それでは、シンボルテーブルを見てみます。

$ cargo objdump --bin app -- -t | grep '\.log'
{{#include ../ci/logging/app4/dev.objdump}}

.logセクション内に__log_warning_start__という追加のシンボルがあります。 このシンボルのアドレスは、最初の警告メッセージのアドレスです。 この値より小さいアドレスを持つシンボルは、エラーになります。 それ以外のシンボルは警告です。

適切なデコーダを使うと、これら全ての情報から、次の人間が読みやすい出力を得ることができます。

WARNING Hello, world!
ERROR Goodbye

このセクションを気に入った場合、stlogログフレームワークを確認して下さい。 このアイデアを完全に実装しています。