シンボルを使ったロギング

このセクションでは、シンボルと ELF フォーマットを活用して 非常に低コストなロギングを実現する方法を紹介します。

任意のシンボル

クレート間で安定したシンボルインターフェースが必要になるたびに、主に no_mangle 属性を使い、ときには export_name 属性も使ってきました。この export_name 属性はシンボル名になる文字列を受け取り、一方 #[unsafe(no_mangle)] は基本的に #[unsafe(export_name = <item-name>)] の 糖衣構文です。

実は、名前は 1 語だけに限定されません。export_name 属性の引数として、 文のような任意の文字列を使うことができます。少なくとも出力フォーマットが ELF であれば、ヌルバイトを含まないものであれば何でも構いません。 これは GNU リンカーを使う場合には一般に成り立ちます。ただし、macOS と Windows のリンカーにはいくつかの既知の制限事項 があります。

確認してみましょう。

$ cargo new --lib foo

$ cat foo/src/lib.rs

#![allow(unused)]
fn main() {
#[unsafe(export_name = "Hello, world!")]
#[used]
static A: u8 = 0;

#[unsafe(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 こんにちは

これで何をしようとしているかわかりますか？

エンコーディング

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

static 変数がゼロサイズでない限り、それぞれ異なるアドレスを持ちます。 ここでやっていることは、事実上、各メッセージを一意な識別子に エンコードすることです。その識別子が、たまたま変数のアドレスになって います。ログシステムのどこかの部分で、この ID をメッセージにデコードし 戻す必要があります。

この考え方を示すコードを書いてみましょう。

この例では I/O を行う方法が必要なので、そのために cortex-m-semihosting クレートを使います。セミホスティングとは、 ターゲットデバイスがホストの I/O 機能を借りるための技法です。ここでいう ホストとは、通常はターゲットデバイスをデバッグしているマシンを指します。 今回の場合、QEMU はセミホスティングをそのままサポートしているため、 デバッガーは不要です。実機では、シリアルポートのような別の I/O 手段を 使うことになります。この場合にセミホスティングを使うのは、QEMU 上で I/O を行う最も簡単な方法だからです。

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

#![no_main]
#![no_std]

use core::fmt::Write;
use cortex_m_semihosting::{debug, hio};

use rt::entry;

entry!(main);

fn main() -> ! {
    let mut hstdout = hio::hstdout().unwrap();

    #[unsafe(export_name = "Hello, world!")]
    static A: u8 = 0;

    let _ = writeln!(hstdout, "{:#x}", &A as *const u8 as usize);

    #[unsafe(export_name = "Goodbye")]
    static B: u8 = 0;

    let _ = writeln!(hstdout, "{:#x}", &B as *const u8 as usize);

    debug::exit(debug::EXIT_SUCCESS);

    loop {}
}

また、プログラムが QEMU プロセスを終了できるように debug::exit API も 利用します。これは、QEMU プロセスを手動で終了しなくて済むようにするための 便宜です。

そして、Cargo.toml の dependencies セクションは次のとおりです。

[dependencies]
cortex-m-semihosting = "0.3.1"
rt = { path = "../rt" }

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

$ 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

0x1fe0
0x1fe1

注: これらのアドレスは、ローカルで得られるものとは異なる場合が あります。static 変数のアドレスは、ツールチェーンが変わったときにも 同じままであることが保証されていないためです（たとえば最適化が改善される ことがあります）。

これでコンソールに 2 つのアドレスが出力されました。

デコーディング

これらのアドレスをどうやって文字列に変換するのでしょうか？ 答えは ELF ファイルのシンボルテーブルにあります。

$ cargo objdump --bin app -- -t | grep '\.rodata\s*0*1\b'

00001fe1 g       .rodata		 00000001 Goodbye
00001fe0 g       .rodata		 00000001 Hello, world!
$ # 1 列目はシンボルのアドレス、最後の列はシンボル名

objdump -t はシンボルテーブルを表示します。このテーブルには すべて の シンボルが含まれますが、ここで見ているのは .rodata セクション内にあり、 サイズが 1 バイトのものだけです（変数の型は u8 です）。

プログラムを最適化すると、シンボルのアドレスはおそらく変わるという点に 注意することが重要です。確認してみましょう。

豆知識 Cargo の設定ファイル（.cargo/config.toml）で target.thumbv7m-none-eabi.runner に、先ほどの長い QEMU コマンド （qemu-system-arm -cpu ... -kernel ...）を設定しておくと、 cargo run がその ランナー を使って出力バイナリを実行するように なります。

$ head -n2 .cargo/config.toml

[target.thumbv7m-none-eabi]
runner = "qemu-system-arm -cpu cortex-m3 -machine lm3s6965evb -nographic -semihosting-config enable=on,target=native -kernel"

$ 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`

0xb9c
0xb9d

$ cargo objdump --bin app --release -- -t | grep '\.rodata\s*0*1\b'

00000b9d g     O .rodata	00000001 Goodbye
00000b9c g     O .rodata	00000001 Hello, world!

したがって、必ず実行した ELF ファイルの中で文字列を探すようにしてください。

もちろん、ELF ファイル内の文字列を調べる処理は、ELF ファイルに含まれる シンボルテーブル（.symtab セクション）をパースするツールを使えば 自動化できます。そのようなツールの実装はこの本の範囲外なので、 読者への演習問題として残しておきます。

ゼロコストにする

もっと良くできるでしょうか？ はい、できます！

現在の実装では static 変数は .rodata に配置されるため、その内容を 一切使わないにもかかわらずフラッシュ上の領域を消費します。リンカースクリプトの ちょっとした細工を使えば、これらがフラッシュ上で ゼロ の領域しか 占有しないようにできます。

$ cat log.x

SECTIONS
{
  .log 0 (INFO) : {
    *(.log);
  }
}

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

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

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

もう 1 つ改善できる点は、整形済み I/O（fmt::Write）からバイナリ I/O に 切り替え、アドレスを文字列ではなくバイト列としてホストに送ることです。

バイナリシリアライズは難しくなりがちですが、ここでは各アドレスを 1 バイトで シリアライズすることで、非常に単純に保ちます。この方法であれば、 エンディアンやフレーミングを気にする必要はありません。この形式の欠点は、 1 バイトでは最大でも 256 個までの異なるアドレスしか表現できないことです。

では、これらの変更を加えてみましょう。

#![no_main]
#![no_std]

use cortex_m_semihosting::{debug, hio};

use rt::entry;

entry!(main);

fn main() -> ! {
    let mut hstdout = hio::hstdout().unwrap();

    #[unsafe(export_name = "Hello, world!")]
    #[unsafe(link_section = ".log")] // <- NEW!
    static A: u8 = 0;

    let address = &A as *const u8 as usize as u8;
    hstdout.write_all(&[address]).unwrap(); // <- CHANGED!

    #[unsafe(export_name = "Goodbye")]
    #[unsafe(link_section = ".log")] // <- NEW!
    static B: u8 = 0;

    let address = &B as *const u8 as usize as u8;
    hstdout.write_all(&[address]).unwrap(); // <- CHANGED!

    debug::exit(debug::EXIT_SUCCESS);

    loop {}
}

これを実行する前に、リンカーに渡される引数へ -Tlog.x を追加する必要が あります。これは Cargo の設定ファイルで行えます。

$ cat .cargo/config.toml

[target.thumbv7m-none-eabi]
runner = "qemu-system-arm -cpu cortex-m3 -machine lm3s6965evb -nographic -semihosting-config enable=on,target=native -kernel"
rustflags = [
  "-C", "link-arg=-Tlink.x",
  "-C", "link-arg=-Tlog.x", # <- NEW!
]

[build]
target = "thumbv7m-none-eabi"

これで実行できます！ 出力はバイナリ形式になったので、xxd コマンドにパイプして16進文字列として再整形します。

$ cargo run | xxd -p

0001

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

$ cargo objdump --bin app -- -t | grep '\.log'

00000001 g     O .log	00000001 Goodbye
00000000 g     O .log	00000001 Hello, world!

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

各変数のサイズは 1 バイトです。型として u8 を使っているためです。u16 のようなものを使うと、すべてのアドレスは偶数になり、アドレス空間全体（0...255）を効率的に使えなくなります。

パッケージ化する

文字列をログに記録する手順は常に同じであることに気づいたでしょう。そこで、これらを専用の crate に置かれたマクロへとリファクタリングできます。また、I/O の部分をトレイトの背後に抽象化することで、ロギングライブラリの再利用性を高めることもできます。

$ cargo new --lib log

$ cat log/src/lib.rs

#![allow(unused)]
#![no_std]

fn main() {
pub trait Log {
    type Error;

    fn log(&mut self, address: u8) -> Result<(), Self::Error>;
}

#[macro_export]
macro_rules! log {
    ($logger:expr, $string:expr) => {{
        #[unsafe(export_name = $string)]
        #[unsafe(link_section = ".log")]
        static SYMBOL: u8 = 0;

        $crate::Log::log(&mut $logger, &SYMBOL as *const u8 as usize as u8)
    }};
}
}

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

$ mv log.x ../log/

$ cat ../log/build.rs

use std::{env, error::Error, fs::File, io::Write, path::PathBuf};

fn main() -> Result<(), Box<dyn Error>> {
    // Put the linker script somewhere the linker can find it
    let out = PathBuf::from(env::var("OUT_DIR")?);

    File::create(out.join("log.x"))?.write_all(include_bytes!("log.x"))?;

    println!("cargo:rustc-link-search={}", out.display());

    Ok(())
}

これで、アプリケーションを log! マクロを使うようにリファクタリングできます。

$ cat src/main.rs

#![no_main]
#![no_std]

use cortex_m_semihosting::{
    debug,
    hio::{self, HStdout},
};

use log::{log, Log};
use rt::entry;

struct Logger {
    hstdout: HStdout,
}

impl Log for Logger {
    type Error = ();

    fn log(&mut self, address: u8) -> Result<(), ()> {
        self.hstdout.write_all(&[address])
    }
}

entry!(main);

fn main() -> ! {
    let hstdout = hio::hstdout().unwrap();
    let mut logger = Logger { hstdout };

    let _ = log!(logger, "Hello, world!");

    let _ = log!(logger, "Goodbye");

    debug::exit(debug::EXIT_SUCCESS);

    loop {}
}

新しい log crate に依存するように、Cargo.toml ファイルを更新するのを忘れないでください。

$ tail -n4 Cargo.toml

[dependencies]
cortex-m-semihosting = "0.3.1"
log = { path = "../log" }
rt = { path = "../rt" }

$ cargo run | xxd -p

0001

$ cargo objdump --bin app -- -t | grep '\.log'

00000001 g     O .log	00000001 Goodbye
00000000 g     O .log	00000001 Hello, world!

出力は前と同じです！

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

多くのロギングフレームワークは、異なる ログレベル でメッセージを記録する手段を提供しています。これらのログレベルは、メッセージの重大度、つまり「これはエラーです」「これは単なる警告です」などを表します。こうしたログレベルは、たとえばエラーメッセージを探すときに、重要でないメッセージを除外するために使えます。

フットプリントを増やすことなく、ロギングライブラリを拡張してログレベルをサポートできます。方法は次のとおりです。

メッセージ用のアドレス空間は、0 から 255 まで（両端を含む）のフラットなものです。簡単にするため、ここではエラーメッセージと警告メッセージだけを区別したいことにしましょう。すべてのエラーメッセージをアドレス空間の先頭に配置し、すべての警告メッセージをエラーメッセージの 後 に配置できます。デコーダーが最初の警告メッセージのアドレスを知っていれば、メッセージを分類できます。この考え方は、2 つを超えるログレベルのサポートにも拡張できます。

この考え方を試すために、log マクロを 2 つの新しいマクロ error! と warn! に置き換えてみましょう。

$ cat ../log/src/lib.rs

#![allow(unused)]
#![no_std]

fn main() {
pub trait Log {
    type Error;

    fn log(&mut self, address: u8) -> Result<(), Self::Error>;
}

/// Logs messages at the ERROR log level
#[macro_export]
macro_rules! error {
    ($logger:expr, $string:expr) => {{
        #[unsafe(export_name = $string)]
        #[unsafe(link_section = ".log.error")] // <- CHANGED!
        static SYMBOL: u8 = 0;

        $crate::Log::log(&mut $logger, &SYMBOL as *const u8 as usize as u8)
    }};
}

/// Logs messages at the WARNING log level
#[macro_export]
macro_rules! warn {
    ($logger:expr, $string:expr) => {{
        #[unsafe(export_name = $string)]
        #[unsafe(link_section = ".log.warning")] // <- CHANGED!
        static SYMBOL: u8 = 0;

        $crate::Log::log(&mut $logger, &SYMBOL as *const u8 as usize as u8)
    }};
}
}

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

次に行う必要があるのは、エラーメッセージを警告メッセージより前に配置するよう、リンカスクリプトを更新することです。

$ cat ../log/log.x

SECTIONS
{
  .log 0 (INFO) : {
    *(.log.error);
    __log_warning_start__ = .;
    *(.log.warning);
  }
}

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

これで、アプリケーションを更新してこれらの新しいマクロを利用できます。

$ cat src/main.rs

#![no_main]
#![no_std]

use cortex_m_semihosting::{
    debug,
    hio::{self, HStdout},
};

use log::{error, warn, Log};
use rt::entry;

entry!(main);

fn main() -> ! {
    let hstdout = hio::hstdout().unwrap();
    let mut logger = Logger { hstdout };

    let _ = warn!(logger, "Hello, world!"); // <- CHANGED!

    let _ = error!(logger, "Goodbye"); // <- CHANGED!

    debug::exit(debug::EXIT_SUCCESS);

    loop {}
}

struct Logger {
    hstdout: HStdout,
}

impl Log for Logger {
    type Error = ();

    fn log(&mut self, address: u8) -> Result<(), ()> {
        self.hstdout.write_all(&[address])
    }
}

出力はほとんど変わりません。

$ cargo run | xxd -p

0100

出力には引き続き 2 バイトが含まれますが、警告のほうが先にログに記録されていても、エラーにはアドレス 0 が、警告にはアドレス 1 が割り当てられます。

では、シンボルテーブルを見てみましょう。

$ cargo objdump --bin app -- -t | grep '\.log'

00000000 g     O .log	00000001 Goodbye
00000001 g     O .log	00000001 Hello, world!
00000001 g       .log	00000000 __log_warning_start__

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

適切なデコーダーがあれば、これらすべての情報から次のような人間可読な出力を得られます。

WARNING Hello, world!
ERROR Goodbye

このセクションが気に入ったら、このアイデアを完全に実装したロギングフレームワーク stlog をチェックしてみてください。