なぜ返答に五秒かかったのか
サポートのアシスタントが、計画を立て、ツールを二つ呼び、もう一度モデルに聞いて、返答を確かめます。利用者は五秒待ち、請求も予定より高くなりました。遅かったのはどの手順で、お金を使ったのはどれでしょうか。
モジュール 69 では、一回の呼び出しをトレースしました。このレッスンはさらに進み、エージェントの実行全体を、手順ごとのトークン、費用、失敗とともに読みます。
このレッスンのゴール
メモ
AI機能を通るリクエストをトレースし、そのトレースから、遅い手順、高い手順、失敗した手順を見つけることができる。
キーワード
| ことば | いみ | れい |
|---|---|---|
| スパンID | 一つのスパンのID | |
| 親スパンID | このスパンを含むスパンのID | |
| 状態 | スパンがうまく終わったか、エラーで終わったか | error |
| ツールのスパン | エージェントが呼んだツール一つのスパン | |
| トークン数 | 入った、または出たトークンの数 | |
| オープンな標準 | 誰でも使える共通の設計 |
学生が入力するセルは、このプレビューでは空白です。
スパンは、IDと時間と事実を持つ
どのスパンも、スパンID と、そのリクエストの トレースID を持ちます。親は 親スパンID で示し、ルートではこれが空です。
スパンには、名前、開始、終了、状態(ok か error)があります。事実は属性に入れます。OpenTelemetry は、時間を 1970 年からのナノ秒で持ちます。このラボでは、数を短くするため、開始からのミリ秒にしています。
例: モデル呼び出しのスパン
| 項目 | 値 |
|---|---|
| trace_id | 7a3f0c1d00000000000000000000aa01 |
| span_id | 0000000000000005 |
| parent_span_id | 0000000000000001 |
| name | モデル: 回答 |
| start と end | 3100 と 4900 |
| status | ok |
| attributes | model m-small-2026-08、input_tokens 2100、output_tokens 300、fallback true |
学生が入力するセルは、このプレビューでは空白です。
モデル呼び出しのスパンが記録するもの
モデルとその版を記録します。新しい版で、速さも費用も変わることがあるからです。入力と出力のトークン数と、かかった時間も記録します。再試行したか、別のモデルに切り替えたかも記録します。
個人情報を、平文のままスパンに載せてはいけません。外す方法は、モジュール 86 のレッスン「AIアプリで安全に記録する」で学びます。
エージェントはツールごとにスパンを足す
エージェントは、モデルを呼ぶだけではありません。計画を立て、ツールを呼び、またモデルに聞きます。ツールの呼び出しごとに、リクエストのスパンの子として ツールのスパン を作ります。
ツールのスパンは、ツールの名前、時間、状態を記録します。ツールが失敗すると、リクエストがうまく終わっても、その中に error として残ります。
助っ人 model.js を書く(1)
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'const base = process.env.AI_URL || \"http://ai:4000\";' '// 応答のトークン数。なければ null。' 'function count(data, name) {' ' return data.usage && typeof data.usage[name] === \"number\" ? data.usage[name] : null;' '}' > model.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
助っ人 model.js を書く(2)
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'async function ask(messages, sample, max) {' ' try {' ' const res = await fetch(base + \"/v1/chat/completions\", {' ' method: \"POST\",' ' headers: { \"content-type\": \"application/json\", authorization: \"Bearer lab\" },' ' body: JSON.stringify({ model: \"lab\", messages: messages, max_tokens: max || 100 }),' ' signal: AbortSignal.timeout(30000),' ' });' ' if (res.ok === false) throw new Error(\"status \" + res.status);' ' const data = await res.json();' ' const text = data.choices[0].message.content;' ' return { text, inTokens: count(data, \"prompt_tokens\"), outTokens: count(data, \"completion_tokens\"), recorded: false };' ' } catch (error) {' ' console.log(\"記録済みサンプル: モデルが答えませんでした (\" + error.message + \")。\");' ' return { text: sample, inTokens: null, outTokens: null, recorded: true };' ' }' '}' 'module.exports = { ask };' >> model.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
エージェントのトレースを書く(1)
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'const { ask } = require(\"./model\");' 'const TRACE = \"7a3f0c1d00000000000000000000aa01\";' 'const PRICES = { \"m-large-2026-09\": [3, 15], \"m-small-2026-08\": [1, 4] };' 'const spans = [];' 'function sid(n) { return String(n).padStart(16, \"0\"); }' 'function span(n, parent, name, start, end, status, attributes) {' ' spans.push({ trace_id: TRACE, span_id: sid(n), parent_span_id: parent ? sid(parent) : \"\",' ' name, start, end, status, attributes });' '}' > trace2.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
エージェントのトレースを書く(2)
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'span(1, 0, \"エージェントのリクエスト\", 0, 5000, \"ok\", {});' 'span(2, 1, \"モデル: 計画\", 0, 800, \"ok\", { model: \"m-large-2026-09\", input_tokens: 900, output_tokens: 60 });' 'span(3, 1, \"ツール: 注文を探す\", 800, 1100, \"ok\", { tool: \"find_order\" });' 'span(4, 1, \"ツール: 配達日\", 1100, 3100, \"error\", { tool: \"delivery_date\" });' 'span(5, 1, \"モデル: 回答\", 3100, 4900, \"ok\", { model: \"m-small-2026-08\", input_tokens: 2100, output_tokens: 300, fallback: true });' 'span(6, 1, \"返答の確認\", 4900, 5000, \"ok\", {});' 'function kids(id) { return spans.filter(function (s) { return s.parent_span_id === id; }); }' 'function took(s) { return s.end - s.start; }' >> trace2.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
エージェントのトレースを書く(3)
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'function cost(a) {' ' const p = PRICES[a.model];' ' return p ? a.input_tokens * p[0] + a.output_tokens * p[1] : 0;' '}' 'function show(id, depth) {' ' for (const s of kids(id)) {' ' const flag = s.attributes.fallback ? \"、代わりのモデル\" : \"\";' ' console.log(\" \".repeat(depth) + s.name + \" \" + took(s) + \" ms \" + s.status + flag);' ' show(s.span_id, depth + 1);' ' }' '}' >> trace2.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
エージェントのトレースを書く(4)
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'async function main() {' ' console.log(\"トレース \" + TRACE);' ' show(\"\", 0);' ' const leaves = spans.filter(function (s) { return kids(s.span_id).length === 0; });' ' leaves.sort(function (a, b) { return took(b) - took(a); });' ' console.log(\"いちばん遅い手順: \" + leaves[0].name + \"、\" + took(leaves[0]) + \" ms\");' ' const priced = spans.filter(function (s) { return cost(s.attributes) > 0; });' ' priced.sort(function (a, b) { return cost(b.attributes) - cost(a.attributes); });' ' console.log(\"いちばん高い手順: \" + priced[0].name + \"、\" + cost(priced[0].attributes) + \" ユニット\");' ' for (const s of spans.filter(function (one) { return one.status === \"error\"; })) {' ' const up = spans.find(function (one) { return one.span_id === s.parent_span_id; });' ' console.log(\"失敗: \" + s.name + \"、親は \" + (up ? up.name : \"なし\"));' ' }' >> trace2.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
エージェントのトレースを書く(5)
docker exec -w /home/node/project agent sh -c "printf '%s\n' ' const live = { trace_id: \"7a3f0c1d00000000000000000000aa02\", span_id: sid(7), parent_span_id: \"\",' ' name: \"モデル: 生の確認\", start: 0, end: 600, status: \"ok\", attributes: {} };' ' const messages = [{ role: \"user\", content: \"短く一文で答えてください。スパンは何を記録しますか。\" }];' ' const reply = await ask(messages, \"スパンは、リクエストの中の、時間を測った一つの手順を記録します。\", 40);' ' live.attributes = { model: \"lab\", input_tokens: reply.inTokens, output_tokens: reply.outTokens, recorded: reply.recorded };' ' console.log(\"生のスパン: \" + JSON.stringify(live));' ' console.log(\"モデル: \" + reply.text);' '}' 'main();' >> trace2.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
トレースを動かして読む
docker exec -w /home/node/project agent node trace2.jsここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
Run の出力
| 行 | 意味 |
|---|---|
| トレース 7a3f0c1d00000000000000000000aa01 | どのスパンにも共通のトレースID |
| ツール: 配達日 2000 ms error | 失敗したツールのスパン |
| モデル: 回答 1800 ms ok、代わりのモデル | 別のモデルを使ったモデルのスパン |
| いちばん遅い手順: ツール: 配達日、2000 ms | 子のない手順のうち、いちばん長いもの |
| いちばん高い手順: モデル: 計画、3600 ユニット | トークン数に、そのモデルの値段をかけたもの |
| 生のスパン: {...} | 生の呼び出し一回をスパンにしたもの。記録済みサンプルが答えると、トークン数は null |
学生が入力するセルは、このプレビューでは空白です。
トレースを三つの見方で読む
速さを見るなら、子のない手順のうち、いちばん長くかかったものを探します。費用を見るなら、モデルのスパンごとに、トークン数にそのモデルの値段をかけます。
失敗を見るなら、状態が error のスパンと、それを含む親のスパンを挙げます。うまく終わったスパンの中に失敗した子があれば、エージェントは立ち直ったということです。
よくある間違い
注意
いちばん遅い手順が、いちばん高い手順でもあると考える人が多いです。ここでは配達日のツールがいちばん遅く、計画の呼び出しがいちばん高くつきます。時間は待ちで、費用はトークンで決まるので、何かを変える前に両方を調べます。
OpenTelemetry は共通の標準
OpenTelemetry は、トレース、メトリクス、ログのためのオープンな標準です。多くのツールがそのスパンの形を読めるので、一つの記録を複数の保存先で使えます。
AIの呼び出しの属性にも、草案の名前があります。草案はまだ変わっている途中なので、下の名前は例として扱ってください。使う前に、最新の文書で確かめてください。
草案の名前(最新の文書で確認)
| こちらの鍵 | 草案の名前 | 中身 |
|---|---|---|
| model | gen_ai.request.model | 頼んだモデル |
| input_tokens | gen_ai.usage.input_tokens | 送ったトークン |
| output_tokens | gen_ai.usage.output_tokens | 出てきたトークン |
| tool | gen_ai.tool.name | 呼んだツール |
| ここにはない | gen_ai.operation.name | 呼び出しの種類(chat など) |
学生が入力するセルは、このプレビューでは空白です。