シンボルでのロギング

このセクションでは、極めて軽量なロギングを行うために、シンボルと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

#![allow(unused)]
fn main() {
#[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を使う最も簡単な方法であるため、今回はセミホスティングを使います。

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

#![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();

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

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

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

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

    debug::exit(debug::EXIT_SUCCESS);

    loop {}
}

プログラムがQEMUプロセスを終了できるようにするため、debug::exitも使えるようにしてあります。 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です）のアドレスだけを詳しく見ていきます。

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

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

$ head -n2 .cargo/config

[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ファイルに含まれるシンボルテーブル（.symtabセクション）を解析するツールを使うことで、 ELFファイル内の文字列を探すプロセスを自動化することが可能です。 そのようなツールを実装することは、本書のスコープ外です。 そのため、読者の演習とします。

ゼロコストにする

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

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

$ cat log.x

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

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

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

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

他に改善点は、フォーマットされた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();

    #[export_name = "Hello, world!"]
    #[link_section = ".log"] // <- 追加!
    static A: u8 = 0;

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

    #[export_name = "Goodbye"]
    #[link_section = ".log"] // <- 追加!
    static B: u8 = 0;

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

    debug::exit(debug::EXIT_SUCCESS);

    loop {}
}

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

$ cat .cargo/config

[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", # <- 追加!
]

[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!

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

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

パッケージする

文字列をログ出力するステップは、常に一緒です。そこで、 クレート内でだけ利用可能なマクロにリファクタリングします。 また、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) => {{
        #[export_name = $string]
        #[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<Error>> {
    // リンカスクリプトをリンカが見つけられる場所に置きます
    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 };

    log!(logger, "Hello, world!");

    log!(logger, "Goodbye");

    debug::exit(debug::EXIT_SUCCESS);

    loop {}
}

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

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

$ 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! error {
    ($logger:expr, $string:expr) => {{
        #[export_name = $string]
        #[link_section = ".log.error"] // <- 変更!
        static SYMBOL: u8 = 0;

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

/// 警告ログレベルでメッセージをログ出力します
#[macro_export]
macro_rules! warn {
    ($logger:expr, $string:expr) => {{
        #[export_name = $string]
        #[link_section = ".log.warning"] // <- 変更!
        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 };

    warn!(logger, "Hello, world!"); // <- 変更!

    error!(logger, "Goodbye"); // <- 変更!

    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         .log		 00000000 __log_warning_start__

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

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

WARNING Hello, world!
ERROR Goodbye

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