diff --git a/grafazos/src/octez-profiling.jsonnet b/grafazos/src/octez-profiling.jsonnet index 62eef3690b3fb18e21a8a670c9b4f9dec2a2f1be..5a9af6b38f1e420c1e090b2caaa96efc6660ba5e 100644 --- a/grafazos/src/octez-profiling.jsonnet +++ b/grafazos/src/octez-profiling.jsonnet @@ -12,7 +12,11 @@ local profiling = import './profiling.jsonnet'; // Constants local panelWidth = 10; local panelHeight = 10; -local startY = 1; +local store_y = 1; +local mempool_y = 41; +local chain_validator_y = 81; +local peer_validator_y = 121; +local block_validator_y = 161; // Create the dashboard dashboard.new('Octez Profiling Dashboard') @@ -23,10 +27,43 @@ dashboard.new('Octez Profiling Dashboard') + dashboard.withVariables([base.nodeInstance]) + dashboard.withPanels( - [ - panel.row.new('Store Profiling'), - profiling.setHead(h=panelHeight, w=panelWidth, x=0, y=startY), - profiling.storeBlock(h=panelHeight, w=panelWidth, x=panelWidth, y=startY), - profiling.computeLiveBlocks(h=panelHeight, w=panelWidth, x=0, y=startY + panelHeight), + //####### + grafonnet.util.grid.wrapPanels(panels=[panel.row.new('Store Profiling')], panelWidth=20, panelHeight=20, startY=store_y) + + [ + profiling.setHead(h=panelHeight, w=panelWidth, x=0, y=store_y), + profiling.storeBlock(h=panelHeight, w=panelWidth, x=panelWidth, y=store_y), + profiling.computeLiveBlocks(h=panelHeight, w=panelWidth, x=0, y=store_y + panelHeight), + ] + + //####### + + grafonnet.util.grid.wrapPanels(panels=[panel.row.new('Mempool Profiling')], panelWidth=20, panelHeight=20, startY=mempool_y) + + [ + profiling.onMempoolRequest(h=panelHeight, w=2 * panelWidth, x=0, y=mempool_y), + profiling.handleUnprocessed(h=panelHeight, w=panelWidth, x=0, y=mempool_y + panelHeight), + ] + + //####### + + grafonnet.util.grid.wrapPanels(panels=[panel.row.new('Chain Validator Profiling')], panelWidth=20, panelHeight=20, startY=chain_validator_y) + + [ + profiling.onChainValidatorRequest(h=panelHeight, w=2 * panelWidth, x=0, y=chain_validator_y), + ] + + //####### + + grafonnet.util.grid.wrapPanels(panels=[panel.row.new('Peer Validator Profiling')], panelWidth=20, panelHeight=20, startY=peer_validator_y) + + [ + profiling.onPeerValidatorRequest(h=panelHeight, w=2 * panelWidth, x=0, y=peer_validator_y), + ] + + //####### + + grafonnet.util.grid.wrapPanels(panels=[panel.row.new('Block Validator Profiling')], panelWidth=20, panelHeight=20, startY=block_validator_y) + + [ + profiling.applyBlock(h=panelHeight, w=panelWidth, x=0, y=block_validator_y), + profiling.applyOperations(h=panelHeight, w=panelWidth, x=panelWidth, y=block_validator_y), + profiling.beginApplication(h=panelHeight, w=panelWidth, x=0, y=block_validator_y + panelHeight), + profiling.beginValidation(h=panelHeight, w=panelWidth, x=panelWidth, y=block_validator_y + panelHeight), + profiling.finalizeApplication(h=panelHeight, w=panelWidth, x=0, y=block_validator_y + 2 * panelHeight), + profiling.finalizeValidation(h=panelHeight, w=panelWidth, x=panelWidth, y=block_validator_y + 2 * panelHeight), + profiling.validateBlock(h=panelHeight, w=panelWidth, x=0, y=block_validator_y + 3 * panelHeight), + profiling.validateOperation(h=panelHeight, w=panelWidth, x=panelWidth, y=block_validator_y + 3 * panelHeight), ] ) diff --git a/grafazos/src/profiling.jsonnet b/grafazos/src/profiling.jsonnet index 343fdff06d6e5afe1feb6d47ff03c88665e8bc42..68461f4d41b32c2a6ecd4abb1edbb1ddf18fd275 100644 --- a/grafazos/src/profiling.jsonnet +++ b/grafazos/src/profiling.jsonnet @@ -16,6 +16,10 @@ local msConversion = '1000'; // From seconds to milliseconds // Profiling constants local store = 'profiling_store_time'; +local mempool = 'profiling_mempool_time'; +local chain_validator = 'profiling_chain_validator_time'; +local peer_validator = 'profiling_peer_validator_time'; +local block_validator = 'profiling_block_validator_time'; // Helper function to calculate rates for a profiling metric local profilingRate(profiling, metricId, metricType) = @@ -29,20 +33,80 @@ local profilingQuery(profiling, metricId, legend) = + query.prometheus.withLegendFormat(legend); // Helper function to create a Grafana panel -local profilingPanel(profiling, metricId, legend, color, h, w, x, y) = +local profilingSinglePanel(profiling, metricId, legend, color, h, w, x, y) = local q = profilingQuery(profiling, metricId, legend); graph.new('Average Execution Time: ' + metricId, [q], h, w, x, y) + graph.withLegendBottom(calcs=['lastNotNull', 'mean', 'min', 'max']) + graph.withFixedColor(color) + timeSeries.standardOptions.withUnit('ms'); +// Helper function to create a Grafana panel with multile PromQL queries +local profilingMultiplePanels(profiling, legend, metrics, h, w, x, y) = + local queries = std.map(function(metric) profilingQuery(profiling, metric.id, metric.legend), metrics); + graph.new('Average Execution Time: ' + legend, queries, h, w, x, y) + + graph.withLegendRight(calcs=['mean', 'lastNotNull', 'max', 'min']) + + timeSeries.standardOptions.withUnit('ms'); + { + // Store Profiling setHead(h, w, x, y): - profilingPanel(store, 'set_head', 'Set Head', 'light-blue', h, w, x, y), + profilingSinglePanel(store, 'set_head', 'Set Head', 'light-blue', h, w, x, y), storeBlock(h, w, x, y): - profilingPanel(store, 'store_block', 'Store Block', 'light-green', h, w, x, y), + profilingSinglePanel(store, 'store_block', 'Store Block', 'light-green', h, w, x, y), computeLiveBlocks(h, w, x, y): - profilingPanel(store, 'compute_live_blocks', 'Compute Live Blocks', 'light-red', h, w, x, y), + profilingSinglePanel(store, 'compute_live_blocks', 'Compute Live Blocks', 'light-red', h, w, x, y), + + // Mempool Profiling + + handleUnprocessed(h, w, x, y): + profilingSinglePanel(mempool, 'handle_unprocessed', 'Handle Unprocessed', 'light-blue', h, w, x, y), + + onMempoolRequest(h, w, x, y): + profilingMultiplePanels(mempool, 'on_request', [ + { id: 'on_advertise', legend: 'On Advertise' }, + { id: 'on_arrived', legend: 'On Arrived' }, + { id: 'on_flush', legend: 'On Flush' }, + { id: 'on_inject', legend: 'On Inject' }, + { id: 'on_notify', legend: 'On Notify' }, + ], h, w, x, y), + + // Chain Validator Profiling + onChainValidatorRequest(h, w, x, y): + profilingMultiplePanels(chain_validator, 'on_request', [ + { id: 'on_validation_request', legend: 'On Validation Request' }, + { id: 'on_notify_branch', legend: 'On Notify Branch' }, + { id: 'on_notify_head', legend: 'On Notify Head' }, + { id: 'on_disconnection', legend: 'On Disconnection' }, + ], h, w, x, y), + + // Peer Validator Profiling + onPeerValidatorRequest(h, w, x, y): + profilingSinglePanel(peer_validator, 'validate_new_head', 'Validate New Head', 'light-red', h, w, x, y), + + // Block Validator Profiling + applyBlock(h, w, x, y): + profilingSinglePanel(block_validator, 'apply_block', 'Apply Block', 'light-blue', h, w, x, y), + + applyOperations(h, w, x, y): + profilingSinglePanel(block_validator, 'apply_operations', 'Apply Operations', 'light-blue', h, w, x, y), + + beginApplication(h, w, x, y): + profilingSinglePanel(block_validator, 'begin_application', 'Begin Application', 'light-red', h, w, x, y), + + beginValidation(h, w, x, y): + profilingSinglePanel(block_validator, 'begin_validation', 'Begin Validation', 'light-red', h, w, x, y), + + finalizeApplication(h, w, x, y): + profilingSinglePanel(block_validator, 'finalize_application', 'Finalize Application', 'light-green', h, w, x, y), + + finalizeValidation(h, w, x, y): + profilingSinglePanel(block_validator, 'finalize_validation', 'Finalize Validation', 'light-green', h, w, x, y), + + validateBlock(h, w, x, y): + profilingSinglePanel(block_validator, 'validate_block', 'Validate Block', 'yellow', h, w, x, y), + + validateOperation(h, w, x, y): + profilingSinglePanel(block_validator, 'validate_operation', 'Validate Operation', 'yellow', h, w, x, y), } diff --git a/src/lib_shell/chain_validator.ml b/src/lib_shell/chain_validator.ml index 21185f83fc4df6949dcaa53892e42a481219df07..cd0bbc0739e7c8dd1e7fadbc9653619eed28d217 100644 --- a/src/lib_shell/chain_validator.ml +++ b/src/lib_shell/chain_validator.ml @@ -615,22 +615,33 @@ let on_request (type a b) w start_testchain active_chains spawn_child start_testchain active_chains spawn_child - block [@profiler.span_s {verbosity = Notice} ["on_validation_request"]] + block + [@profiler.span_s + {verbosity = Notice; metadata = [("prometheus", "")]} + ["on_validation_request"]] | Request.Notify_branch (peer_id, locator) -> on_notify_branch w peer_id - locator [@profiler.span_s {verbosity = Notice} ["on_notify_branch"]] + locator + [@profiler.span_s + {verbosity = Notice; metadata = [("prometheus", "")]} + ["on_notify_branch"]] | Request.Notify_head (peer_id, hash, header, mempool) -> on_notify_head w peer_id (hash, header) - mempool [@profiler.span_s {verbosity = Notice} ["on_notify_head"]] + mempool + [@profiler.span_s + {verbosity = Notice; metadata = [("prometheus", "")]} ["on_notify_head"]] | Request.Disconnection peer_id -> on_disconnection w - peer_id [@profiler.span_s {verbosity = Notice} ["on_disconnection"]] + peer_id + [@profiler.span_s + {verbosity = Notice; metadata = [("prometheus", "")]} + ["on_disconnection"]] let collect_proto ~metrics (chain_store, block) = let open Lwt_syntax in diff --git a/src/lib_shell/peer_validator.ml b/src/lib_shell/peer_validator.ml index c7090de0aa46096b6f5930b4d3939250c8ecc6cf..216b1611f01a98d3fe39d549bd78b453fe95294a 100644 --- a/src/lib_shell/peer_validator.ml +++ b/src/lib_shell/peer_validator.ml @@ -244,7 +244,9 @@ let validate_new_head w hash (header : Block_header.t) = [@profiler.span_s {verbosity = Debug} (profiling_validate_new_head_prefix hash ["fitness increases"])])) - [@profiler.span_s {verbosity = Info} (profiling_new_head_prefix hash [])] + [@profiler.span_s + {verbosity = Info; metadata = [("prometheus", "validate_new_head")]} + (profiling_new_head_prefix hash [])] let assert_acceptable_head w hash (header : Block_header.t) = let open Lwt_result_syntax in diff --git a/src/lib_shell/prevalidator.ml b/src/lib_shell/prevalidator.ml index afb6d23a2d5902e3fb7826c5b7127419f0fca68d..4435c871f052faff62eb4f9e209614b9a0d24087 100644 --- a/src/lib_shell/prevalidator.ml +++ b/src/lib_shell/prevalidator.ml @@ -1442,7 +1442,9 @@ module Make let* () = (handle_unprocessed pv - [@profiler.aggregate_s {verbosity = Notice} "handle_unprocessed"]) + [@profiler.aggregate_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "handle_unprocessed"]) in r in @@ -1453,7 +1455,10 @@ module Make () [@profiler.stop] [@profiler.record - {verbosity = Notice} + { + verbosity = Notice; + metadata = [("prometheus", "__ENABLE_CHILDREN_ONLY__")]; + } (Format.sprintf "%s" (Block_hash.to_b58check hash))] ; Requests.on_advertise pv.shell ; (* TODO: https://gitlab.com/tezos/tezos/-/issues/1727 @@ -1473,35 +1478,48 @@ module Make block live_blocks live_operations - [@profiler.aggregate_s {verbosity = Notice} "on_flush"])) + [@profiler.aggregate_s + {verbosity = Notice; metadata = [("prometheus", "")]} "on_flush"])) | Request.Notify (peer, mempool) -> Requests.on_notify pv.shell peer - mempool [@profiler.aggregate_f {verbosity = Notice} "on_notify"] ; + mempool + [@profiler.aggregate_f + {verbosity = Notice; metadata = [("prometheus", "")]} "on_notify"] ; return_unit | Request.Leftover -> - () [@profiler.mark {verbosity = Notice} ["leftover"]] ; + () + [@profiler.mark + {verbosity = Notice; metadata = [("prometheus", "")]} ["leftover"]] ; (* unprocessed ops are handled just below *) return_unit | Request.Inject {op; force} -> Requests.on_inject pv ~force - op [@profiler.aggregate_s {verbosity = Notice} "on_inject"] + op + [@profiler.aggregate_s + {verbosity = Notice; metadata = [("prometheus", "")]} "on_inject"] | Request.Arrived (oph, op) -> Requests.on_arrived pv oph - op [@profiler.aggregate_s {verbosity = Notice} "on_arrived"] + op + [@profiler.aggregate_s + {verbosity = Notice; metadata = [("prometheus", "")]} "on_arrived"] | Request.Advertise -> Requests.on_advertise - pv.shell [@profiler.aggregate_f {verbosity = Notice} "on_advertise"] ; + pv.shell + [@profiler.aggregate_f + {verbosity = Notice; metadata = [("prometheus", "")]} "on_advertise"] ; return_unit | Request.Ban oph -> Requests.on_ban pv - oph [@profiler.aggregate_s {verbosity = Notice} "on_ban"] + oph + [@profiler.aggregate_s + {verbosity = Notice; metadata = [("prometheus", "")]} "on_ban"] let on_close w = let pv = Worker.state w in @@ -1525,7 +1543,10 @@ module Make let*! head = Store.Chain.current_head chain_store in () [@profiler.record - {verbosity = Notice} + { + verbosity = Notice; + metadata = [("prometheus", "__ENABLE_CHILDREN_ONLY__")]; + } (Format.sprintf "%s" (Block_hash.to_b58check (Store.Block.hash head)))] ; let*! mempool = Store.Chain.mempool chain_store in diff --git a/src/lib_validation/block_validation.ml b/src/lib_validation/block_validation.ml index 31bcbb34d73b76c5c8fe10ebbb2688449a5c11ca..4ae2feee468b4c2d4b6e2452c158fd79b2ae003a 100644 --- a/src/lib_validation/block_validation.ml +++ b/src/lib_validation/block_validation.ml @@ -624,7 +624,9 @@ module Make (Proto : Protocol_plugin.T) = struct ~predecessor:predecessor_block_header.shell ~cache [@time.duration_lwt application_beginning] - [@profiler.record_s {verbosity = Notice} "begin_application"]) + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "begin_application"]) in let* state, ops_metadata = (List.fold_left_i_es @@ -638,7 +640,10 @@ module Make (Proto : Protocol_plugin.T) = struct oph op [@profiler.record_s - {verbosity = Info} + { + verbosity = Info; + metadata = [("prometheus", "apply_operations")]; + } ("operation : " ^ Operation_hash.to_b58check oph)]) in return (state, op_metadata :: acc)) @@ -659,7 +664,9 @@ module Make (Proto : Protocol_plugin.T) = struct state (Some block_header.shell) [@time.duration_lwt block_finalization] - [@profiler.record_s {verbosity = Notice} "finalize_application"]) + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "finalize_application"]) in return (validation_result, block_data, ops_metadata)) @@ -758,7 +765,9 @@ module Make (Proto : Protocol_plugin.T) = struct block_header predecessor_context predecessor_hash - [@profiler.record_s {verbosity = Notice} "prepare_context"]) + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "prepare_context"]) in let* validation_result, block_metadata, ops_metadata = proto_apply_operations @@ -887,7 +896,9 @@ module Make (Proto : Protocol_plugin.T) = struct }; cache; }) - [@profiler.record_s {verbosity = Notice} "post_validation"] + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "post_validation"] let recompute_metadata chain_id ~cache ~(predecessor_block_header : Block_header.t) @@ -1334,7 +1345,10 @@ module Make (Proto : Protocol_plugin.T) = struct chain_id (Application block_header) ~predecessor:predecessor_block_header.shell - ~cache [@profiler.record_s {verbosity = Notice} "begin_validation"]) + ~cache + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "begin_validation"]) in let* state = (List.fold_left_i_es @@ -1347,7 +1361,10 @@ module Make (Proto : Protocol_plugin.T) = struct oph op [@profiler.record_s - {verbosity = Info} + { + verbosity = Info; + metadata = [("prometheus", "validate_operation")]; + } ("operation : " ^ Operation_hash.to_b58check oph)])) state ops @@ -1359,7 +1376,10 @@ module Make (Proto : Protocol_plugin.T) = struct in let* () = (Proto.finalize_validation - state [@profiler.record_s {verbosity = Notice} "finalize_validation"]) + state + [@profiler.record_s + {verbosity = Notice; metadata = [("prometheus", "")]} + "finalize_validation"]) in return_unit