observe: findings as critical-path zeroing + Amdahl ceiling · gazagnaire.org/ocaml-observe@358624d

+108 -82

2 changed files

Expand all

lib

obs

memtrace_eio.ml

test

obs_eio

test_memtrace_eio.ml

+56 -55

lib/obs/memtrace_eio.ml

View file

··· 263 263 (* (process, fiber) -> block label -> blocked secs: what each fiber spent 264 264 its suspended time waiting on (reason, with the active span when 265 265 known) *) 266 - fiber_block_in_span : (int * int, float) Hashtbl.t; 267 - (* (process, fiber) -> blocked secs that elapsed inside a traced span: 268 - when this is most of a fiber's blocked time, its wait is already 269 - accounted for in the span hotspots, so the waiting-fiber finding is 270 - redundant *) 271 266 mutable suspend_open : 272 267 (int 273 268 * int ··· 345 340 suspend_total = Hashtbl.create 32; 346 341 suspend_where = Hashtbl.create 32; 347 342 fiber_block = Hashtbl.create 64; 348 - fiber_block_in_span = Hashtbl.create 64; 349 343 suspend_open = []; 350 344 lost = 0; 351 345 n_events = 0; ··· 683 677 (match fiber with 684 678 | Some f -> 685 679 bump2 t.fiber_block (process, f) (block_label reason span) dt; 686 - if span <> None then bump t.fiber_block_in_span (process, f) dt; 687 680 let waker = resolve_waker t ~process ~since ~now:ts_ns ~obj_id in 688 681 push_seg t ~process f 689 682 { s_start = since; s_end = ts_ns; kind = Block { reason; waker } } ··· 1087 1080 | _ -> acc) 1088 1081 t.fibers None 1089 1082 1090 - (* 4. a non-root fiber that spends almost all its life suspended. The fiber's 1091 - own spans name where it runs and its dominant block label names what it 1092 - waits on, so the finding points at a real location instead of a generic 1093 - "check its dependency". *) 1094 - (* The fraction of a fiber's charged block time that elapsed inside a traced 1095 - span. When most of it did, the wait already shows up in the span hotspots, 1096 - so flagging the fiber would just restate that lower-ranked evidence. *) 1097 - let span_explained_block t id = 1098 - let total = 1099 - match Hashtbl.find_opt t.fiber_block id with 1100 - | Some h -> Hashtbl.fold (fun _ v a -> a +. v) h 0. 1101 - | None -> 0. 1102 - in 1103 - let in_span = 1104 - Option.value (Hashtbl.find_opt t.fiber_block_in_span id) ~default:0. 1105 - in 1106 - total > 0. && in_span /. total >= 0.5 1107 - 1108 - let detect_waiting_fiber ~add ~dur_s t ~n_fibers = 1083 + (* 4. a non-root fiber that spends almost all its life suspended AND is on the 1084 + critical path -- it (in part) IS the bottleneck. Its reclaimable payoff is 1085 + the wall it holds on the path (critical-path zeroing), not its whole idle 1086 + life: a fiber parked off the path has slack and optimizing it returns 1087 + nothing (the "non-bottleneck is a mirage" rule), so it is not flagged. *) 1088 + let detect_waiting_fiber ~add ~dur_s t ~n_fibers ~on_path_wait = 1109 1089 let is_root = root_predicate t ~n_fibers in 1110 1090 match most_suspended_fiber t ~is_root with 1111 - | Some (key, (f : fiber_acc), suspended) 1112 - when not (span_explained_block t key) -> 1113 - let id = snd key in 1114 - let name = Option.value f.name ~default:(string_of_int id) in 1115 - let runs_in = 1116 - match argmax f.span_time with 1117 - | Some s -> Fmt.str " (runs in %s)" s 1118 - | None -> "" 1119 - in 1120 - let blocked_on = 1121 - match Option.bind (Hashtbl.find_opt t.fiber_block key) argmax with 1122 - | Some label -> label 1123 - | None -> "its dependency" 1124 - in 1125 - add "fiber" 1126 - ~diagnosis: 1127 - (Fmt.str "fiber %s%s is almost always waiting, not running" name 1128 - runs_in) 1129 - ~evidence: 1130 - (Fmt.str "%s suspended (mostly on %s) vs %s running" 1131 - (dur_s suspended) blocked_on (dur_s f.run_time)) 1132 - ~fix:(Fmt.str "check whether %s is the real bottleneck" blocked_on) 1133 - ~payoff:suspended ~certainty:Report.Estimate 1134 - | _ -> () 1091 + | Some (key, (f : fiber_acc), suspended) -> ( 1092 + match Hashtbl.find_opt on_path_wait key with 1093 + | Some on_path when on_path > 0. -> 1094 + let id = snd key in 1095 + let name = Option.value f.name ~default:(string_of_int id) in 1096 + let runs_in = 1097 + match argmax f.span_time with 1098 + | Some s -> Fmt.str " (runs in %s)" s 1099 + | None -> "" 1100 + in 1101 + let blocked_on = 1102 + match Option.bind (Hashtbl.find_opt t.fiber_block key) argmax with 1103 + | Some label -> label 1104 + | None -> "its dependency" 1105 + in 1106 + add "fiber" 1107 + ~diagnosis: 1108 + (Fmt.str "fiber %s%s is on the critical path, mostly waiting" 1109 + name runs_in) 1110 + ~evidence: 1111 + (Fmt.str 1112 + "%s on the path (of %s suspended); blocked mostly on %s" 1113 + (dur_s on_path) (dur_s suspended) blocked_on) 1114 + ~fix:(Fmt.str "this wait bounds the run -- shorten %s" blocked_on) 1115 + ~payoff:on_path ~certainty:Report.Estimate 1116 + | _ -> ()) 1117 + | None -> () 1135 1118 1136 1119 (* 5. GC-tail latency: a long stop-the-world straggler. *) 1137 1120 let detect_gc_tail ~add ~frac ~dur_s t = ··· 1329 1312 t.segments [] 1330 1313 in 1331 1314 match all with 1332 - | [] -> ([], Hashtbl.create 1) 1315 + | [] -> ([], Hashtbl.create 1, Hashtbl.create 1) 1333 1316 | _ -> 1334 1317 let by_fiber = segments_by_fiber t in 1335 1318 let last = ··· 1342 1325 in 1343 1326 let path = cp_walk by_fiber ~last ~bound:(List.length all) in 1344 1327 let on_path_secs = Hashtbl.create 64 in 1328 + let on_path_wait = Hashtbl.create 64 in 1345 1329 List.iter 1346 - (fun (proc, fid, seg) -> bump on_path_secs (proc, fid) (seg_dur seg)) 1330 + (fun (proc, fid, (seg : seg)) -> 1331 + bump on_path_secs (proc, fid) (seg_dur seg); 1332 + match seg.kind with 1333 + | Block { waker = External; _ } -> 1334 + bump on_path_wait (proc, fid) (seg_dur seg) 1335 + | _ -> ()) 1347 1336 path; 1348 - (cp_buckets path, on_path_secs) 1337 + (cp_buckets path, on_path_secs, on_path_wait) 1349 1338 1350 1339 (* A finding below [min_frac] of wall is not worth acting on (the "stop when 1351 1340 the payoff is trivial" rule), so it is dropped before ranking. *) 1352 1341 let report ?(min_frac = 0.1) t : Report.t = 1353 1342 let now_ns = t.mono_last in 1354 1343 flush_open_state t ~now_ns; 1355 - let critical_path, on_path_secs = compute_critical_path t in 1344 + let critical_path, on_path_secs, on_path_wait = compute_critical_path t in 1356 1345 let trace_duration = trace_duration_of t in 1357 1346 let wall_time = 1358 1347 if t.wall_stop > t.wall_start then t.wall_stop -. t.wall_start ··· 1524 1513 detect_wait ~add ~frac ~dur_s t ~waiting ~waiting_by_cause; 1525 1514 detect_contention ~add ~dur_s ~pct_s contention; 1526 1515 detect_gc ~add ~dur_s ~pct_s t ~gc_time ~promoted_frac; 1527 - detect_waiting_fiber ~add ~dur_s t ~n_fibers; 1516 + detect_waiting_fiber ~add ~dur_s t ~n_fibers ~on_path_wait; 1528 1517 detect_gc_tail ~add ~frac ~dur_s t; 1529 1518 detect_hot_span ~add ~dur_s ~frac ~waiting ~gc_frac spans; 1530 1519 let findings = ··· 1799 1788 (pct0 f.payoff_frac) 1800 1789 (certainty_tag f.certainty)) 1801 1790 r.findings; 1791 + (* The Amdahl ceiling: no fix returns more wall than the critical path; work 1792 + off it has slack. *) 1793 + (if r.critical_path <> [] && r.wall_time > 0. then 1794 + let cp = 1795 + List.fold_left 1796 + (fun a (c : Report.cp_seg) -> a +. c.seconds) 1797 + 0. r.critical_path 1798 + in 1799 + line 1800 + "ceiling: at most %s (%s of wall) is reclaimable -- the critical path" 1801 + (dur cp) 1802 + (pct0 (cp /. r.wall_time))); 1802 1803 Buffer.add_char b '\n' 1803 1804 1804 1805 let cp_kind_tag = function

+52 -27

test/obs_eio/test_memtrace_eio.ml

View file

··· 726 726 "evidence names block cause" true (contains f.evidence "db"); 727 727 Alcotest.(check bool) "fix names block cause" true (contains f.fix "db") 728 728 729 - (* When a fiber spends its blocked time inside a traced span, the wait is already 730 - visible in the span hotspots, so the redundant waiting-fiber finding is 731 - suppressed. Fiber 2 blocks on "net" entirely inside "io.read". *) 732 - let test_waiting_fiber_span_suppressed () = 729 + (* A fiber that is mostly idle but OFF the critical path has slack and is not the 730 + bottleneck, so it is not flagged (the "optimizing a non-bottleneck is a 731 + mirage" rule). Fiber 1 runs continuously 0..100ms on ring 0 -- that is the 732 + critical path. Fiber 2 on ring 1 is suspended 96 of its 98ms, but its wait 733 + ends at 98ms with nothing downstream depending on it, so it is off the path. *) 734 + let test_waiting_fiber_off_path_not_flagged () = 733 735 let m = M.v () in 734 736 M.set_wall_clock m ~start:0. ~stop:0.1; 735 - M.eio_event m ~ring:0 ~ts_ns:(ms 0.) (`Create (2, `Fiber_in 0)); 736 - M.eio_event m ~ring:0 ~ts_ns:(ms 0.) (`Fiber 2); 737 - M.eio_event m ~ring:0 ~ts_ns:(ms 0.) (`Enter_span "io.read"); 738 - M.eio_event m ~ring:0 ~ts_ns:(ms 1.) (`Suspend_fiber "net"); 739 - M.eio_event m ~ring:0 ~ts_ns:(ms 90.) (`Fiber 2); 740 - M.eio_event m ~ring:0 ~ts_ns:(ms 90.) `Exit_span; 741 - M.eio_event m ~ring:0 ~ts_ns:(ms 100.) (`Exit_fiber 2); 737 + M.eio_event m ~ring:0 ~ts_ns:(ms 0.) (`Create (1, `Fiber_in 0)); 738 + M.eio_event m ~ring:0 ~ts_ns:(ms 0.) (`Fiber 1); 739 + M.eio_event m ~ring:0 ~ts_ns:(ms 100.) (`Exit_fiber 1); 740 + M.eio_event m ~ring:1 ~ts_ns:(ms 1.) (`Create (2, `Fiber_in 0)); 741 + M.eio_event m ~ring:1 ~ts_ns:(ms 1.) (`Fiber 2); 742 + M.eio_event m ~ring:1 ~ts_ns:(ms 2.) (`Suspend_fiber "idle"); 743 + M.eio_event m ~ring:1 ~ts_ns:(ms 98.) (`Fiber 2); 744 + M.eio_event m ~ring:1 ~ts_ns:(ms 99.) (`Exit_fiber 2); 742 745 let r = M.report m in 743 746 let fiber_findings = 744 747 List.filter (fun (f : Rep.finding) -> f.kind = "fiber") r.findings 745 748 in 746 749 Alcotest.(check int) 747 - "span-explained wait suppressed" 0 748 - (List.length fiber_findings) 750 + "off-path idle fiber not flagged" 0 751 + (List.length fiber_findings); 752 + let f2 = List.find (fun (f : Rep.fiber) -> f.id = 2) r.fibers in 753 + Alcotest.(check bool) "fiber 2 off the critical path" false f2.on_path; 754 + Alcotest.(check bool) "fiber 2 has slack" true (f2.slack > 0.) 749 755 750 756 (* A sleep-dominated wait is named by its span and gets a polling-loop fix, not 751 757 the generic "batch the blocking calls" advice. Fiber 1 sleeps 799ms inside ··· 927 933 Fa.feed_string m data; 928 934 M.report m 929 935 936 + (* The cross-domain critical-path scenario driven through the fxt writer: fiber 1 937 + (ring 0) runs 2ms then Puts promise 7; fiber 2 (ring 1) awaited 7 and runs 8ms 938 + once woken. The waker edge (`Put`) and the per-(process,ring) segments must 939 + survive the .fxt round-trip for the recovered critical path to be 2ms+8ms. *) 940 + let build_cp_cross s = 941 + let at ?(ring = 0) ts e = Fa.Sink.eio_event s ~ring ~ts_ns:(ms ts) e in 942 + at 0. (`Create (7, `Obj Promise)); 943 + at 0. (`Fiber 1); 944 + at 2. (`Put 7); 945 + at 2. (`Exit_fiber 1); 946 + at ~ring:1 0. (`Fiber 2); 947 + at ~ring:1 0. (`Try_get 7); 948 + at ~ring:1 0. (`Suspend_fiber "await"); 949 + at ~ring:1 2. (`Fiber 2); 950 + at ~ring:1 10. (`Exit_fiber 2) 951 + 952 + let test_fxt_cp_roundtrip () = 953 + let r = fxt_roundtrip build_cp_cross in 954 + (match cp_find r "0:fiber 1" with 955 + | Some c -> close ~eps:1e-6 "fiber 1 on path through fxt" c.seconds 0.002 956 + | None -> Alcotest.fail "fiber 1 missing from the critical path after fxt"); 957 + (match cp_find r "0:fiber 2" with 958 + | Some c -> close ~eps:1e-6 "fiber 2 on path through fxt" c.seconds 0.008 959 + | None -> Alcotest.fail "fiber 2 missing from the critical path after fxt"); 960 + close ~eps:1e-6 "critical path total through fxt" (cp_total r) 0.010 961 + 930 962 (* One scenario fused into a 1s monotonic timeline (offline has no wall clock, 931 963 so wall_time = trace_duration = 1.0s): - 3 create-fiber: root (cc:Root), 932 964 worker (cc:Switch), and one idle fiber. - a named Mutex "db_lock": 20 ··· 1014 1046 Alcotest.(check bool) 1015 1047 "contention names db_lock" true 1016 1048 (contains cf.Rep.diagnosis "db_lock"); 1017 - (* the worker fiber-waiting finding fires and names the worker; the root, 1018 - recovered as cc:root, is excluded. *) 1019 - let fibs = 1020 - List.filter (fun (f : Rep.finding) -> f.kind = "fiber") r.Rep.findings 1021 - in 1022 - Alcotest.(check int) "one fiber finding" 1 (List.length fibs); 1023 - let ff = List.hd fibs in 1024 - Alcotest.(check bool) 1025 - "fiber finding names worker" true 1026 - (contains ff.Rep.diagnosis "worker"); 1027 - (* worker ran 10ms, suspended 889ms over a 899ms life. *) 1028 - close "fiber waiting payoff" ff.Rep.payoff_seconds 0.889; 1049 + (* The contention finding above is the bottleneck; the critical-path zeroing of 1050 + the fiber finding is tested on the exact scenarios below, not on this fused 1051 + round-trip. *) 1029 1052 (* GC counts exact: 3 cycles, 12 slices, 2 minor collections. *) 1030 1053 Alcotest.(check int) "major cycles" 3 r.Rep.major_cycles; 1031 1054 Alcotest.(check int) "major slices" 12 r.Rep.major_slices; ··· 1508 1531 Alcotest.test_case "suspend where" `Quick test_suspend_where; 1509 1532 Alcotest.test_case "waiting fiber location" `Quick 1510 1533 test_waiting_fiber_location; 1511 - Alcotest.test_case "waiting fiber span suppressed" `Quick 1512 - test_waiting_fiber_span_suppressed; 1534 + Alcotest.test_case "waiting fiber off path" `Quick 1535 + test_waiting_fiber_off_path_not_flagged; 1513 1536 Alcotest.test_case "wait sleep fix" `Quick test_wait_sleep_fix; 1514 1537 Alcotest.test_case "summary vs full" `Quick test_summary_vs_full; 1515 1538 Alcotest.test_case "gc finding requires ctf" `Quick test_gc_finding_no_ctf; ··· 1528 1551 test_alloc_join_unavailable; 1529 1552 Alcotest.test_case "render content" `Quick test_render_content; 1530 1553 Alcotest.test_case "fxt round-trip" `Quick test_fxt_roundtrip; 1554 + Alcotest.test_case "fxt critical path round-trip" `Quick 1555 + test_fxt_cp_roundtrip; 1531 1556 Alcotest.test_case "fxt round-trip gc time" `Quick 1532 1557 test_fxt_roundtrip_gc_time; 1533 1558 Alcotest.test_case "fxt foreign root not flagged" `Quick

Configure Feed

Configure Feed