遅い段階を見つける
モデル呼び出しのトレースとは、リクエストの各段階が何をして、どれだけ時間がかかったかを記録することです。モデルを使う機能は、処理の鎖の途中で失敗します。最初と最後にログを一行ずつ残しても、どこで失敗したかは分かりません。
ユーザーから「返事に十秒かかる」と連絡が来たとします。原因はプロンプトか、モデルか、再試行か、後の確認でしょうか。トレースがあれば、ひと目で分かります。
このレッスンのゴール
メモ
私は、各呼び出しが何をしたかを記録して、失敗や遅れの原因を探せます。
キーワード
| ことば | いみ |
|---|---|
| トレース | 一つのリクエストを始めから終わりまで記録したもの |
| スパン | トレースの中の、時間を測った一つの段階 |
| 親 | 別のスパンを含んでいるスパン |
| 属性 | スパンに付ける、名前の付いた情報 |
| トレース ID | 一つのリクエストの全スパンが共有する ID |
| マスキング | 記録を保存する前に秘密情報を取り除くこと |
| 自分の時間 | スパンの所要時間から子の所要時間を引いた値 |
学生が入力するセルは、このプレビューでは空白です。
トレースはスパンの木
トレースは一つのリクエストです。いくつものスパンでできています。スパンには名前、開始、終了、親があります。親とは、そのスパンを含むスパンのことです。親を持たないスパンは一つだけで、これがルートです。
一つのリクエストの全スパンは、同じトレース ID を持ちます。保存先はこれでスパンを集め直します。スパンには、ルートや結果などの属性も付きます。
例: 一つのリクエスト
| スパン | 親 | 開始 | 終了 | 所要時間 |
|---|---|---|---|---|
| リクエスト | なし | 0 | 856 | 856 ms |
| プロンプト作成 | リクエスト | 0 | 4 | 4 ms |
| モデル呼び出し | リクエスト | 4 | 854 | 850 ms |
| 応答の確認 | リクエスト | 854 | 856 | 2 ms |
学生が入力するセルは、このプレビューでは空白です。
トレースに入れてはいけないもの
トレースの保存先は多くの人が読み、何週間も残ります。ですから、スパンには秘密情報を入れません。API キー、トークン、パスワードです。個人情報も入れません。メールアドレス、氏名、電話番号です。
多くの場合、プロンプトや応答の本文も入れないほうが安全です。代わりに、長さ、件数、結果を残します。危険なキーは、スパンを保存する前に、一か所でまとめて取り除きます。この手順をマスキングと呼びます。
よくある間違い
注意
「ログは社内のものだから、プロンプトを全部書いても安全だ」と考える人が多くいます。しかし、プロンプトにはユーザーが打った内容が入り、そこには名前や秘密が混ざります。本文ではなく、長さと結果を記録しましょう。
モデル用の助っ人を書く（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"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
モデル用の助っ人を書く（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 d = await res.json();' ' return { text: d.choices[0].message.content, inTokens: count(d, \"prompt_tokens\"), outTokens: count(d, \"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\");' '' 'let now = 0; // 自分で進める時計。だれが動かしても同じ時間になる' 'const spans = [];' 'function tick(ms) { now = now + ms; }' 'function start(name, parent) {' ' const span = { id: spans.length + 1, name, parent, start: now, end: now, attrs: {} };' ' spans.push(span);' ' return span;' '}' 'function finish(span) { span.end = now; }' > trace1.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
トレーサーを書く（2）
docker exec -w /home/node/project agent sh -c "printf '%s\n' '// トレースに入れてはいけないキー。秘密情報と個人情報。' 'const NEVER = [\"email\", \"api_key\", \"prompt\", \"name\"];' 'function note(span, key, value) {' ' span.attrs[key] = NEVER.includes(key) ? \"[除去済み]\" : value;' '}' >> trace1.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
トレーサーを書く（3）
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'function show(parent, depth) {' ' for (const s of spans) {' ' if (s.parent === parent) {' ' console.log(\" \".repeat(depth) + s.name + \" \" + (s.end - s.start) + \" ms \" + JSON.stringify(s.attrs));' ' show(s.id, depth + 1);' ' }' ' }' '}' >> trace1.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
トレーサーを書く（4）
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'async function modelStep(root) {' ' const call = start(\"モデル呼び出し\", root.id);' ' const messages = [{ role: \"user\", content: \"トレースの使い道を一文で一つ答えてください。\" }];' ' const reply = await ask(messages, \"トレースを見ると、リクエストのどの段階が遅かったか分かります。\", 40);' ' tick(850); // 実際の呼び出しにかかった時間にかかわらず、自分の時計を850ミリ秒進める' ' note(call, \"result\", reply.text.length > 0 ? \"ok\" : \"empty\");' ' note(call, \"prompt\", messages[0].content);' ' finish(call);' '}' >> trace1.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
トレーサーを書く（5）
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'async function main() {' ' const root = start(\"リクエスト\", 0);' ' note(root, \"route\", \"/question\");' ' note(root, \"email\", \"[email protected]\");' ' const build = start(\"プロンプト作成\", root.id);' ' tick(4); finish(build);' ' await modelStep(root);' ' const check = start(\"応答の確認\", root.id);' ' tick(2); finish(check); finish(root);' ' console.log(\"トレース t-0001\");' ' show(0, 0);' '}' 'main();' >> trace1.js"ここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
実行してトレースを表示する
docker exec -w /home/node/project agent node trace1.jsここでは表示のみで、実行されません。無料アカウントを作成すると、実行ボタンで自分のラボのターミナルに入力できます。
練習用の代用品と、トレースの読み方
ラボにはトレースサービスがありません。そこで、スパンはリストに入れ、時計はスクリプトが進める数にしています。本物のシステムでは、スパンを本物のトレースサービスへ送り、本物の時計を読みます。
形は同じです。
遅い段階を探すには、自分の時間を使います。スパンの所要時間から、子の所要時間を引いた値です。親は子を含むので、いつも遅く見えるからです。
出力の例
| 行 | 示していること |
|---|---|
| トレース t-0001 | トレース ID |
| リクエスト 856 ms | ルート。ルートの情報があり、メールは除去されている |
| プロンプト作成 4 ms | 半角スペース二つ分下がった子 |
| モデル呼び出し 850 ms | 遅い段階。プロンプトは除去されている |
| 応答の確認 2 ms | 最後の子 |
学生が入力するセルは、このプレビューでは空白です。