Don't crash on pauses greater than 10sec

Author: ngorogiannis

lib/olly_gc_stats/olly_gc_stats.5.0.ml

@@ -1,8 +1,12 @@
 include Olly_gc_stats_common
 
-let print_percentiles json output hist =
+let print_percentiles json output hist outliers =
   let to_sec x = float_of_int x /. 1_000_000_000. in
   let ms ns = ns /. 1_000_000. in
+  let outlier_mean_ms =
+    if outliers.count = 0 then 0.
+    else float_of_int outliers.total /. float_of_int outliers.count |> ms
+  in
 
   let mean_latency = H.mean hist |> ms
   and max_latency = float_of_int (H.max hist) |> ms in
@@ -82,10 +86,12 @@ let print_percentiles json output hist =
       Buffer.contents buf
     in
     Printf.fprintf oc
-      {|{"version": 1, "wall_time": %.2f, "cpu_time": %.2f, "gc_time": %.2f, "gc_overhead": %.2f, "max_rss_kb": %d, "domain_stats": {%s}, "mean_latency": %f, "stddev_latency": %f, "min_latency": %.2f, "max_latency": %f, "distr_latency": {%s}, "allocations": {"total_heap": %.0f, "minor_heap": %.0f, "promoted_words": %.0f, "promoted_pct": %.2f}, "collections": {"minor": %i, "major": %i, "forced_major": %i, "compactions": %i}}|}
+      {|{"version": 2, "wall_time": %.2f, "cpu_time": %.2f, "gc_time": %.2f, "gc_overhead": %.2f, "max_rss_kb": %d, "domain_stats": {%s}, "mean_latency": %f, "stddev_latency": %f, "min_latency": %.2f, "max_latency": %f, "distr_latency": {%s}, "outliers": {"count": %d, "mean_latency": %f, "max_latency": %f}, "allocations": {"total_heap": %.0f, "minor_heap": %.0f, "promoted_words": %.0f, "promoted_pct": %.2f}, "collections": {"minor": %i, "major": %i, "forced_major": %i, "compactions": %i}}|}
       real_time !total_cpu_time total_gc_time gc_overhead
       (Olly_common.Max_rss.max_rss_kb rss_collector)
       domain_stats mean_latency stddev_latency min_latency max_latency distribs
+      outliers.count outlier_mean_ms
+      (float_of_int outliers.max |> ms)
       total_heap !minor_words !promoted_words promoted_pct !minor_collections
       !major_collections !forced_major_collections !compactions
   else (
@@ -127,6 +133,13 @@ let print_percentiles json output hist =
     Fun.flip Array.iter percentiles (fun p ->
         Printf.fprintf oc "%.4f \t %.2f\n" p
           (float_of_int (H.value_at_percentile hist p) |> ms));
+    if outliers.count > 0 then
+      Printf.fprintf oc
+        "#[Beyond histogram (> %.0f ms):\t%d events,\t mean (ms):\t%.2f,\t \
+         max (ms):\t%.2f]\n"
+        (float_of_int highest_trackable_value |> ms)
+        outliers.count outlier_mean_ms
+        (float_of_int outliers.max |> ms);
     Printf.fprintf oc "\n";
     Printf.fprintf oc "GC allocations (in words): \n";
     Printf.fprintf oc "Total heap:\t %.0f\n" total_heap;
@@ -143,9 +156,10 @@ let gc_stats poll_sleep json output runtime_events_dir runtime_events_log_wsize
     exec_args =
   let current_event = Hashtbl.create 13 in
   let hist =
-    H.init ~lowest_discernible_value:10 ~highest_trackable_value:10_000_000_000
+    H.init ~lowest_discernible_value:10 ~highest_trackable_value
       ~significant_figures:3
   in
+  let outliers = make_outliers () in
   let is_gc_phase phase =
     match phase with
     | Runtime_events.EV_MAJOR | Runtime_events.EV_STW_LEADER
@@ -182,7 +196,7 @@ let gc_stats poll_sleep json output runtime_events_dir runtime_events_log_wsize
     | Some (saved_phase, saved_ts) when saved_phase = phase ->
         Hashtbl.remove current_event ring_id;
         let latency = Int64.to_int (Int64.sub (Ts.to_int64 ts) saved_ts) in
-        assert (H.record_value hist latency);
+        record_latency hist outliers latency;
         domain_gc_times.(ring_id) <- domain_gc_times.(ring_id) + latency
     | _ -> ()
   in
@@ -204,7 +218,7 @@ let gc_stats poll_sleep json output runtime_events_dir runtime_events_log_wsize
   in
 
   let init = Fun.id in
-  let cleanup () = print_percentiles json output hist in
+  let cleanup () = print_percentiles json output hist outliers in
   let on_poll = Olly_common.Max_rss.sample rss_collector in
   let open Olly_common.Launch in
   try

lib/olly_gc_stats/olly_gc_stats.5.3.ml

@@ -52,9 +52,13 @@ let print_per_domain_stats oc =
     |> Array.combine domain_major_words);
   print_table oc !data
 
-let print_percentiles json output hist =
+let print_percentiles json output hist outliers =
   let to_sec x = float_of_int x /. 1_000_000_000. in
   let ms ns = ns /. 1_000_000. in
+  let outlier_mean_ms =
+    if outliers.count = 0 then 0.
+    else float_of_int outliers.total /. float_of_int outliers.count |> ms
+  in
 
   let mean_latency = H.mean hist |> ms
   and max_latency = float_of_int (H.max hist) |> ms in
@@ -155,10 +159,12 @@ let print_percentiles json output hist =
       Buffer.contents buf
     in
     Printf.fprintf oc
-      {|{"version": 1, "wall_time": %.2f, "cpu_time": %.2f, "gc_time": %.2f, "gc_overhead": %.2f, "max_rss_kb": %d, "domain_stats": {%s}, "mean_latency": %f, "stddev_latency": %f, "min_latency": %.2f, "max_latency": %f, "distr_latency": {%s}, "allocations": {"total_heap": %.0f, "minor_heap": %.0f, "major_heap": %.0f, "promoted_words": %.0f, "promoted_pct": %.2f}, "domain_alloc_stats": {%s}, "collections": {"minor": %i, "major": %i, "forced_major": %i, "compactions": %i}}|}
+      {|{"version": 2, "wall_time": %.2f, "cpu_time": %.2f, "gc_time": %.2f, "gc_overhead": %.2f, "max_rss_kb": %d, "domain_stats": {%s}, "mean_latency": %f, "stddev_latency": %f, "min_latency": %.2f, "max_latency": %f, "distr_latency": {%s}, "outliers": {"count": %d, "mean_latency": %f, "max_latency": %f}, "allocations": {"total_heap": %.0f, "minor_heap": %.0f, "major_heap": %.0f, "promoted_words": %.0f, "promoted_pct": %.2f}, "domain_alloc_stats": {%s}, "collections": {"minor": %i, "major": %i, "forced_major": %i, "compactions": %i}}|}
       real_time !total_cpu_time total_gc_time gc_overhead
       (Olly_common.Max_rss.max_rss_kb rss_collector)
       domain_stats mean_latency stddev_latency min_latency max_latency distribs
+      outliers.count outlier_mean_ms
+      (float_of_int outliers.max |> ms)
       total_heap !minor_words !major_words !promoted_words promoted_pct
       domain_alloc_stats !minor_collections !major_collections
       !forced_major_collections !compactions
@@ -201,6 +207,13 @@ let print_percentiles json output hist =
     Fun.flip Array.iter percentiles (fun p ->
         Printf.fprintf oc "%.4f \t %.2f\n" p
           (float_of_int (H.value_at_percentile hist p) |> ms));
+    if outliers.count > 0 then
+      Printf.fprintf oc
+        "#[Beyond histogram (> %.0f ms):\t%d events,\t mean (ms):\t%.2f,\t \
+         max (ms):\t%.2f]\n"
+        (float_of_int highest_trackable_value |> ms)
+        outliers.count outlier_mean_ms
+        (float_of_int outliers.max |> ms);
     Printf.fprintf oc "\n";
     print_global_allocation_stats oc;
     print_per_domain_stats oc;
@@ -213,9 +226,10 @@ let gc_stats poll_sleep json output runtime_events_dir runtime_events_log_wsize
     exec_args =
   let current_event = Hashtbl.create 13 in
   let hist =
-    H.init ~lowest_discernible_value:10 ~highest_trackable_value:10_000_000_000
+    H.init ~lowest_discernible_value:10 ~highest_trackable_value
       ~significant_figures:3
   in
+  let outliers = make_outliers () in
   let is_gc_phase phase =
     match phase with
     | Runtime_events.EV_MAJOR | Runtime_events.EV_STW_LEADER
@@ -252,7 +266,7 @@ let gc_stats poll_sleep json output runtime_events_dir runtime_events_log_wsize
     | Some (saved_phase, saved_ts) when saved_phase = phase ->
         Hashtbl.remove current_event ring_id;
         let latency = Int64.to_int (Int64.sub (Ts.to_int64 ts) saved_ts) in
-        assert (H.record_value hist latency);
+        record_latency hist outliers latency;
         domain_gc_times.(ring_id) <- domain_gc_times.(ring_id) + latency
     | _ -> ()
   in
@@ -278,7 +292,7 @@ let gc_stats poll_sleep json output runtime_events_dir runtime_events_log_wsize
   in
 
   let init = Fun.id in
-  let cleanup () = print_percentiles json output hist in
+  let cleanup () = print_percentiles json output hist outliers in
   let on_poll = Olly_common.Max_rss.sample rss_collector in
   let open Olly_common.Launch in
   try

lib/olly_gc_stats/olly_gc_stats_common.ml

@@ -9,6 +9,11 @@ type ts = { mutable start_time : float; mutable end_time : float }
    This can be user configurable with OCAMLRUNPARAM=d=XXX
 *)
 let number_domains = 128
+
+(* Largest GC pause (in nanoseconds) the latency histogram can track. Pauses
+   beyond this are summarised separately. *)
+let highest_trackable_value = 10_000_000_000
+
 let wall_time = { start_time = 0.; end_time = 0. }
 let rss_collector = Olly_common.Max_rss.create ()
 let domain_elapsed_times = Array.make number_domains 0.
@@ -20,6 +25,21 @@ let major_collections = ref 0
 let forced_major_collections = ref 0
 let compactions = ref 0
 
+(* Running summary of GC pauses that fall outside the histogram's range. *)
+type outliers = { mutable count : int; mutable total : int; mutable max : int }
+
+let make_outliers () = { count = 0; total = 0; max = 0 }
+
+(* Record [latency] into [hist], or, if it is too large for the histogram,
+   fold it into [outliers]. [H.record_value] returns [false] for out-of-range
+   values; a non-positive latency is a spurious measurement and is dropped. *)
+let record_latency hist outliers latency =
+  if (not (H.record_value hist latency)) && latency > highest_trackable_value
+  then (
+    outliers.count <- outliers.count + 1;
+    outliers.total <- outliers.total + latency;
+    if latency > outliers.max then outliers.max <- latency)
+
 let lifecycle domain_id ts lifecycle_event _data =
   let ts = float_of_int Int64.(to_int @@ Ts.to_int64 ts) /. 1_000_000_000. in
   match lifecycle_event with