Skip to content

Commit 23e3bcf

Browse files
committed
refactor(sqlite): simplify profiling fingerprints
1 parent 61c44d1 commit 23e3bcf

10 files changed

Lines changed: 184 additions & 380 deletions

File tree

docs/content/docs/sqlite-profiling.mdx

Lines changed: 109 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,8 @@ skill: true
66

77
Profiling helps you find slow queries, transaction contention, and unnecessary storage activity.
88

9+
Collect [Prometheus metrics from each worker](/actors/self-host/workers/prometheus-metrics/) to use the queries below.
10+
911
## Identify operations
1012

1113
### Transaction names
@@ -18,17 +20,29 @@ Without a name, RivetKit falls back to a fingerprint of the transaction's statem
1820

1921
### Statement fingerprints
2022

21-
RivetKit normalizes each SQL statement into a sanitized shape, then hashes that shape into a stable fingerprint. The fingerprint groups metrics without putting SQL text in a Prometheus label.
22-
23-
- Bound and inline literal values do not change the fingerprint.
24-
- Whitespace, capitalization, and comments do not change the fingerprint.
25-
- Keep query structure static and use `?` or named bindings for dynamic values.
23+
RivetKit hashes each SQL statement exactly as provided. The fingerprint groups metrics without putting SQL text in a Prometheus label.
2624

2725
For example, repeated `SELECT * FROM orders WHERE id = ?` calls share one fingerprint regardless of the bound ID.
2826

27+
### Find the SQL for a fingerprint
28+
29+
RivetKit logs the SQL statement or transaction name for each tracked fingerprint.
30+
31+
For example, suppose a Prometheus result contains `fingerprint="select-a1b2c3d4e5f60718"`:
32+
33+
1. Copy the fingerprint: `select-a1b2c3d4e5f60718`.
34+
2. Search the actor logs for `sqlite fingerprint catalog` and `select-a1b2c3d4e5f60718`.
35+
3. Read `identity` from the matching log line:
36+
37+
```text
38+
sqlite fingerprint catalog fingerprint="select-a1b2c3d4e5f60718" identity="SELECT value FROM items WHERE id = ?"
39+
```
40+
41+
For a transaction fingerprint, `identity` contains its static transaction name.
42+
2943
## Find slow operations
3044

31-
**Slowest statements and transactions**
45+
### Slowest statements and transactions
3246

3347
```promql
3448
histogram_quantile(
@@ -39,25 +53,72 @@ histogram_quantile(
3953
)
4054
```
4155

42-
**Failed operations**
56+
### Slowest latency phases
57+
58+
```promql
59+
histogram_quantile(
60+
0.95,
61+
sum by (le, actor_name, type, fingerprint, phase) (
62+
rate(rivet_rivetkit_sqlite_phase_duration_seconds_bucket[5m])
63+
)
64+
)
65+
```
66+
67+
- `transaction_wait`: waiting for another transaction on the actor to finish.
68+
- `worker_wait`: waiting for earlier SQLite work on the actor to finish.
69+
- `storage`: loading or saving SQLite data.
70+
- `local_work`: executing SQL and preparing results, excluding storage time.
71+
- `application_time`: time the transaction stays open between SQL calls.
72+
- `commit`: saving changes at the end of a transaction.
73+
74+
### Non-success outcomes
4375

4476
```promql
4577
sum by (actor_name, type, fingerprint, outcome) (
4678
rate(rivet_rivetkit_sqlite_outcome_total{outcome!="success"}[5m])
4779
)
4880
```
4981

50-
**Transaction contention**
82+
### Transaction contention
5183

5284
```promql
5385
max by (actor_name) (
5486
max_over_time(rivet_rivetkit_sqlite_coordinator_queue_depth[5m])
5587
)
5688
```
5789

90+
### Native worker saturation
91+
92+
```promql
93+
max by (actor_name) (
94+
max_over_time(rivet_rivetkit_sqlite_worker_queue_depth[5m])
95+
)
96+
```
97+
98+
```promql
99+
avg by (actor_name) (
100+
avg_over_time(rivet_rivetkit_sqlite_worker_inflight[5m])
101+
)
102+
```
103+
104+
A sustained worker queue indicates SQLite work is arriving faster than the actor's native worker completes it. The average `worker_inflight` value is the fraction of sampled time that the worker was executing a command.
105+
106+
### Transactions with the most statements
107+
108+
```promql
109+
histogram_quantile(
110+
0.95,
111+
sum by (le, actor_name, fingerprint) (
112+
rate(rivet_rivetkit_sqlite_transaction_statement_count_bucket[5m])
113+
)
114+
)
115+
```
116+
117+
Large statement counts can identify loops or oversized units of work. Use a static transaction name so the fingerprint remains stable across branches.
118+
58119
## Find storage-heavy operations
59120

60-
**Operations with the most storage requests**
121+
### Average storage round trips per operation
61122

62123
```promql
63124
sum by (actor_name, type, fingerprint) (
@@ -69,15 +130,48 @@ sum by (actor_name, type, fingerprint) (
69130
)
70131
```
71132

72-
**SQLite page usage by kind**
133+
### Pages per physical storage request
134+
135+
```promql
136+
sum by (actor_name, request_ordinal, page_kind) (
137+
rate(rivet_rivetkit_sqlite_get_pages_pages_sum[5m])
138+
)
139+
/
140+
sum by (actor_name, request_ordinal, page_kind) (
141+
rate(rivet_rivetkit_sqlite_get_pages_pages_count[5m])
142+
)
143+
```
144+
145+
Compare `response_present` with `demand_requested` to see response amplification. `overflow_expansion_extra` shows pages added while resolving SQLite overflow chains, and `prefetch_requested` shows speculative reads.
146+
147+
### Large storage responses
148+
149+
```promql
150+
histogram_quantile(
151+
0.95,
152+
sum by (le, actor_name, request_ordinal) (
153+
rate(rivet_rivetkit_sqlite_get_pages_response_bytes_bucket[5m])
154+
)
155+
)
156+
```
157+
158+
### Missing response pages
159+
160+
```promql
161+
sum by (actor_name, request_ordinal) (
162+
rate(rivet_rivetkit_sqlite_get_pages_missing_pages_total[5m])
163+
)
164+
```
165+
166+
### SQLite page usage by kind
73167

74168
```promql
75169
sum by (actor_name, type, page_kind) (
76170
rate(rivet_rivetkit_sqlite_local_pages_total[5m])
77171
)
78172
```
79173

80-
**SQLite data volume by kind**
174+
### SQLite data volume by kind
81175

82176
```promql
83177
sum by (actor_name, type, byte_kind) (
@@ -91,18 +185,15 @@ High round-trip or page counts can indicate a missing index, a large scan, or in
91185

92186
RivetKit emits bounded structured diagnostics for operations that are slow, fail, show unusual storage amplification, or are selected by baseline sampling.
93187

94-
- Fingerprint catalog events map a fingerprint to its sanitized SQL shape or static transaction name.
95-
- Operation events include latency phases, rows, bytes, page activity, and storage requests.
188+
- Operation events include timing components, rows, bytes, page activity, and storage requests.
96189
- Transaction events include statement count, application-held time, commit time, and terminal outcome.
97190
- Event sampling, rate limits, and a bounded queue prevent diagnostics from blocking SQLite work.
98191

99-
Search actor logs for `sqlite fingerprint catalog` or `sampled SQLite operation profile` and match events using the `fingerprint` field.
100-
101-
Catalog events contain the sanitized SQL shape, never bound values or raw SQL. Continue binding dynamic values instead of constructing SQL strings.
192+
Search actor logs for `sampled SQLite operation profile` to inspect one profiled statement execution. Transaction details use `sampled SQLite transaction profile`.
102193

103194
## Configure profiling
104195

105-
Profiling is enabled by default and most applications do not need to configure it. Set `profiling.slowOperationThresholdMs` or `profiling.baselineSampleRate` on the database provider when needed.
196+
Profiling is enabled by default and most applications do not need to configure it. The entire profiling configuration surface is experimental and subject to change without notice. Set `profiling.slowOperationThresholdMs` or `profiling.baselineSampleRate` on the database provider when needed.
106197

107198
Increase fingerprint limits only when `other` is hiding frequently repeated operations. Prometheus series remain allocated for the life of the process after admission.
108199

@@ -114,7 +205,7 @@ Fast statements initially appear under `other`, while overflow metrics show when
114205

115206
### Too many fingerprints
116207

117-
Fingerprints use normalized SQL shapes, so formatting, comments, and literal values do not create separate entries. Keep query structure static and pass dynamic values as bindings.
208+
Statement fingerprints use the exact query text. Keep formatting and query structure static, and pass dynamic values as bindings instead of constructing SQL strings.
118209

119210
### Transactions are hard to identify
120211

rivetkit-rust/packages/rivetkit-core/src/actor/config.rs

Lines changed: 0 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -67,10 +67,7 @@ pub struct SqliteProfilingConfig {
6767
pub max_prometheus_series: usize,
6868
pub max_statements_per_transaction_trace: usize,
6969
pub max_get_pages_requests_per_trace: usize,
70-
pub max_sql_bytes_to_normalize: usize,
71-
pub max_catalog_sql_shape_bytes: usize,
7270
pub max_transaction_name_bytes: usize,
73-
pub fingerprint_computation_cache_entries: usize,
7471
pub slow_operation_threshold_ms: u64,
7572
pub baseline_sample_rate: f64,
7673
pub max_diagnostic_events_per_minute: usize,
@@ -86,10 +83,7 @@ impl Default for SqliteProfilingConfig {
8683
max_prometheus_series: 25_000,
8784
max_statements_per_transaction_trace: 32,
8885
max_get_pages_requests_per_trace: 16,
89-
max_sql_bytes_to_normalize: 65_536,
90-
max_catalog_sql_shape_bytes: 4_096,
9186
max_transaction_name_bytes: 128,
92-
fingerprint_computation_cache_entries: 1_024,
9387
slow_operation_threshold_ms: 10,
9488
baseline_sample_rate: 0.001,
9589
max_diagnostic_events_per_minute: 120,
@@ -111,10 +105,7 @@ pub struct SqliteProfilingConfigInput {
111105
pub max_prometheus_series: Option<u32>,
112106
pub max_statements_per_transaction_trace: Option<u32>,
113107
pub max_get_pages_requests_per_trace: Option<u32>,
114-
pub max_sql_bytes_to_normalize: Option<u32>,
115-
pub max_catalog_sql_shape_bytes: Option<u32>,
116108
pub max_transaction_name_bytes: Option<u32>,
117-
pub fingerprint_computation_cache_entries: Option<u32>,
118109
pub slow_operation_threshold_ms: Option<u32>,
119110
pub baseline_sample_rate: Option<f64>,
120111
pub max_diagnostic_events_per_minute: Option<u32>,
@@ -139,10 +130,7 @@ impl SqliteProfilingConfig {
139130
set_usize!(max_prometheus_series);
140131
set_usize!(max_statements_per_transaction_trace);
141132
set_usize!(max_get_pages_requests_per_trace);
142-
set_usize!(max_sql_bytes_to_normalize);
143-
set_usize!(max_catalog_sql_shape_bytes);
144133
set_usize!(max_transaction_name_bytes);
145-
set_usize!(fingerprint_computation_cache_entries);
146134
if let Some(value) = input.slow_operation_threshold_ms {
147135
config.slow_operation_threshold_ms = u64::from(value);
148136
}

rivetkit-rust/packages/rivetkit-core/src/actor/sqlite/mod.rs

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -474,15 +474,15 @@ impl SqliteDb {
474474
}
475475
let fingerprint = self.profiling.statement_fingerprint(sql)?;
476476
let observation = profiling::StatementObservation {
477-
fingerprint: Arc::clone(&fingerprint),
477+
fingerprint,
478478
total_ns: duration_ns(started_at.elapsed()),
479479
transaction_wait_ns: duration_ns(transaction_wait),
480480
profile: profile.unwrap_or_default(),
481481
};
482482
if let Some(metrics) = &self.vfs_metrics {
483483
let metric = depot_client::vfs::SqliteOperationMetric {
484484
operation_type: "statement",
485-
fingerprint: fingerprint.display.clone(),
485+
fingerprint: observation.fingerprint.display.clone(),
486486
fingerprint_source: "query",
487487
transaction_mode,
488488
storage_transport: "proxy",
@@ -493,13 +493,13 @@ impl SqliteDb {
493493
profile: observation.profile.clone(),
494494
};
495495
if metrics.observe_operation_profile(&metric)
496-
&& self.profiling.mark_cataloged(&fingerprint.display)
496+
&& self.profiling.mark_cataloged(&metric.fingerprint)
497497
{
498498
metrics.record_fingerprint_catalog(
499499
"statement",
500-
&fingerprint.display,
501-
&fingerprint.normalized_sql,
502-
1,
500+
&metric.fingerprint,
501+
sql,
502+
profiling::FINGERPRINT_FORMAT_VERSION,
503503
);
504504
}
505505
metrics.emit_operation_diagnostic_event(

0 commit comments

Comments
 (0)