Riebeckite
Menu
Color mode

Observability

Observability は、Riebeckite の実行中に 何が起きたのか、どこに時間がかかったのか を調べるための仕組みです。

Riebeckite では目的の異なる3つの仕組みを分けています。

  • Logger — 何が起きたかを知る
  • Tracer — どの処理にどれだけ時間がかかったかを記録する
  • Profiler — Trace をまとめて、Build のどこを調査すべきか確認する
Diagram source
text
flowchart LR
    R["Riebeckite Build"]
 
    R --> L["Logger"]
    R --> T["Tracer / TraceSink"]
 
    L --> LO["何が起きた？"]
    T --> SP["Timed Spans"]
    SP --> P["Profiler"]
    P --> PO["どこに時間がかかった？"]

Logger / Tracer / Profiler の違い

機能 答える問い 主な用途
Logger 何が起きた・失敗したか 実行状況やエラーの記録
Tracer / TraceSink どこで、どれだけ処理したか 処理時間を span として記録
Profiler Build のどこを調査すべきか Trace の集計と分析

たとえば Build が遅い場合、Logger に大量のメッセージを追加して原因を探すのではなく、Tracer で処理時間を記録し、Profiler でその結果を確認します。

逆に「Plugin の読み込みに失敗した」のような出来事を伝えるのは Logger の役割です。

Trace

Trace は、Build の処理を span という単位に分けて処理時間を記録します。

たとえば Build が次のように実行されたとします。

Diagram source
text
flowchart TD
    B["build"]
    B --> C["content.load"]
    B --> P["plugins.run"]
    B --> D["diagnostics.run"]
    B --> A["application.build"]
 
    P --> P1["plugin A"]
    P --> P2["plugin B"]

build が親 span、その中で実行される処理が child span になります。

これにより、

Build 全体が遅い

だけではなく、

plugins.run の中の特定 Plugin に時間がかかっている

といったところまで調べられます。

Span を作る場所

すべての関数に span を追加する必要はありません。

主に次のような、処理時間を知る意味がある境界へ追加します。

  • 主要な Build phase
  • Plugin の処理
  • ファイル読み込みなどの I/O
  • Diagnostics
  • その他、独立して性能を確認したい処理

span の名前には、Build 間で比較できる安定した名前を使用します。

たとえば、

text
content.load
plugins.run
diagnostics.run
application.build

のような名前です。

入力ファイル名などによって span 名そのものが毎回変化する設計は避けます。

Span は必ず閉じる

処理が成功した場合だけでなく、失敗した場合も span を閉じます。

Diagram source
text
flowchart TD
    A["Span 開始"]
    B["処理"]
    C{"成功？"}
    D["Span 終了"]
    E["Span 終了"]
    F["結果を返す"]
    G["Error を伝播"]
 
    A --> B --> C
    C -->|Yes| D --> F
    C -->|No| E --> G

Trace はエラー処理の代わりではありません。

処理が失敗した場合は Trace を記録したうえで、通常の caller contract に従って error を伝播します。

Trace のためにエラーを握りつぶしてはいけません。

並列処理と時間

Trace を読むときは、処理時間の合計と実際の経過時間は同じとは限らないことに注意してください。

たとえば Plugin A と Plugin B が並列に実行されたとします。

Diagram source
text
gantt
    title Parallel Plugin Work
    dateFormat X
    axisFormat %L ms
 
    section Plugins
    Plugin A :a, 0, 100
    Plugin B :b, 0, 100

それぞれが 100ms かかった場合、

text
Plugin A = 100ms
Plugin B = 100ms

なので、処理量としては合計 200ms です。

しかし2つは同時に実行されているため、実際の経過時間はおよそ 100ms です。

text
Cumulative work = 200ms
Wall-clock time = 約100ms

Profiler はこの違いを維持します。

child span の時間を単純に足して、

plugins.run = 200ms

のように表示すると、並列処理を直列処理のように見せてしまうためです。

Profiler

Profiler は Trace を集計して、Build のどこに時間がかかっているかを確認するための機能です。

CLI から実行できます。

sh
riebeckite profile

incremental state を再利用せず計測する場合は、

sh
riebeckite profile --full

を使用します。

--full は、incremental build の影響を避けて Build 全体の performance を調べたい場合に便利です。

Profiler の目的は、

「遅い」という事実から、次にどこを調査すればよいかを絞り込むこと

です。

Profiler は Cache の状況も分けて表示します。

  • Plugin cache — プラグイン自身が保存した結果の hit / miss
  • Content cache — persistent content cache の hit / miss / bypass と、miss / bypass の理由

これにより、

なぜ warm build なのにキャッシュが使われていないのか

を、安全性のための bypass なのか、依存関係の変更による miss なのかまで区別して確認できます。

Diagnostics の計測

Diagnostics も通常の Build phase と同じように計測されます。

Profiler には、

text
diagnostics.run

span の duration が表示されます。

さらに Diagnostics が生成した finding の件数も確認できます。

  • total
  • error
  • warning
  • info

これにより、

text
diagnostics.run
├─ duration
├─ total
├─ error
├─ warning
└─ info

のように、Diagnostics にどれだけ時間がかかり、どれだけの問題が報告されたのかを同時に確認できます。

たとえば Diagnostics が Build 時間の大部分を占めている場合、その phase をさらに調査する判断材料になります。

安全性

Observability は Riebeckite の動作を観測するための仕組みであり、Build の結果を変えてはいけません。

Instrumentation を有効にしても無効にしても、生成される Site は同じである必要があります。

また、Logger や Trace には次のような情報を記録しないでください。

  • secret
  • credential
  • token
  • 不要に機微なコンテンツ本文

観測のために必要な情報だけを記録します。

Trace や Profile の保存データも Build-time の情報です。

Cloudflare Workers などの runtime が、書き換え可能な Trace / Profile file に依存する設計にはしません。

問題を調査するとき

問題の種類によって使う機能を分けます。

Diagram source
text
flowchart TD
    Q{"何を調べたい？"}
 
    Q -->|"何が起きた？"| L["Logger"]
    Q -->|"どこに時間がかかった？"| P["Profiler"]
    Q -->|"設定や構成に問題がある？"| D["Diagnostics"]
    Q -->|"Build の状態を確認したい"| B["Build System / Inspector"]

Build が失敗している場合は Logger や Diagnostics、Build が遅い場合は Trace / Profiler、incremental build の状態を確認したい場合は Inspector と組み合わせて調査します。

Build の仕組みについては Build System、問題の報告については Diagnostics、現在の state を確認する場合は Inspector を参照してください。

History

1 changesCollapseExpand
1 + # Observability
2 +
3 + Observability は、Riebeckite の実行中に **何が起きたのか、どこに時間がかかったのか** を調べるための仕組みです。
4 +
5 + Riebeckite では目的の異なる3つの仕組みを分けています。
6 +
7 + - **Logger** — 何が起きたかを知る
8 + - **Tracer** — どの処理にどれだけ時間がかかったかを記録する
9 + - **Profiler** — Trace をまとめて、Build のどこを調査すべきか確認する
10 +
11 + ```mermaid
12 + flowchart LR
13 + R["Riebeckite Build"]
14 +
15 + R --> L["Logger"]
16 + R --> T["Tracer / TraceSink"]
17 +
18 + L --> LO["何が起きた？"]
19 + T --> SP["Timed Spans"]
20 + SP --> P["Profiler"]
21 + P --> PO["どこに時間がかかった？"]
22 + ```
23 +
24 + ## Logger / Tracer / Profiler の違い
25 +
26 + | 機能 | 答える問い | 主な用途 |
27 + | --- | --- | --- |
28 + | Logger | 何が起きた・失敗したか | 実行状況やエラーの記録 |
29 + | Tracer / `TraceSink` | どこで、どれだけ処理したか | 処理時間を span として記録 |
30 + | Profiler | Build のどこを調査すべきか | Trace の集計と分析 |
31 +
32 + たとえば Build が遅い場合、Logger に大量のメッセージを追加して原因を探すのではなく、Tracer で処理時間を記録し、Profiler でその結果を確認します。
33 +
34 + 逆に「Plugin の読み込みに失敗した」のような出来事を伝えるのは Logger の役割です。
35 +
36 + # Trace
37 +
38 + Trace は、Build の処理を **span** という単位に分けて処理時間を記録します。
39 +
40 + たとえば Build が次のように実行されたとします。
41 +
42 + ```mermaid
43 + flowchart TD
44 + B["build"]
45 + B --> C["content.load"]
46 + B --> P["plugins.run"]
47 + B --> D["diagnostics.run"]
48 + B --> A["application.build"]
49 +
50 + P --> P1["plugin A"]
51 + P --> P2["plugin B"]
52 + ```
53 +
54 + `build` が親 span、その中で実行される処理が child span になります。
55 +
56 + これにより、
57 +
58 + > Build 全体が遅い
59 +
60 + だけではなく、
61 +
62 + > `plugins.run` の中の特定 Plugin に時間がかかっている
63 +
64 + といったところまで調べられます。
65 +
66 + ## Span を作る場所
67 +
68 + すべての関数に span を追加する必要はありません。
69 +
70 + 主に次のような、処理時間を知る意味がある境界へ追加します。
71 +
72 + - 主要な Build phase
73 + - Plugin の処理
74 + - ファイル読み込みなどの I/O
75 + - Diagnostics
76 + - その他、独立して性能を確認したい処理
77 +
78 + span の名前には、Build 間で比較できる安定した名前を使用します。
79 +
80 + たとえば、
81 +
82 + ```text
83 + content.load
84 + plugins.run
85 + diagnostics.run
86 + application.build
87 + ```
88 +
89 + のような名前です。
90 +
91 + 入力ファイル名などによって span 名そのものが毎回変化する設計は避けます。
92 +
93 + ## Span は必ず閉じる
94 +
95 + 処理が成功した場合だけでなく、失敗した場合も span を閉じます。
96 +
97 + ```mermaid
98 + flowchart TD
99 + A["Span 開始"]
100 + B["処理"]
101 + C{"成功？"}
102 + D["Span 終了"]
103 + E["Span 終了"]
104 + F["結果を返す"]
105 + G["Error を伝播"]
106 +
107 + A --> B --> C
108 + C -->|Yes| D --> F
109 + C -->|No| E --> G
110 + ```
111 +
112 + Trace はエラー処理の代わりではありません。
113 +
114 + 処理が失敗した場合は Trace を記録したうえで、通常の caller contract に従って error を伝播します。
115 +
116 + Trace のためにエラーを握りつぶしてはいけません。
117 +
118 + # 並列処理と時間
119 +
120 + Trace を読むときは、**処理時間の合計と実際の経過時間は同じとは限らない**ことに注意してください。
121 +
122 + たとえば Plugin A と Plugin B が並列に実行されたとします。
123 +
124 + ```mermaid
125 + gantt
126 + title Parallel Plugin Work
127 + dateFormat X
128 + axisFormat %L ms
129 +
130 + section Plugins
131 + Plugin A :a, 0, 100
132 + Plugin B :b, 0, 100
133 + ```
134 +
135 + それぞれが 100ms かかった場合、
136 +
137 + ```text
138 + Plugin A = 100ms
139 + Plugin B = 100ms
140 + ```
141 +
142 + なので、処理量としては合計 200ms です。
143 +
144 + しかし2つは同時に実行されているため、実際の経過時間はおよそ 100ms です。
145 +
146 + ```text
147 + Cumulative work = 200ms
148 + Wall-clock time = 約100ms
149 + ```
150 +
151 + Profiler はこの違いを維持します。
152 +
153 + child span の時間を単純に足して、
154 +
155 + > plugins.run = 200ms
156 +
157 + のように表示すると、並列処理を直列処理のように見せてしまうためです。
158 +
159 + # Profiler
160 +
161 + Profiler は Trace を集計して、Build のどこに時間がかかっているかを確認するための機能です。
162 +
163 + CLI から実行できます。
164 +
165 + ```sh
166 + riebeckite profile
167 + ```
168 +
169 + incremental state を再利用せず計測する場合は、
170 +
171 + ```sh
172 + riebeckite profile --full
173 + ```
174 +
175 + を使用します。
176 +
177 + `--full` は、incremental build の影響を避けて Build 全体の performance を調べたい場合に便利です。
178 +
179 + Profiler の目的は、
180 +
181 + **「遅い」という事実から、次にどこを調査すればよいかを絞り込むこと**
182 +
183 + です。
184 +
185 + Profiler は Cache の状況も分けて表示します。
186 +
187 + - **Plugin cache** — プラグイン自身が保存した結果の hit / miss
188 + - **Content cache** — persistent content cache の hit / miss / bypass と、miss / bypass の理由
189 +
190 + これにより、
191 +
192 + > なぜ warm build なのにキャッシュが使われていないのか
193 +
194 + を、安全性のための bypass なのか、依存関係の変更による miss なのかまで区別して確認できます。
195 +
196 + # Diagnostics の計測
197 +
198 + Diagnostics も通常の Build phase と同じように計測されます。
199 +
200 + Profiler には、
201 +
202 + ```text
203 + diagnostics.run
204 + ```
205 +
206 + span の duration が表示されます。
207 +
208 + さらに Diagnostics が生成した finding の件数も確認できます。
209 +
210 + - total
211 + - error
212 + - warning
213 + - info
214 +
215 + これにより、
216 +
217 + ```text
218 + diagnostics.run
219 + ├─ duration
220 + ├─ total
221 + ├─ error
222 + ├─ warning
223 + └─ info
224 + ```
225 +
226 + のように、**Diagnostics にどれだけ時間がかかり、どれだけの問題が報告されたのか**を同時に確認できます。
227 +
228 + たとえば Diagnostics が Build 時間の大部分を占めている場合、その phase をさらに調査する判断材料になります。
229 +
230 + # 安全性
231 +
232 + Observability は **Riebeckite の動作を観測するための仕組み**であり、Build の結果を変えてはいけません。
233 +
234 + Instrumentation を有効にしても無効にしても、生成される Site は同じである必要があります。
235 +
236 + また、Logger や Trace には次のような情報を記録しないでください。
237 +
238 + - secret
239 + - credential
240 + - token
241 + - 不要に機微なコンテンツ本文
242 +
243 + 観測のために必要な情報だけを記録します。
244 +
245 + Trace や Profile の保存データも Build-time の情報です。
246 +
247 + Cloudflare Workers などの runtime が、書き換え可能な Trace / Profile file に依存する設計にはしません。
248 +
249 + # 問題を調査するとき
250 +
251 + 問題の種類によって使う機能を分けます。
252 +
253 + ```mermaid
254 + flowchart TD
255 + Q{"何を調べたい？"}
256 +
257 + Q -->|"何が起きた？"| L["Logger"]
258 + Q -->|"どこに時間がかかった？"| P["Profiler"]
259 + Q -->|"設定や構成に問題がある？"| D["Diagnostics"]
260 + Q -->|"Build の状態を確認したい"| B["Build System / Inspector"]
261 + ```
262 +
263 + Build が失敗している場合は Logger や Diagnostics、Build が遅い場合は Trace / Profiler、incremental build の状態を確認したい場合は Inspector と組み合わせて調査します。
264 +
265 + Build の仕組みについては [Build System](build-system.md)、問題の報告については [Diagnostics](diagnostics.md)、現在の state を確認する場合は [Inspector](inspector.md) を参照してください。
266 +