Nix Observability Daemon
observability
nix
simplify!
+317
-324
-38
.sqlx/query-089e573957a6b2e2371c5a8e1bd6f7f7408369b8e9a44307088a136231472e53.json
-38
.sqlx/query-089e573957a6b2e2371c5a8e1bd6f7f7408369b8e9a44307088a136231472e53.json
···
1
-
{
2
-
"db_name": "SQLite",
3
-
"query": "SELECT event_type as \"event_type!\", CAST(COUNT(*) AS INTEGER) as \"count!\", CAST(SUM(duration_ms) AS INTEGER) as \"total_ms\", CAST(AVG(duration_ms) AS REAL) as \"avg_ms!\"\n FROM events GROUP BY event_type ORDER BY total_ms DESC",
4
-
"describe": {
5
-
"columns": [
6
-
{
7
-
"name": "event_type!",
8
-
"ordinal": 0,
9
-
"type_info": "Int64"
10
-
},
11
-
{
12
-
"name": "count!",
13
-
"ordinal": 1,
14
-
"type_info": "Int"
15
-
},
16
-
{
17
-
"name": "total_ms",
18
-
"ordinal": 2,
19
-
"type_info": "Int"
20
-
},
21
-
{
22
-
"name": "avg_ms!",
23
-
"ordinal": 3,
24
-
"type_info": "Float"
25
-
}
26
-
],
27
-
"parameters": {
28
-
"Right": 0
29
-
},
30
-
"nullable": [
31
-
true,
32
-
false,
33
-
true,
34
-
true
35
-
]
36
-
},
37
-
"hash": "089e573957a6b2e2371c5a8e1bd6f7f7408369b8e9a44307088a136231472e53"
38
-
}
+32
.sqlx/query-0bcfc2ee3a0b7cf099fe676813616b903265959353dad8b3d263be382e335967.json
+32
.sqlx/query-0bcfc2ee3a0b7cf099fe676813616b903265959353dad8b3d263be382e335967.json
···
1
+
{
2
+
"db_name": "SQLite",
3
+
"query": "SELECT cache_url as \"cache_url!\", CAST(AVG(duration_ms) AS REAL) as \"avg_ms!\", CAST(COUNT(*) AS INTEGER) as \"count!\"\n FROM events WHERE cache_url IS NOT NULL\n GROUP BY cache_url ORDER BY 2 DESC",
4
+
"describe": {
5
+
"columns": [
6
+
{
7
+
"name": "cache_url!",
8
+
"ordinal": 0,
9
+
"type_info": "Text"
10
+
},
11
+
{
12
+
"name": "avg_ms!",
13
+
"ordinal": 1,
14
+
"type_info": "Float"
15
+
},
16
+
{
17
+
"name": "count!",
18
+
"ordinal": 2,
19
+
"type_info": "Int64"
20
+
}
21
+
],
22
+
"parameters": {
23
+
"Right": 0
24
+
},
25
+
"nullable": [
26
+
true,
27
+
true,
28
+
false
29
+
]
30
+
},
31
+
"hash": "0bcfc2ee3a0b7cf099fe676813616b903265959353dad8b3d263be382e335967"
32
+
}
-38
.sqlx/query-1224d24c36144c233d68aa99cfef9ed88be349a6058e3fd1df2d3860cce7dd66.json
-38
.sqlx/query-1224d24c36144c233d68aa99cfef9ed88be349a6058e3fd1df2d3860cce7dd66.json
···
1
-
{
2
-
"db_name": "SQLite",
3
-
"query": "SELECT phase_name as \"name!\", CAST(COUNT(*) AS INTEGER) as \"count!\", CAST(SUM(duration_ms) AS INTEGER) as \"total_ms\", CAST(AVG(duration_ms) AS REAL) as \"avg_ms!\"\n FROM phases GROUP BY phase_name ORDER BY total_ms DESC LIMIT 8",
4
-
"describe": {
5
-
"columns": [
6
-
{
7
-
"name": "name!",
8
-
"ordinal": 0,
9
-
"type_info": "Text"
10
-
},
11
-
{
12
-
"name": "count!",
13
-
"ordinal": 1,
14
-
"type_info": "Int"
15
-
},
16
-
{
17
-
"name": "total_ms",
18
-
"ordinal": 2,
19
-
"type_info": "Int"
20
-
},
21
-
{
22
-
"name": "avg_ms!",
23
-
"ordinal": 3,
24
-
"type_info": "Float"
25
-
}
26
-
],
27
-
"parameters": {
28
-
"Right": 0
29
-
},
30
-
"nullable": [
31
-
true,
32
-
false,
33
-
true,
34
-
true
35
-
]
36
-
},
37
-
"hash": "1224d24c36144c233d68aa99cfef9ed88be349a6058e3fd1df2d3860cce7dd66"
38
-
}
-12
.sqlx/query-1bb0081dc5f5f17fdb0d8b1d5b957d5f0c80b2ed422c21640b71ebf9a1d97d1d.json
-12
.sqlx/query-1bb0081dc5f5f17fdb0d8b1d5b957d5f0c80b2ed422c21640b71ebf9a1d97d1d.json
···
1
-
{
2
-
"db_name": "SQLite",
3
-
"query": "INSERT INTO phases (event_nix_id, phase_name, duration_ms) VALUES (?, ?, ?)",
4
-
"describe": {
5
-
"columns": [],
6
-
"parameters": {
7
-
"Right": 3
8
-
},
9
-
"nullable": []
10
-
},
11
-
"hash": "1bb0081dc5f5f17fdb0d8b1d5b957d5f0c80b2ed422c21640b71ebf9a1d97d1d"
12
-
}
-38
.sqlx/query-794b666df6d03afb34990aac32c093da05e2d267359d2d3c2cbee3c9994e972f.json
-38
.sqlx/query-794b666df6d03afb34990aac32c093da05e2d267359d2d3c2cbee3c9994e972f.json
···
1
-
{
2
-
"db_name": "SQLite",
3
-
"query": "SELECT duration_ms as \"duration_ms!\", event_type as \"event_type!\", drv_path, text\n FROM events\n WHERE event_type IN (105, 108, 102, 112)\n ORDER BY duration_ms DESC LIMIT 10",
4
-
"describe": {
5
-
"columns": [
6
-
{
7
-
"name": "duration_ms!",
8
-
"ordinal": 0,
9
-
"type_info": "Int64"
10
-
},
11
-
{
12
-
"name": "event_type!",
13
-
"ordinal": 1,
14
-
"type_info": "Int64"
15
-
},
16
-
{
17
-
"name": "drv_path",
18
-
"ordinal": 2,
19
-
"type_info": "Text"
20
-
},
21
-
{
22
-
"name": "text",
23
-
"ordinal": 3,
24
-
"type_info": "Text"
25
-
}
26
-
],
27
-
"parameters": {
28
-
"Right": 0
29
-
},
30
-
"nullable": [
31
-
true,
32
-
true,
33
-
true,
34
-
true
35
-
]
36
-
},
37
-
"hash": "794b666df6d03afb34990aac32c093da05e2d267359d2d3c2cbee3c9994e972f"
38
-
}
-38
.sqlx/query-7bb2f27051c89ba91931c129b6b37e3f88ffa1b26248b428c91fa4b367178d50.json
-38
.sqlx/query-7bb2f27051c89ba91931c129b6b37e3f88ffa1b26248b428c91fa4b367178d50.json
···
1
-
{
2
-
"db_name": "SQLite",
3
-
"query": "SELECT\n CAST(COUNT(*) FILTER (WHERE event_type = 108) AS INTEGER) as \"cache_hits!\",\n CAST(COUNT(*) FILTER (WHERE event_type = 105) AS INTEGER) as \"cache_misses!\",\n CAST(COALESCE(SUM(total_bytes), 0) AS INTEGER) as \"total_bytes!\",\n CAST(COALESCE(SUM(duration_ms) FILTER (WHERE event_type IN (101, 108)), 0) AS INTEGER) as \"net_ms!\"\n FROM events",
4
-
"describe": {
5
-
"columns": [
6
-
{
7
-
"name": "cache_hits!",
8
-
"ordinal": 0,
9
-
"type_info": "Int"
10
-
},
11
-
{
12
-
"name": "cache_misses!",
13
-
"ordinal": 1,
14
-
"type_info": "Int"
15
-
},
16
-
{
17
-
"name": "total_bytes!",
18
-
"ordinal": 2,
19
-
"type_info": "Int"
20
-
},
21
-
{
22
-
"name": "net_ms!",
23
-
"ordinal": 3,
24
-
"type_info": "Int"
25
-
}
26
-
],
27
-
"parameters": {
28
-
"Right": 0
29
-
},
30
-
"nullable": [
31
-
false,
32
-
false,
33
-
false,
34
-
false
35
-
]
36
-
},
37
-
"hash": "7bb2f27051c89ba91931c129b6b37e3f88ffa1b26248b428c91fa4b367178d50"
38
-
}
+32
.sqlx/query-8018f90535a4f5b3a4997a6fadab4a8937bf63b32036740aac380656966d5626.json
+32
.sqlx/query-8018f90535a4f5b3a4997a6fadab4a8937bf63b32036740aac380656966d5626.json
···
1
+
{
2
+
"db_name": "SQLite",
3
+
"query": "SELECT duration_ms as \"duration_ms!\", drv_path, text\n FROM events WHERE event_type = 105\n ORDER BY duration_ms DESC LIMIT 10",
4
+
"describe": {
5
+
"columns": [
6
+
{
7
+
"name": "duration_ms!",
8
+
"ordinal": 0,
9
+
"type_info": "Int64"
10
+
},
11
+
{
12
+
"name": "drv_path",
13
+
"ordinal": 1,
14
+
"type_info": "Text"
15
+
},
16
+
{
17
+
"name": "text",
18
+
"ordinal": 2,
19
+
"type_info": "Text"
20
+
}
21
+
],
22
+
"parameters": {
23
+
"Right": 0
24
+
},
25
+
"nullable": [
26
+
true,
27
+
true,
28
+
true
29
+
]
30
+
},
31
+
"hash": "8018f90535a4f5b3a4997a6fadab4a8937bf63b32036740aac380656966d5626"
32
+
}
+2
-2
.sqlx/query-9b40fd391fbe4613357eb865139a8e1e98273fd765c58a0d9f31b6ad38e59e26.json
.sqlx/query-8230b2b702eee1a62a4970000c0f574cc4cca84858bda07ca760ed814b0a3756.json
+2
-2
.sqlx/query-9b40fd391fbe4613357eb865139a8e1e98273fd765c58a0d9f31b6ad38e59e26.json
.sqlx/query-8230b2b702eee1a62a4970000c0f574cc4cca84858bda07ca760ed814b0a3756.json
···
1
1
{
2
2
"db_name": "SQLite",
3
-
"query": "INSERT INTO events (nix_id, parent_id, event_type, text, drv_path, cache_url, start_time, end_time, duration_ms, total_bytes) \n VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)",
3
+
"query": "INSERT INTO events (nix_id, parent_id, event_type, text, drv_path, cache_url, start_time, end_time, duration_ms, total_bytes)\n VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)",
4
4
"describe": {
5
5
"columns": [],
6
6
"parameters": {
···
8
8
},
9
9
"nullable": []
10
10
},
11
-
"hash": "9b40fd391fbe4613357eb865139a8e1e98273fd765c58a0d9f31b6ad38e59e26"
11
+
"hash": "8230b2b702eee1a62a4970000c0f574cc4cca84858bda07ca760ed814b0a3756"
12
12
}
+50
.sqlx/query-c455929cf7c0ef853cba8765ef901dff54d94770c1e36404f096deb72882dfcb.json
+50
.sqlx/query-c455929cf7c0ef853cba8765ef901dff54d94770c1e36404f096deb72882dfcb.json
···
1
+
{
2
+
"db_name": "SQLite",
3
+
"query": "SELECT\n CAST(COUNT(*) FILTER (WHERE event_type = 105) AS INTEGER) as \"build_count!\",\n COALESCE(SUM(duration_ms) FILTER (WHERE event_type = 105), 0) as \"build_total_ms!\",\n CAST(COUNT(*) FILTER (WHERE event_type = 108) AS INTEGER) as \"subst_count!\",\n COALESCE(SUM(duration_ms) FILTER (WHERE event_type = 108), 0) as \"subst_total_ms!\",\n COALESCE(SUM(total_bytes) FILTER (WHERE event_type = 101), 0) as \"download_bytes!\",\n COALESCE(SUM(duration_ms) FILTER (WHERE event_type = 101), 0) as \"download_ms!\"\n FROM events",
4
+
"describe": {
5
+
"columns": [
6
+
{
7
+
"name": "build_count!",
8
+
"ordinal": 0,
9
+
"type_info": "Int"
10
+
},
11
+
{
12
+
"name": "build_total_ms!",
13
+
"ordinal": 1,
14
+
"type_info": "Int"
15
+
},
16
+
{
17
+
"name": "subst_count!",
18
+
"ordinal": 2,
19
+
"type_info": "Int"
20
+
},
21
+
{
22
+
"name": "subst_total_ms!",
23
+
"ordinal": 3,
24
+
"type_info": "Int"
25
+
},
26
+
{
27
+
"name": "download_bytes!",
28
+
"ordinal": 4,
29
+
"type_info": "Int"
30
+
},
31
+
{
32
+
"name": "download_ms!",
33
+
"ordinal": 5,
34
+
"type_info": "Int"
35
+
}
36
+
],
37
+
"parameters": {
38
+
"Right": 0
39
+
},
40
+
"nullable": [
41
+
false,
42
+
false,
43
+
false,
44
+
false,
45
+
false,
46
+
false
47
+
]
48
+
},
49
+
"hash": "c455929cf7c0ef853cba8765ef901dff54d94770c1e36404f096deb72882dfcb"
50
+
}
+3
-17
flake.lock
+3
-17
flake.lock
···
16
16
"type": "github"
17
17
}
18
18
},
19
-
"nixpkgs_2": {
20
-
"locked": {
21
-
"lastModified": 1744536153,
22
-
"narHash": "sha256-awS2zRgF4uTwrOKwwiJcByDzDOdo3Q1rPZbiHQg/N38=",
23
-
"owner": "NixOS",
24
-
"repo": "nixpkgs",
25
-
"rev": "18dd725c29603f582cf1900e0d25f9f1063dbf11",
26
-
"type": "github"
27
-
},
28
-
"original": {
29
-
"owner": "NixOS",
30
-
"ref": "nixpkgs-unstable",
31
-
"repo": "nixpkgs",
32
-
"type": "github"
33
-
}
34
-
},
35
19
"root": {
36
20
"inputs": {
37
21
"nixpkgs": "nixpkgs",
···
40
24
},
41
25
"rust-overlay": {
42
26
"inputs": {
43
-
"nixpkgs": "nixpkgs_2"
27
+
"nixpkgs": [
28
+
"nixpkgs"
29
+
]
44
30
},
45
31
"locked": {
46
32
"lastModified": 1773284828,
+198
-141
src/main.rs
+198
-141
src/main.rs
···
14
14
use tokio::sync::Mutex;
15
15
use tracing::{error, info};
16
16
17
-
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
17
+
#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
18
+
#[serde(from = "u64")]
18
19
#[repr(u64)]
19
20
enum ActivityType {
20
21
Unknown = 0,
21
22
CopyPath = 100,
22
-
FileTransfer = 101,
23
+
FileTransfer = 101, // Actual HTTP download
23
24
Realise = 102,
24
25
CopyPaths = 103,
25
26
Builds = 104,
26
-
Build = 105,
27
+
Build = 105, // Individual derivation build
27
28
OptimiseStore = 106,
28
29
VerifyPaths = 107,
29
-
Substitute = 108,
30
-
QueryPathInfo = 109,
30
+
Substitute = 108, // High-level cache substitution
31
+
QueryPathInfo = 109, // Checking if path exists on cache
31
32
PostBuildHook = 110,
32
33
BuildWaiting = 111,
33
34
FetchTree = 112,
···
60
61
}
61
62
}
62
63
64
+
impl Default for ActivityType {
65
+
fn default() -> Self { Self::Unknown }
66
+
}
67
+
63
68
impl fmt::Display for ActivityType {
64
69
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
65
70
write!(f, "{:?}", self)
66
71
}
67
72
}
68
73
69
-
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
74
+
#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
70
75
#[repr(u64)]
71
76
enum ResultType {
72
77
Unknown = 0,
···
98
103
}
99
104
}
100
105
106
+
impl fmt::Display for ResultType {
107
+
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
108
+
write!(f, "{:?}", self)
109
+
}
110
+
}
111
+
112
+
impl Default for ResultType {
113
+
fn default() -> Self { Self::Unknown }
114
+
}
115
+
101
116
#[derive(Parser)]
102
117
struct Cli {
103
118
#[command(subcommand)]
···
117
132
},
118
133
/// Show statistics from the daemon
119
134
Stats {
135
+
/// Path to the Unix socket
136
+
#[arg(short, long, env = "NOD_SOCKET")]
137
+
socket: Option<PathBuf>,
138
+
},
139
+
/// Clear all data from the database
140
+
Clean {
120
141
/// Path to the Unix socket
121
142
#[arg(short, long, env = "NOD_SOCKET")]
122
143
socket: Option<PathBuf>,
···
127
148
struct NixEvent {
128
149
action: String,
129
150
id: u64,
130
-
#[serde(default)]
131
-
#[serde(rename = "type")]
151
+
// Raw number: ActivityType for "start", ResultType for "result", absent on "stop"
152
+
#[serde(default, rename = "type")]
132
153
event_type: u64,
133
154
#[serde(default)]
134
155
text: String,
···
138
159
parent: u64,
139
160
}
140
161
162
+
// Sent over the socket as JSON - all computed values, no raw types
141
163
#[derive(Debug, Serialize, Deserialize)]
142
164
struct Stats {
143
-
by_type: Vec<TypeStat>,
144
-
cache_hits: i32,
145
-
cache_misses: i32,
146
-
total_bytes: i32,
147
-
net_ms: i32,
148
-
by_phase: Vec<PhaseStat>,
149
-
slowest: Vec<SlowEvent>,
165
+
build_count: i64,
166
+
build_total_ms: i64,
167
+
subst_count: i64,
168
+
subst_total_ms: i64,
169
+
download_bytes: i64,
170
+
download_ms: i64,
171
+
slowest_builds: Vec<SlowBuild>,
172
+
cache_latency: Vec<CacheStat>,
150
173
}
151
174
152
175
#[derive(Debug, Serialize, Deserialize)]
153
-
struct TypeStat {
154
-
event_type: i64, // table column INTEGER -> i64
155
-
count: i32, // CAST(COUNT()) -> i32
156
-
total_ms: Option<i32>, // CAST(SUM()) -> Option<i32>
157
-
avg_ms: f64,
176
+
struct SlowBuild {
177
+
duration_ms: i64,
178
+
drv_path: Option<String>,
179
+
text: Option<String>,
158
180
}
159
181
160
182
#[derive(Debug, Serialize, Deserialize)]
161
-
struct PhaseStat {
162
-
name: String,
163
-
count: i32, // CAST(COUNT()) -> i32
164
-
total_ms: Option<i32>, // CAST(SUM()) -> Option<i32>
183
+
struct CacheStat {
184
+
cache_url: String,
165
185
avg_ms: f64,
166
-
}
167
-
168
-
#[derive(Debug, Serialize, Deserialize)]
169
-
struct SlowEvent {
170
-
duration_ms: i64, // table column INTEGER -> i64
171
-
event_type: i64, // table column INTEGER -> i64
172
-
drv_path: Option<String>,
173
-
text: Option<String>,
186
+
count: i64,
174
187
}
175
188
176
189
struct Activity {
···
181
194
start_time: DateTime<Utc>,
182
195
fields: Vec<serde_json::Value>,
183
196
total_bytes: u64,
184
-
current_phase: Option<(String, DateTime<Utc>)>,
185
197
}
186
198
187
199
struct State {
···
267
279
let stats: Stats = serde_json::from_str(&line).context("Invalid response from daemon")?;
268
280
display_stats(stats);
269
281
}
282
+
Commands::Clean { socket } => {
283
+
let socket_path = socket.unwrap_or_else(|| {
284
+
project_dirs.as_ref()
285
+
.and_then(|d| d.runtime_dir())
286
+
.map(|d| d.join("nod.sock"))
287
+
.unwrap_or_else(|| PathBuf::from("/tmp/nod.sock"))
288
+
});
289
+
290
+
let mut stream = UnixStream::connect(&socket_path)
291
+
.await
292
+
.with_context(|| format!("Failed to connect to daemon at {}", socket_path.display()))?;
293
+
294
+
stream.write_all(b"clean\n").await?;
295
+
296
+
let mut reader = BufReader::new(stream);
297
+
let mut line = String::new();
298
+
reader.read_line(&mut line).await.context("Daemon closed connection")?;
299
+
300
+
if line.trim() == "ok" {
301
+
info!("Database cleared successfully.");
302
+
} else {
303
+
error!("Daemon failed to clear database.");
304
+
}
305
+
}
270
306
}
271
307
272
308
Ok(())
···
304
340
loop {
305
341
line.clear();
306
342
if reader.read_line(&mut line).await? == 0 { break; }
307
-
if line.trim() == "get_stats" {
343
+
let cmd = line.trim();
344
+
345
+
if cmd == "get_stats" {
308
346
let pool = state.lock().await.pool.clone();
309
347
let stats = collect_stats(pool).await?;
310
348
writer.write_all((serde_json::to_string(&stats)? + "\n").as_bytes()).await?;
311
349
break;
312
350
}
351
+
if cmd == "clean" {
352
+
let pool = state.lock().await.pool.clone();
353
+
sqlx::query("DELETE FROM phases").execute(&pool).await?;
354
+
sqlx::query("DELETE FROM events").execute(&pool).await?;
355
+
sqlx::query("VACUUM").execute(&pool).await?;
356
+
writer.write_all(b"ok\n").await?;
357
+
info!("Database cleared via socket command");
358
+
break;
359
+
}
360
+
313
361
if let Ok(event) = serde_json::from_str::<NixEvent>(&line) {
314
362
process_event(event, &state).await?;
315
363
}
···
323
371
match event.action.as_str() {
324
372
"start" => {
325
373
let act_type = ActivityType::from(event.event_type);
326
-
let mut text = event.text;
327
-
328
-
// Nix typically puts the relevant path in fields[0] for builds/substitutions
329
-
if let Some(path) = event.fields.get(0).and_then(|v| v.as_str()) {
330
-
text = path.to_string();
331
-
}
374
+
let text = if !event.text.is_empty() {
375
+
event.text.clone()
376
+
} else {
377
+
event.fields.get(0).and_then(|v| v.as_str()).unwrap_or("").to_string()
378
+
};
379
+
380
+
info!(
381
+
id = event.id,
382
+
parent = event.parent,
383
+
act_type = %act_type,
384
+
text = %text,
385
+
fields = ?event.fields,
386
+
"start"
387
+
);
332
388
333
-
info!(id = event.id, %act_type, "Start: {}", text);
334
389
s.active_activities.insert(event.id, Activity {
335
390
id: event.id,
336
391
parent_id: event.parent,
···
339
394
start_time: Utc::now(),
340
395
fields: event.fields,
341
396
total_bytes: 0,
342
-
current_phase: None,
343
397
});
344
398
}
345
399
"result" => {
346
400
let res_type = ResultType::from(event.event_type);
347
-
let pool = s.pool.clone();
401
+
402
+
info!(
403
+
id = event.id,
404
+
res_type = %res_type,
405
+
fields = ?event.fields,
406
+
"result"
407
+
);
348
408
349
409
if let Some(act) = s.active_activities.get_mut(&event.id) {
350
410
match res_type {
351
-
ResultType::SetPhase => {
352
-
let phase_name = event.fields.get(0).and_then(|v| v.as_str()).unwrap_or("unknown");
353
-
let now = Utc::now();
354
-
if let Some((name, start)) = act.current_phase.take() {
355
-
let duration = now.signed_duration_since(start).num_milliseconds();
356
-
let nid = act.id as i64;
357
-
tokio::spawn(async move {
358
-
let _ = sqlx::query!(
359
-
"INSERT INTO phases (event_nix_id, phase_name, duration_ms) VALUES (?, ?, ?)",
360
-
nid,
361
-
name,
362
-
duration
363
-
)
364
-
.execute(&pool)
365
-
.await;
366
-
});
367
-
}
368
-
act.current_phase = Some((phase_name.to_string(), now));
369
-
}
370
411
ResultType::Progress => {
371
412
if let Some(total) = event.fields.get(1).and_then(|v| v.as_u64()) {
372
-
act.total_bytes = total;
413
+
if total > 0 { act.total_bytes = total; }
373
414
}
374
415
}
375
416
_ => {}
···
378
419
}
379
420
"stop" => {
380
421
if let Some(act) = s.active_activities.remove(&event.id) {
422
+
let act_type = ActivityType::from(act.event_type);
381
423
let end_time = Utc::now();
382
424
let duration = end_time.signed_duration_since(act.start_time).num_milliseconds();
383
-
let act_type = ActivityType::from(act.event_type);
425
+
426
+
info!(
427
+
id = act.id,
428
+
act_type = %act_type,
429
+
duration_ms = duration,
430
+
total_bytes = act.total_bytes,
431
+
text = %act.text,
432
+
fields = ?act.fields,
433
+
"stop"
434
+
);
384
435
385
436
let drv_path = act.fields.get(0).and_then(|v| v.as_str()).map(|s| s.to_string());
386
-
let mut cache_url = None;
387
-
if act_type == ActivityType::Substitute {
388
-
cache_url = act.fields.get(1).and_then(|v| v.as_str()).map(|s| s.to_string());
389
-
}
437
+
let cache_url = if act_type == ActivityType::QueryPathInfo {
438
+
act.fields.get(1).and_then(|v| v.as_str()).map(|s| s.to_string())
439
+
} else {
440
+
None
441
+
};
390
442
391
-
let nid = act.id as i64;
392
-
let pid = act.parent_id as i64;
393
-
let ety = act.event_type as i64;
394
-
let start_time = act.start_time.to_rfc3339();
443
+
let nix_id = act.id as i64;
444
+
let parent_id = act.parent_id as i64;
445
+
let event_type_i64 = act.event_type as i64;
446
+
let start_time_str = act.start_time.to_rfc3339();
395
447
let end_time_str = end_time.to_rfc3339();
396
-
let total_bytes = act.total_bytes as i64;
448
+
let total_bytes_i64 = act.total_bytes as i64;
397
449
398
450
sqlx::query!(
399
-
"INSERT INTO events (nix_id, parent_id, event_type, text, drv_path, cache_url, start_time, end_time, duration_ms, total_bytes)
451
+
"INSERT INTO events (nix_id, parent_id, event_type, text, drv_path, cache_url, start_time, end_time, duration_ms, total_bytes)
400
452
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)",
401
-
nid, pid, ety, act.text, drv_path, cache_url, start_time, end_time_str, duration, total_bytes
453
+
nix_id, parent_id, event_type_i64, act.text, drv_path, cache_url,
454
+
start_time_str, end_time_str, duration, total_bytes_i64
402
455
)
403
456
.execute(&s.pool)
404
457
.await?;
405
458
}
406
459
}
407
-
_ => {}
460
+
_ => {
461
+
info!(action = %event.action, id = event.id, "unknown action");
462
+
}
408
463
}
409
464
Ok(())
410
465
}
411
466
412
467
async fn collect_stats(pool: Pool<Sqlite>) -> Result<Stats> {
413
-
let by_type = sqlx::query_as!(
414
-
TypeStat,
415
-
"SELECT event_type as \"event_type!\", CAST(COUNT(*) AS INTEGER) as \"count!\", CAST(SUM(duration_ms) AS INTEGER) as \"total_ms\", CAST(AVG(duration_ms) AS REAL) as \"avg_ms!\"
416
-
FROM events GROUP BY event_type ORDER BY total_ms DESC"
417
-
).fetch_all(&pool).await?;
418
-
419
-
let io = sqlx::query!(
468
+
// Single pass over events for the three summary counters.
469
+
// CAST(COUNT FILTER) returns i32, COALESCE(SUM, 0) returns i32 in sqlx SQLite.
470
+
let summary = sqlx::query!(
420
471
"SELECT
421
-
CAST(COUNT(*) FILTER (WHERE event_type = 108) AS INTEGER) as \"cache_hits!\",
422
-
CAST(COUNT(*) FILTER (WHERE event_type = 105) AS INTEGER) as \"cache_misses!\",
423
-
CAST(COALESCE(SUM(total_bytes), 0) AS INTEGER) as \"total_bytes!\",
424
-
CAST(COALESCE(SUM(duration_ms) FILTER (WHERE event_type IN (101, 108)), 0) AS INTEGER) as \"net_ms!\"
472
+
CAST(COUNT(*) FILTER (WHERE event_type = 105) AS INTEGER) as \"build_count!\",
473
+
COALESCE(SUM(duration_ms) FILTER (WHERE event_type = 105), 0) as \"build_total_ms!\",
474
+
CAST(COUNT(*) FILTER (WHERE event_type = 108) AS INTEGER) as \"subst_count!\",
475
+
COALESCE(SUM(duration_ms) FILTER (WHERE event_type = 108), 0) as \"subst_total_ms!\",
476
+
COALESCE(SUM(total_bytes) FILTER (WHERE event_type = 101), 0) as \"download_bytes!\",
477
+
COALESCE(SUM(duration_ms) FILTER (WHERE event_type = 101), 0) as \"download_ms!\"
425
478
FROM events"
426
479
).fetch_one(&pool).await?;
427
480
428
-
let by_phase = sqlx::query_as!(
429
-
PhaseStat,
430
-
"SELECT phase_name as \"name!\", CAST(COUNT(*) AS INTEGER) as \"count!\", CAST(SUM(duration_ms) AS INTEGER) as \"total_ms\", CAST(AVG(duration_ms) AS REAL) as \"avg_ms!\"
431
-
FROM phases GROUP BY phase_name ORDER BY total_ms DESC LIMIT 8"
481
+
// Top 10 slowest local builds.
482
+
let slowest_builds = sqlx::query_as!(
483
+
SlowBuild,
484
+
"SELECT duration_ms as \"duration_ms!\", drv_path, text
485
+
FROM events WHERE event_type = 105
486
+
ORDER BY duration_ms DESC LIMIT 10"
432
487
).fetch_all(&pool).await?;
433
488
434
-
let slowest = sqlx::query_as!(
435
-
SlowEvent,
436
-
"SELECT duration_ms as \"duration_ms!\", event_type as \"event_type!\", drv_path, text
437
-
FROM events
438
-
WHERE event_type IN (105, 108, 102, 112)
439
-
ORDER BY duration_ms DESC LIMIT 10"
489
+
// Per-cache average query latency (QueryPathInfo = 109 stores cache_url).
490
+
let cache_latency = sqlx::query_as!(
491
+
CacheStat,
492
+
"SELECT cache_url as \"cache_url!\", CAST(AVG(duration_ms) AS REAL) as \"avg_ms!\", CAST(COUNT(*) AS INTEGER) as \"count!\"
493
+
FROM events WHERE cache_url IS NOT NULL
494
+
GROUP BY cache_url ORDER BY 2 DESC"
440
495
).fetch_all(&pool).await?;
441
496
442
497
Ok(Stats {
443
-
by_type,
444
-
cache_hits: io.cache_hits,
445
-
cache_misses: io.cache_misses,
446
-
total_bytes: io.total_bytes,
447
-
net_ms: io.net_ms,
448
-
by_phase,
449
-
slowest,
498
+
build_count: summary.build_count as i64,
499
+
build_total_ms: summary.build_total_ms as i64,
500
+
subst_count: summary.subst_count as i64,
501
+
subst_total_ms: summary.subst_total_ms as i64,
502
+
download_bytes: summary.download_bytes as i64,
503
+
download_ms: summary.download_ms as i64,
504
+
slowest_builds,
505
+
cache_latency,
450
506
})
451
507
}
452
508
453
-
fn display_stats(stats: Stats) {
454
-
println!("\n{:<22} {:>8} {:>12} {:>12}", "ACTIVITY TYPE", "COUNT", "AVG TIME", "TOTAL TIME");
455
-
println!("{}", "-".repeat(57));
456
-
for row in stats.by_type {
457
-
let label = format!("{:?}", ActivityType::from(row.event_type));
458
-
let total_s = row.total_ms.unwrap_or(0) as f64 / 1000.0;
459
-
println!("{:<22} {:>8} {:>11.2}s {:>11.2}s", label, row.count, row.avg_ms / 1000.0, total_s);
509
+
fn fmt_ms(ms: i64) -> String {
510
+
if ms < 1000 {
511
+
format!("{}ms", ms)
512
+
} else if ms < 60_000 {
513
+
format!("{:.1}s", ms as f64 / 1000.0)
514
+
} else {
515
+
format!("{}m{:.1}s", ms / 60_000, (ms % 60_000) as f64 / 1000.0)
460
516
}
517
+
}
461
518
462
-
let total_io = stats.cache_hits + stats.cache_misses;
463
-
let hit_rate = if total_io > 0 { stats.cache_hits as f64 / total_io as f64 * 100.0 } else { 0.0 };
464
-
let mb = stats.total_bytes as f64 / 1024.0 / 1024.0;
465
-
let speed = if stats.net_ms > 0 { mb / (stats.net_ms as f64 / 1000.0) } else { 0.0 };
466
-
println!("\n--- PERFORMANCE ---");
467
-
println!("{:<18} {:>10.1}%", "Cache Hit Rate:", hit_rate);
468
-
println!("{:<18} {:>10.2} MB", "Total Data:", mb);
469
-
println!("{:<18} {:>10.2} MB/s", "Avg Net Speed:", speed);
519
+
// Strip /nix/store/<hash>- prefix to get the human-readable package name.
520
+
fn drv_name(path: &str) -> &str {
521
+
let s = path.strip_prefix("/nix/store/").unwrap_or(path);
522
+
// hash is 32 hex chars followed by '-'
523
+
if s.len() > 33 && s.chars().take(32).all(|c| c.is_ascii_hexdigit()) && s.as_bytes()[32] == b'-' {
524
+
&s[33..]
525
+
} else {
526
+
s
527
+
}
528
+
}
470
529
471
-
if !stats.by_phase.is_empty() {
472
-
println!("\n{:<22} {:>8} {:>12} {:>12}", "BUILD PHASE", "COUNT", "AVG TIME", "TOTAL TIME");
473
-
println!("{}", "-".repeat(57));
474
-
for row in stats.by_phase {
475
-
let total_s = row.total_ms.unwrap_or(0) as f64 / 1000.0;
476
-
println!("{:<22} {:>8} {:>11.2}s {:>11.2}s", row.name, row.count, row.avg_ms / 1000.0, total_s);
530
+
fn display_stats(stats: Stats) {
531
+
let build_avg = if stats.build_count > 0 { stats.build_total_ms / stats.build_count } else { 0 };
532
+
let subst_avg = if stats.subst_count > 0 { stats.subst_total_ms / stats.subst_count } else { 0 };
533
+
let mb = stats.download_bytes as f64 / 1_048_576.0;
534
+
let dl_speed = if stats.download_ms > 0 { mb / (stats.download_ms as f64 / 1000.0) } else { 0.0 };
535
+
536
+
println!("{:<14} {:>6} total {:>9} avg {:>9}", "built", stats.build_count, fmt_ms(stats.build_total_ms), fmt_ms(build_avg));
537
+
println!("{:<14} {:>6} total {:>9} avg {:>9}", "substituted", stats.subst_count, fmt_ms(stats.subst_total_ms), fmt_ms(subst_avg));
538
+
println!("{:<14} {:>8.1} MB avg {:>6.1} MB/s", "downloaded", mb, dl_speed);
539
+
540
+
if !stats.slowest_builds.is_empty() {
541
+
println!();
542
+
for row in &stats.slowest_builds {
543
+
let path = row.drv_path.as_deref().or(row.text.as_deref()).unwrap_or("?");
544
+
println!("{:>9} {}", fmt_ms(row.duration_ms), drv_name(path));
477
545
}
478
546
}
479
547
480
-
if !stats.slowest.is_empty() {
481
-
println!("\n{:<12} {:<10} {}", "DURATION", "TYPE", "DERIVATION / TASK");
482
-
println!("{}", "-".repeat(57));
483
-
for row in stats.slowest {
484
-
let label = match row.event_type {
485
-
105 => "Build",
486
-
108 => "Subst",
487
-
112 => "Fetch",
488
-
102 => "Realise",
489
-
_ => "Other",
490
-
};
491
-
let path = row.drv_path.or(row.text).unwrap_or_default();
492
-
let name = path.strip_prefix("/nix/store/").unwrap_or(&path);
493
-
println!("{:>10.2}s {:<10} {}", row.duration_ms as f64 / 1000.0, label, name);
548
+
if !stats.cache_latency.is_empty() {
549
+
let url_w = stats.cache_latency.iter().map(|r| r.cache_url.len()).max().unwrap_or(0);
550
+
println!();
551
+
for row in &stats.cache_latency {
552
+
println!("{:<width$} avg {:>7} {:>6} queries", row.cache_url, fmt_ms(row.avg_ms as i64), row.count, width = url_w);
494
553
}
495
554
}
496
-
497
-
println!();
498
555
}