🪄
printfデバッグ地獄から脱出したい！自動ログ挿入＆シーケンス図自動生成で効率化した話

2025/07/12に公開
 プロローグ「ここ、デバッガ使ってないんですか？」

新しい部署でそう尋ねると、その場にいた全員が、まるで面白い冗談を聞いたかのように顔を見合わせた。

「デバッガだぁ？」

「そんな高尚なもん、この現場にあるわけねえだろ」

「ブレークポイントなんざ犬にでも食わせておけ！」

「いいか小僧、ここはprintfデバッグの聖地だ」

そうやって、部署全体で“洗礼”を受けた日だった。

その日から、僕のprintfデバッグ地獄が始まった。

 はじめにさて、このようなやりとりが本当にあったかはさておき。

新しく配属された部署は、デバッガも使えないレガシーな環境でした。

以前は便利な開発環境で、普通にデバッガでブレークポイントを張って不具合調査をしていたので、なかなかしんどいものがありました。

新しい現場での不具合調査は、printfを仕込んで、ビルドして、実機に書き込んで動かして、出てきたログから怪しいところにまたprintfを仕込んで……という無限ループ。

ちなみに、昔は「関数の入り口と出口にはprintfを必ず書く」というコーディング規約があったそうですが、私が配属された時点では、いつの間にかそのルールも消えていました。 （ナゼ！？）

おかげで、いまは「怪しそうな箇所」を手作業でprintfで埋めてまわるしかなくなっています。
配属直後のキャッチアップもできて一石二鳥、みたいな雰囲気もありましたが、さすがにこれでは終わりが見えません。

静的解析ツール（sourcetrailやdoxygen）で呼び出し経路を可視化しようとしたり、gdbのビルドにも挑戦して、なんとか動かすこと自体はできました。

しかし、静的解析はスパゲッティコードがそのまま可視化されただけ。

gdbも、マイコンの非力さや通信タイミングの制約で、ブレークをかけた瞬間にプログラムがクラッシュしてしまい、結局どれも現場では使いものになりませんでした。

なんとか処理の流れを見えるようにできないかと思い、自動ログ挿入とシーケンス図自動生成のツールを作りました。

この記事では、その工夫と現場での効果を紹介します。

 printf自動挿入ツールの誕生
 手作業printfの限界現場でのデバッグは、printfを手作業で仕込んでビルドし、実機に書き込んでログを確認する作業です。

怪しそうな場所にprintfを追加してみては、また別の箇所に仕込む……。

この「当たりをつけて仕込む」のが難しい。

 手作業でprintfを仕込むとどうなるかたとえば、次のようなシンプルな関数でも、

「どこを通ったか」「どの条件が成立したか」を知るために、

関数の入り口・if文・else節ごとにprintfを入れる必要があります。
int foo(int x) {
    if (x > 0) {
        return 1;
    } else {
        return -1;
    }
}
手作業でprintfを追加すると、こうなります。
int foo(int x) {
    printf("func_entry: foo x=%d\n", x);
    if (x > 0) {
        printf("cond_true: if (x > 0)\n");
        printf("func_exit: foo\n");
        return 1;
    } else {
        printf("cond_true: else (if (x > 0))\n");
        printf("func_exit: foo\n");
        return -1;
    }
}
こうしたprintfを毎回書いては消し…を繰り返すのは、手間も抜け漏れも発生しやすく、現実的にはなかなか大変です。

「いっそ、プロジェクトのすべての関数や分岐に仕込めたらもっと楽になるんじゃないか？」

そんな発想が生まれました。

 正規表現の落とし穴最初は、「正規表現で関数やif、switchのキーワードを見つけて、片っ端からprintfを挿入すればいい」と思いました。

しかし、スパゲッティコードあるあるで、関数や処理が丸ごとコメントアウトされていたり、コメントの中にもprintfを挿入してしまったり。

関数の入り口と出口でログの組み合わせがズレることも多発しました。

 VSCodeの発見→tree-sitter導入悩んでいる時、ふとVSCodeのシンタックスハイライトを見て「エディタはどうやってコードとコメントを区別してるんだ？」と疑問に。

調べてみると、AST（構文木）で構造解析していることを知り、tree-sitterを活用して、正確に挿入ポイントだけを検出できる仕組みに切り替えました。

 ツールの仕組みtree-sitterでC/C++の構文木を構築し、関数・if・switchなどのブロックだけを認識。

コメント部分には挿入せず、必要な場所へprintfを自動で追加します。

tree-sitter導入や構造解析の詳細は、別記事で詳しくまとめています。

https://zenn.dev/naosegu/articles/ae9666741e8fe5

 シーケンス図自動生成ツールで見える化もともと、「処理の流れを“図”として可視化したい」というのが現場での本来の目的でした。

そのため、ログ挿入の自動化ツールと合わせて、実行ログからシーケンス図（呼び出し経路）を自動生成するツールも作りました。

 技術的なポイントログに出力された関数のentry、exitなどの情報から、どのクラスのどの関数（メソッド）がどこから呼ばれているかを解析し、PlantUML形式のシーケンス図を自動生成します。
実際の出力例は、サンプルで紹介します。

 じゃんけんプログラムで体験する可視化の力ここからは、「printf自動挿入ツール」と「シーケンス図自動生成ツール」が現場でどれだけ役立つのかを、ミニ例として“じゃんけんプログラム”で体験してみます。

 サンプルの登場クラスと役割GameMaster
ゲーム全体の進行を担当。ユーザーの手を受け付け、CPUの手を決定し、JankenJudgeで勝敗判定、ResultAnnouncerで結果を表示します。
JankenJudge
勝敗判定（if/switchによる分岐処理）を担当し、結果を返します。
ResultAnnouncer
勝敗（勝ち／負け／あいこ）ごとのメッセージを表示します。
main関数では3回じゃんけんを実行し、「グー」「チョキ」「パー」を入力します。

※CPUの手は1回目「チョキ」、2回目「グー」、3回目「パー」だったと仮定します。これで「勝ち」「負け」「あいこ」全パターンを体験できます。

 具体的なビフォーアフターたとえば、JankenJudge::judge 関数は元々こういうシンプルな実装です。

 ログ挿入前の例class JankenJudge {
public:
    std::string judge(const std::string& userHand, const std::string& cpuHand) {
        if (userHand == cpuHand) {
            return "あいこ";
        } else if (
            (userHand == "グー" && cpuHand == "チョキ") ||
            (userHand == "チョキ" && cpuHand == "パー") ||
            (userHand == "パー" && cpuHand == "グー")
        ) {
            return "勝ち";
        } else {
            return "負け";
        }
    }
};


 ログ挿入後（自動挿入ツール適用例）class JankenJudge {
public:
    std::string judge(const std::string& userHand, const std::string& cpuHand) {
        printf("FUNC_ENTRY: JankenJudge::judge userHand=%s cpuHand=%s\n", userHand.c_str(), cpuHand.c_str());
        if (userHand == cpuHand) {
            printf("COND_TRUE: if (userHand == cpuHand)\n");
            printf("FUNC_EXIT: JankenJudge::judge\n");
            return "あいこ";
        } else if (
            (userHand == "グー" && cpuHand == "チョキ") ||
            (userHand == "チョキ" && cpuHand == "パー") ||
            (userHand == "パー" && cpuHand == "グー")
        ) {
            printf("COND_TRUE: else if (complex condition)\n");
            printf("FUNC_EXIT: JankenJudge::judge\n");
            return "勝ち";
        } else {
            printf("COND_TRUE: else (if (userHand == cpuHand))\n");
            printf("FUNC_EXIT: JankenJudge::judge\n");
            return "負け";
        }
    }
};

各関数の入り口・出口、if文や複雑な分岐ごとに、自動でprintfログが入る
条件式が長い場合は「complex condition」と出力して可読性を保つ
else節のログは直前のif条件のみを明示し、どの分岐の「else」なのかが一目で分かる
手作業でこれを全部書くのは本当に骨が折れますが、ツールを使えば一度で全ての分岐や関数に抜け漏れなくログが入ります。

 実行ログ例実際にツールでログ挿入後のプログラムを動かすと、下記のような出力が得られます。
FUNC_ENTRY: GameMaster::playJanken userHand=グー
FUNC_ENTRY: JankenJudge::judge userHand=グー cpuHand=チョキ
COND_TRUE: else if (complex condition)
FUNC_EXIT: JankenJudge::judge
FUNC_ENTRY: ResultAnnouncer::announce result=勝ち ...
FUNC_EXIT: ResultAnnouncer::announce
FUNC_EXIT: GameMaster::playJanken

FUNC_ENTRY: GameMaster::playJanken userHand=チョキ
FUNC_ENTRY: JankenJudge::judge userHand=チョキ cpuHand=グー
COND_TRUE: else (if (userHand == cpuHand))
FUNC_EXIT: JankenJudge::judge
FUNC_ENTRY: ResultAnnouncer::announce result=負け ...
FUNC_EXIT: ResultAnnouncer::announce
FUNC_EXIT: GameMaster::playJanken

FUNC_ENTRY: GameMaster::playJanken userHand=パー
FUNC_ENTRY: JankenJudge::judge userHand=パー cpuHand=パー
COND_TRUE: if (userHand == cpuHand)
FUNC_EXIT: JankenJudge::judge
FUNC_ENTRY: ResultAnnouncer::announce result=あいこ ...
FUNC_EXIT: ResultAnnouncer::announce
FUNC_EXIT: GameMaster::playJanken


 シーケンス図自動生成ツールによる呼び出し経路の可視化この実行ログをそのままシーケンス図自動生成ツールにかけると、

呼び出し経路や関数の流れがPlantUML形式のシーケンス図として出力されます。
PlantUMLコード@startuml
autonumber
autoactivate on
participant main
participant GameMaster
participant JankenJudge
participant ResultAnnouncer

main -> GameMaster : playJanken("グー")
GameMaster -> JankenJudge : judge("グー", "チョキ")
JankenJudge --> GameMaster : return "勝ち"
GameMaster -> ResultAnnouncer : announce("勝ち", ...)
ResultAnnouncer --> GameMaster : return
GameMaster --> main : return

main -> GameMaster : playJanken("チョキ")
GameMaster -> JankenJudge : judge("チョキ", "グー")
JankenJudge --> GameMaster : return "負け"
GameMaster -> ResultAnnouncer : announce("負け", ...)
ResultAnnouncer --> GameMaster : return
GameMaster --> main : return

main -> GameMaster : playJanken("パー")
GameMaster -> JankenJudge : judge("パー", "パー")
JankenJudge --> GameMaster : return "あいこ"
GameMaster -> ResultAnnouncer : announce("あいこ", ...)
ResultAnnouncer --> GameMaster : return
GameMaster --> main : return

@enduml
シーケンス図の縦線（ライフライン）はクラスやオブジェクトを表し、太線の部分（アクティベーション）は関数の実行中を示します。

矢印はメソッド（関数）の呼び出し・戻りを表しており、どのクラスのどの関数がどこから呼ばれたかが一目で分かります。
なお、実際のログにはif文の条件や分岐の情報も出力していますが、シーケンス図には関数の呼び出し関係や処理の流れのみを可視化しています。

分岐まで全てを図に盛り込むと情報が多くなりすぎてしまうため、

「処理全体の流れはシーケンス図で把握し、怪しい箇所はログやソースコードで分岐を詳しく追う」

という運用をしています。

 現場でどう変わったかツールを導入してから、不具合調査や実機の運用が以前よりだいぶやりやすくなったと感じています。

 実機リソースの有効活用私の職場では実機の数に限りがあり、複数人で不具合調査を進めると、しばしば「実機待ち」が発生していました。

ツール導入前は、「ログを入れ直して再ビルド→実機で動かす→またログ追加して…」の繰り返しで、調査のたびに何度も実機を使い直す必要がありました。

不具合の再現さえしてしまえば、あとはその時のログだけでいくらでも分析・追跡ができます。

実機リソースの使い方に余裕が生まれ、調査の効率が上がったと実感しています。

 処理の流れが「見える」ようになったシーケンス図自動生成ツールを使うことで、どこからどこまで処理が流れているのかが一目で分かるようになりました。

コードを頭で組み立てる必要がなくなり、全体の流れを図として瞬時に把握できます。

また、シーケンス図で「同じ形が続いている＝定常処理」「ここだけ形が変わった＝異常や分岐」

といった“見た目の変化”にもすぐ気づけるため、「流れが変わったポイント」や「いつもと違う動作」を発見しやすくなりました。

 まとめデバッガ無し・printf頼みの現場でも、自動ログ挿入やシーケンス図自動生成のツールがあれば、調査はかなり楽になります。

本当は「読んで分かるコード」が一番ですが、そう簡単にはいかないものです。

現場からは以上です。
プロローグ

はじめに

printf自動挿入ツールの誕生

手作業printfの限界

手作業でprintfを仕込むとどうなるか

正規表現の落とし穴

VSCodeの発見→tree-sitter導入

ツールの仕組み

シーケンス図自動生成ツールで見える化

技術的なポイント

じゃんけんプログラムで体験する可視化の力

サンプルの登場クラスと役割

具体的なビフォーアフター

ログ挿入前の例

ログ挿入後（自動挿入ツール適用例）

実行ログ例

シーケンス図自動生成ツールによる呼び出し経路の可視化

現場でどう変わったか

実機リソースの有効活用

処理の流れが「見える」ようになった

まとめ

Discussion
