1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
|
#!/usr/bin/env python3
"""Parse hub perf log to extract hydration / spawn / deprovision timings."""
from __future__ import annotations
import re
import statistics
import sys
from pathlib import Path
HYDRATE_RE = re.compile(r"Hydration complete module '([^']+)': (\d+) files \(([^)]+)\) in ([\d.]+)(ms|s)")
SPAWN_RE = re.compile(r"module '([^']+)' started, listening on port \d+, spawn took ([\d.]+)(ms|s)")
PROVISION_START_RE = re.compile(r"\[(\d{2}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3})\] \[inf\] Provisioning storage server instance for module '([^']+)'")
SPAWN_DONE_RE = re.compile(r"\[(\d{2}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3})\] \[inf\] Storage server instance for module '([^']+)' started")
HYDRATE_DONE_RE = re.compile(r"\[(\d{2}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3})\] \[inf\] Hydration complete module '([^']+)'")
DEPROV_START_RE = re.compile(r"\[(\d{2}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3})\] \[inf\] Module '([^']+)' changed state from provisioned to deprovisioning")
DEPROV_REMOVE_RE = re.compile(r"\[(\d{2}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3})\] \[inf\] Module '([^']+)' (?:removed|changed state from deprovisioning to unprovisioned)")
def to_ms(num: str, unit: str) -> float:
v = float(num)
return v * 1000.0 if unit == "s" else v
def parse_ts(ts: str) -> float:
# 26-04-29 22:41:34.009 -> seconds since arbitrary epoch (use day-of-year * 86400 + h*3600 + m*60 + s)
import datetime
dt = datetime.datetime.strptime(ts, "%y-%m-%d %H:%M:%S.%f")
return dt.timestamp()
def stats(name: str, vals: list[float]) -> str:
if not vals:
return f"{name:14s} n=0"
vs = sorted(vals)
n = len(vs)
p50 = vs[n // 2]
p95 = vs[min(n - 1, int(n * 0.95))]
p99 = vs[min(n - 1, int(n * 0.99))]
return (f"{name:14s} n={n:5d} mean={statistics.mean(vs):8.0f}ms "
f"p50={p50:7.0f}ms p95={p95:7.0f}ms p99={p99:7.0f}ms max={max(vs):7.0f}ms "
f"sum={sum(vs)/1000.0:7.1f}s")
def analyse(log_path: Path) -> None:
print(f"=== {log_path}")
hydrate_durations: list[float] = []
spawn_durations: list[float] = []
prov_start: dict[str, float] = {}
hydrate_done: dict[str, float] = {}
spawn_done: dict[str, float] = {}
deprov_start: dict[str, float] = {}
deprov_done: dict[str, float] = {}
with log_path.open("r", encoding="utf-8", errors="replace") as f:
for line in f:
m = HYDRATE_RE.search(line)
if m:
hydrate_durations.append(to_ms(m.group(4), m.group(5)))
m = SPAWN_RE.search(line)
if m:
spawn_durations.append(to_ms(m.group(2), m.group(3)))
m = PROVISION_START_RE.search(line)
if m:
prov_start[m.group(2)] = parse_ts(m.group(1))
continue
m = HYDRATE_DONE_RE.search(line)
if m:
hydrate_done[m.group(2)] = parse_ts(m.group(1))
continue
m = SPAWN_DONE_RE.search(line)
if m:
spawn_done[m.group(2)] = parse_ts(m.group(1))
continue
m = DEPROV_START_RE.search(line)
if m:
deprov_start[m.group(2)] = parse_ts(m.group(1))
continue
m = DEPROV_REMOVE_RE.search(line)
if m:
deprov_done[m.group(2)] = parse_ts(m.group(1))
continue
# Reconstruct end-to-end provision wall time per module:
e2e_prov_ms: list[float] = []
queue_to_hydrate_ms: list[float] = [] # time in DataPool queue before hydrate begun (proxy: prov_start->hydrate_done minus hydrate ms)
spawn_minus_data_ms: list[float] = [] # time between hydrate_done and spawn_done (lifetime + lifetime queue)
for mid, t0 in prov_start.items():
t_end = spawn_done.get(mid)
if t_end is None:
continue
e2e_prov_ms.append((t_end - t0) * 1000.0)
t_h = hydrate_done.get(mid)
if t_h is not None:
spawn_minus_data_ms.append((t_end - t_h) * 1000.0)
e2e_deprov_ms: list[float] = []
for mid, t0 in deprov_start.items():
t_end = deprov_done.get(mid)
if t_end is None:
continue
e2e_deprov_ms.append((t_end - t0) * 1000.0)
print(stats("hydrate_dur", hydrate_durations))
print(stats("spawn_dur", spawn_durations))
print(stats("e2e_prov", e2e_prov_ms))
print(stats("after_hydrate", spawn_minus_data_ms))
print(stats("e2e_deprov", e2e_deprov_ms))
if hydrate_durations and spawn_durations:
h_sum = sum(hydrate_durations) / 1000.0
s_sum = sum(spawn_durations) / 1000.0
print(f" total hydrate work: {h_sum:.1f}s, total spawn work: {s_sum:.1f}s, ratio H/S: {h_sum/s_sum:.2f}")
print()
if __name__ == "__main__":
for arg in sys.argv[1:]:
analyse(Path(arg))
|