From f858316c9effaa79d85aa72d554c963de7ef10bf Mon Sep 17 00:00:00 2001 From: Julien Sagot Date: Thu, 21 Nov 2024 17:37:38 +0100 Subject: [PATCH 1/3] Profiler: add a special "__ENABLE_CHILDREN_ONLY__" for prometheus backend. --- src/bin_node/prometheus_profiler.ml | 4 ++++ src/bin_node/prometheus_profiler.mli | 6 +++++- 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/src/bin_node/prometheus_profiler.ml b/src/bin_node/prometheus_profiler.ml index 7a940f5d8cf5..6a51e167c20a 100644 --- a/src/bin_node/prometheus_profiler.ml +++ b/src/bin_node/prometheus_profiler.ml @@ -74,6 +74,10 @@ module Prometheus = struct let namespace = "profiling" in match Stdlib.List.assoc_opt "prometheus" metadata with | None -> false + | Some "__ENABLE_CHILDREN_ONLY__" -> + (* We don't record the metric but pretend we did so that children of + the node will be processed *) + true | Some id' -> let id = if id' = "" then id else id' in if d.wall = 0. then diff --git a/src/bin_node/prometheus_profiler.mli b/src/bin_node/prometheus_profiler.mli index f126b5fb6d5b..b9a725bb65e6 100644 --- a/src/bin_node/prometheus_profiler.mli +++ b/src/bin_node/prometheus_profiler.mli @@ -17,5 +17,9 @@ You MUST avoid metric names that are too unique such as block or operation hashes because prometheus will quickly fail at handling - a too high metrics cardinality otherwise. *) + a too high metrics cardinality otherwise. + + Note that if a parent node is not marked as the "prometheus" attribute, + its children will be skipped. In order to skip the node but not its + children, use the special value ["__ENABLE_CHILDREN_ONLY__"]. *) val prometheus : (string * Profiler.verbosity) Profiler.driver -- GitLab From afacca41685a184863668eabdd091a8d0f58e14e Mon Sep 17 00:00:00 2001 From: Julien Sagot Date: Thu, 21 Nov 2024 17:38:13 +0100 Subject: [PATCH 2/3] Profiler: enable prometheus backend in Block_store module. --- src/lib_store/unix/block_store.ml | 122 +++++++++++++++++++++++------- 1 file changed, 94 insertions(+), 28 deletions(-) diff --git a/src/lib_store/unix/block_store.ml b/src/lib_store/unix/block_store.ml index 6990e459f9ca..3ce6adbe8457 100644 --- a/src/lib_store/unix/block_store.ml +++ b/src/lib_store/unix/block_store.ml @@ -423,7 +423,9 @@ let cement_blocks ?(check_consistency = true) ~write_metadata block_store ~check_consistency cemented_store ~write_metadata - chunk_iterator [@profiler.record_s {verbosity = Debug} "cement blocks"]) + chunk_iterator + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} "cement blocks"]) in let*! () = Store_events.(emit end_cementing_blocks) () in return_unit @@ -925,7 +927,9 @@ let update_floating_stores block_store ~history_mode ~ro_store ~rw_store (read_predecessor_block_by_level block_store ~head:new_head - new_head_lpbl [@profiler.record_s {verbosity = Debug} "read lpbl block"]) + new_head_lpbl + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} "read lpbl block"]) in let final_hash, final_level = Block_repr.descriptor lpbl_block in (* 1. Append to the new RO [new_store] blocks between @@ -948,13 +952,16 @@ let update_floating_stores block_store ~history_mode ~ro_store ~rw_store floating_stores final_hash max_nb_blocks_to_retrieve - [@profiler.record_s {verbosity = Debug} "retrieve N lpbl's predecessors"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "retrieve N lpbl's predecessors"]) in (* [min_level_to_preserve] is the lowest block that we want to keep in the floating stores. *) let*! min_level_to_preserve = match[@profiler.record_s - {verbosity = Debug} "read min level block to preserve"] + {verbosity = Debug; metadata = [("prometheus", "")]} + "read min level block to preserve"] lpbl_predecessors with | [] -> Lwt.return new_head_lpbl @@ -977,7 +984,9 @@ let update_floating_stores block_store ~history_mode ~ro_store ~rw_store ~src_floating_stores:floating_stores ~block_hashes:lpbl_predecessors ~dst_floating_store:new_store - [@profiler.record_s {verbosity = Debug} "copy all lpbl predecessors"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "copy all lpbl predecessors"]) in (* 2. Retrieve ALL cycles (potentially more than one) *) (* 2.1. We write back to the new store all the blocks from @@ -1039,7 +1048,8 @@ let update_floating_stores block_store ~history_mode ~ro_store ~rw_store store block_hash [@profiler.aggregate_s - {verbosity = Debug} "find block index info"]) + {verbosity = Debug; metadata = [("prometheus", "")]} + "find block index info"]) in Lwt.return (WithExceptions.Option.get ~loc:__LOC__ pred_opt) in @@ -1051,15 +1061,17 @@ let update_floating_stores block_store ~history_mode ~ro_store ~rw_store predecessors, resulting_context_hash ) [@profiler.aggregate_s - {verbosity = Debug} "raw append block"])) + {verbosity = Debug; metadata = [("prometheus", "")]} + "raw append block"])) else return_unit) store [@profiler.record_s - {verbosity = Debug} + {verbosity = Debug; metadata = [("prometheus", "")]} (Printf.sprintf "iterate over floating store '%s'" kind)])) [ro_store; rw_store] [@profiler.record_s - {verbosity = Debug} "iterate and prune floating stores"]) + {verbosity = Debug; metadata = [("prometheus", "")]} + "iterate and prune floating stores"]) in let is_cementing_highwatermark_genesis = Compare.Int32.( @@ -1092,7 +1104,9 @@ let update_floating_stores block_store ~history_mode ~ro_store ~rw_store [] initial_pred sorted_lpbl - [@profiler.record_s {verbosity = Debug} "retrieve cycle to cement"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "retrieve cycle to cement"]) in return (may_shrink_cycles cycles ~cycle_size_limit) in @@ -1104,7 +1118,9 @@ let update_floating_stores block_store ~history_mode ~ro_store ~rw_store ~min_level_to_preserve ~new_head ~cycles_to_cement - [@profiler.record_s {verbosity = Debug} "compute new savepoint"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "compute new savepoint"]) in let* new_caboose = (compute_new_caboose @@ -1112,7 +1128,10 @@ let update_floating_stores block_store ~history_mode ~ro_store ~rw_store history_mode ~new_savepoint ~min_level_to_preserve - ~new_head [@profiler.record_s {verbosity = Debug} "compute new caboose"]) + ~new_head + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "compute new caboose"]) in return (cycles_to_cement, new_savepoint, new_caboose) @@ -1176,7 +1195,8 @@ let move_all_floating_stores block_store ~new_ro_store = ~src:new_ro_store ~dst_kind:RO [@profiler.record_s - {verbosity = Debug} "promote new ro floating as ro"]) + {verbosity = Debug; metadata = [("prometheus", "")]} + "promote new ro floating as ro"]) in (* ...and [new_rw] to [rw] *) let* () = @@ -1185,7 +1205,8 @@ let move_all_floating_stores block_store ~new_ro_store = ~src:block_store.rw_floating_block_store ~dst_kind:RW [@profiler.record_s - {verbosity = Debug} "promote new rw floating as rw"]) + {verbosity = Debug; metadata = [("prometheus", "")]} + "promote new rw floating as rw"]) in (* Load the swapped stores *) (let*! ro = Floating_block_store.init chain_dir ~readonly:false RO in @@ -1193,7 +1214,9 @@ let move_all_floating_stores block_store ~new_ro_store = let*! rw = Floating_block_store.init chain_dir ~readonly:false RW in block_store.rw_floating_block_store <- rw ; return_unit) - [@profiler.record_s {verbosity = Debug} "open new floating stores"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "open new floating stores"]) let check_store_consistency block_store ~cementing_highwatermark = let open Lwt_result_syntax in @@ -1271,7 +1294,9 @@ let instantiate_temporary_floating_store block_store = block_store.chain_dir ~readonly:false RW_TMP - [@profiler.record_s {verbosity = Debug} "initializing RW TMP"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "initializing RW TMP"]) in block_store.rw_floating_block_store <- new_rw_store ; return (ro_store, rw_store, new_rw_store))) @@ -1302,7 +1327,8 @@ let create_merging_thread block_store ~history_mode ~old_ro_store ~old_rw_store ~readonly:false RO_TMP [@profiler.record_s - {verbosity = Debug} "initializing RO TMP floating store"]) + {verbosity = Debug; metadata = [("prometheus", "")]} + "initializing RO TMP floating store"]) in let* new_savepoint, new_caboose = Lwt.catch @@ -1319,7 +1345,9 @@ let create_merging_thread block_store ~history_mode ~old_ro_store ~old_rw_store ~lowest_bound_to_preserve_in_floating ~cementing_highwatermark ~cycle_size_limit - [@profiler.record_s {verbosity = Debug} "update floating stores"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "update floating stores"]) in let*! () = Store_events.(emit cementing_block_ranges) cycles_interval_to_cement @@ -1462,7 +1490,11 @@ let merge_stores ?(cycle_size_limit = default_cycle_size_limit) block_store previous merge. *) () [@profiler.reset_block_section - {verbosity = Notice} (Block_repr.hash new_head)] ; + { + verbosity = Notice; + metadata = [("prometheus", "__ENABLE_CHILDREN_ONLY__")]; + } + (Block_repr.hash new_head)] ; let*! () = Lwt_mutex.lock block_store.merge_mutex in protect ~on_error:(fun err -> @@ -1482,7 +1514,9 @@ let merge_stores ?(cycle_size_limit = default_cycle_size_limit) block_store (fun () -> (let*! () = lock block_store.stored_data_lockfile in Block_store_status.set_merge_status block_store.status_data) - [@profiler.record_s {verbosity = Notice} "write status"]) + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "write status"]) (fun () -> unlock block_store.stored_data_lockfile) in let new_head_lpbl = @@ -1511,7 +1545,14 @@ let merge_stores ?(cycle_size_limit = default_cycle_size_limit) block_store (instantiate_temporary_floating_store block_store [@profiler.record_s - {verbosity = Notice} "instanciate tmp floating stores"])) + { + verbosity = Notice; + metadata = + [ + ("prometheus", "instantiate_temporary_floating_store"); + ]; + } + "instanciate tmp floating stores"])) (fun () -> unlock block_store.lockfile) in (* Important: do not clean-up the temporary stores on @@ -1545,7 +1586,11 @@ let merge_stores ?(cycle_size_limit = default_cycle_size_limit) block_store ~lowest_bound_to_preserve_in_floating ~cementing_highwatermark [@profiler.record_s - {verbosity = Info} "create_merging_thread"]) + { + verbosity = Info; + metadata = [("prometheus", "")]; + } + "create_merging_thread"]) in let* () = Lwt_idle_waiter.force_idle @@ -1564,7 +1609,10 @@ let merge_stores ?(cycle_size_limit = default_cycle_size_limit) block_store block_store ~new_ro_store [@profiler.record_s - {verbosity = Info} + { + verbosity = Info; + metadata = [("prometheus", "")]; + } "move_all_floating_stores"]) in let*! () = @@ -1575,14 +1623,22 @@ let merge_stores ?(cycle_size_limit = default_cycle_size_limit) block_store block_store new_caboose [@profiler.record_s - {verbosity = Info} "write_caboose"]) + { + verbosity = Info; + metadata = [("prometheus", "")]; + } + "write_caboose"]) in let* () = (write_savepoint block_store new_savepoint [@profiler.record_s - {verbosity = Info} "write_savepoint"]) + { + verbosity = Info; + metadata = [("prometheus", "")]; + } + "write_savepoint"]) in return_unit) (fun () -> @@ -1602,7 +1658,11 @@ let merge_stores ?(cycle_size_limit = default_cycle_size_limit) block_store ~previous_savepoint ~new_savepoint [@profiler.record_s - {verbosity = Info} "performing GC"]) + { + verbosity = Info; + metadata = [("prometheus", "")]; + } + "performing GC"]) in (* Don't call the finalizer in the critical section, in case it needs to access the block @@ -1622,13 +1682,19 @@ let merge_stores ?(cycle_size_limit = default_cycle_size_limit) block_store (fun () -> unlock block_store.stored_data_lockfile) [@profiler.record_s - {verbosity = Info} "set idle status"]) + { + verbosity = Info; + metadata = [("prometheus", "")]; + } + "set idle status"]) in return_unit)) (fun () -> Lwt_mutex.unlock block_store.merge_mutex ; Lwt.return_unit) - [@profiler.record_s {verbosity = Notice} "merging thread"]) + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "merging thread"]) in let merge_end = Time.System.now () in let merging_time = Ptime.diff merge_end merge_start in -- GitLab From af278a402f260d2bf322bcac8b1b487b1b8ec74b Mon Sep 17 00:00:00 2001 From: Julien Sagot Date: Thu, 21 Nov 2024 17:38:22 +0100 Subject: [PATCH 3/3] Profiler: enable prometheus backend in Store module. --- src/lib_store/unix/store.ml | 66 +++++++++++++++++++++++++++---------- 1 file changed, 49 insertions(+), 17 deletions(-) diff --git a/src/lib_store/unix/store.ml b/src/lib_store/unix/store.ml index 5ed3e9a23037..40101ca0b302 100644 --- a/src/lib_store/unix/store.ml +++ b/src/lib_store/unix/store.ml @@ -510,7 +510,13 @@ module Block = struct let open Lwt_result_syntax in let bytes = Block_header.to_bytes block_header in let hash = Block_header.hash_raw bytes in - () [@profiler.reset_block_section {verbosity = Notice} hash] ; + () + [@profiler.reset_block_section + { + verbosity = Notice; + metadata = [("prometheus", "__ENABLE_CHILDREN_ONLY__")]; + } + hash] ; (let { Block_validation.validation_store = { @@ -700,7 +706,8 @@ module Block = struct chain_store.global_store.global_block_watcher (chain_store, block) ; return_some block) - [@profiler.record_s {verbosity = Notice} "store_block"] + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} "store_block"] let store_validated_block chain_store ~hash ~block_header ~operations = let open Lwt_result_syntax in @@ -1316,7 +1323,8 @@ module Chain = struct } ; return (diffed_new_live_blocks, diffed_new_live_operations)) [@profiler.record_s - {verbosity = Debug} "compute live blocks with new head"]) + {verbosity = Debug; metadata = [("prometheus", "")]} + "compute live blocks with new head"]) | Some live_data, Some _ when Block_hash.equal (Block.predecessor block) @@ -1335,7 +1343,8 @@ module Chain = struct ~new_head:block ~cache_expected_capacity:expected_capacity [@profiler.record_s - {verbosity = Debug} "compute live blocks with alternative head"] + {verbosity = Debug; metadata = [("prometheus", "")]} + "compute live blocks with alternative head"] | _ when update_cache -> (* The block candidate is not on top of the current head. It is likely to be an alternate branch. We recompute the whole live @@ -1359,7 +1368,8 @@ module Chain = struct in return (live_blocks, live_ops)) [@profiler.record_s - {verbosity = Debug} "compute live blocks with alternative branch"] + {verbosity = Debug; metadata = [("prometheus", "")]} + "compute live blocks with alternative branch"] | _ -> (* The block candidate is not on top of the current head. It is likely to be an alternate head. We recompute the whole @@ -1369,7 +1379,9 @@ module Chain = struct chain_store block expected_capacity - [@profiler.record_s {verbosity = Debug} "compute whole live blocks"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "compute whole live blocks"]) in return new_live_blocks @@ -1403,7 +1415,9 @@ module Chain = struct live_blocks live_operations ~pred_cache - [@profiler.record_s {verbosity = Debug} "rollback livedata"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "rollback livedata"]) else locked_compute_live_blocks_with_cache ~update_cache @@ -1412,7 +1426,8 @@ module Chain = struct block metadata [@profiler.record_s - {verbosity = Debug} "locked compute live blocks with cache"] + {verbosity = Debug; metadata = [("prometheus", "")]} + "locked compute live blocks with cache"] in return res @@ -1429,7 +1444,9 @@ module Chain = struct metadata in return r) - [@profiler.aggregate_s {verbosity = Notice} "compute_live_blocks"]) + [@profiler.aggregate_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "compute_live_blocks"]) let is_ancestor chain_store ~head:(hash, lvl) ~ancestor:(hash', lvl') = let open Lwt_syntax in @@ -1944,7 +1961,9 @@ module Chain = struct ~loc:__LOC__ cementing_highwatermark) ~disable_context_pruning:chain_store.disable_context_pruning - [@profiler.mark {verbosity = Notice} ["merge_stores"]]) + [@profiler.mark + {verbosity = Notice; metadata = [("prometheus", "")]} + ["merge_stores"]]) in (* The new memory highwatermark is new_head_lpbl, the disk value will be updated after the merge completion. *) @@ -1981,12 +2000,16 @@ module Chain = struct (Stored_data.write chain_state.current_head_data new_head_descr - [@profiler.record_s {verbosity = Debug} "write_new_head"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "write_new_head"]) in (Stored_data.write chain_state.target_data new_target - [@profiler.record_s {verbosity = Debug} "write_new_target"])) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "write_new_target"])) (fun () -> unlock chain_store.stored_data_lockfile) in (* Update live_data *) @@ -1997,7 +2020,9 @@ module Chain = struct chain_state new_head new_head_metadata - [@profiler.record_s {verbosity = Debug} "updating live blocks"]) + [@profiler.record_s + {verbosity = Debug; metadata = [("prometheus", "")]} + "updating live blocks"]) in let new_chain_state = {chain_state with live_blocks; live_operations; current_head = new_head} @@ -2034,7 +2059,9 @@ module Chain = struct Block.get_block_metadata chain_store pred_block in Block.get_block_metadata chain_store new_head) - [@profiler.record_s {verbosity = Info} "get_pred_block"]) + [@profiler.record_s + {verbosity = Info; metadata = [("prometheus", "")]} + "get_pred_block"]) in let*! target = Stored_data.get chain_state.target_data in let new_head_lpbl = @@ -2046,7 +2073,9 @@ module Chain = struct chain_store new_head_lpbl previous_head - [@profiler.record_s {verbosity = Info} "may_split_context"]) + [@profiler.record_s + {verbosity = Info; metadata = [("prometheus", "")]} + "may_split_context"]) in let* lfbl_block_opt = match chain_state.last_finalized_block_level with @@ -2113,10 +2142,13 @@ module Chain = struct ~new_head_metadata ~new_head_descr ~new_target - [@profiler.record_s {verbosity = Info} "finalize_set_head"]) + [@profiler.record_s + {verbosity = Info; metadata = [("prometheus", "")]} + "finalize_set_head"]) in return (new_chain_state, previous_head)) - [@profiler.record_s {verbosity = Notice} "set_head"]) + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} "set_head"]) let set_target chain_store new_target = let open Lwt_result_syntax in -- GitLab