diff --git a/manifest/product_octez.ml b/manifest/product_octez.ml index 1b7bbf4f711987ad9e1bf6638520ede4d2dd90d5..9414321360ddb1e4293b91ec7eb968fce4efea76 100644 --- a/manifest/product_octez.ml +++ b/manifest/product_octez.ml @@ -6266,6 +6266,7 @@ let hash = Protocol.hash in let baking = only_if active @@ fun () -> + let (PPX {preprocess; preprocessor_deps}) = ppx_profiler in octez_protocol_lib "baking" ~internal_name:("tezos_baking_" ^ name_dash) @@ -6274,6 +6275,8 @@ let hash = Protocol.hash (if N.(number <= 011) then "Base library for `tezos-baker/endorser/accuser`" else "Base library for `tezos-baker/accuser`") + ~preprocess + ~preprocessor_deps ~deps: [ octez_base |> open_ ~m:"TzPervasives" diff --git a/src/proto_020_PsParisC/lib_delegate/baking_nonces.ml b/src/proto_020_PsParisC/lib_delegate/baking_nonces.ml index 7d38c52f8db91ab70ccf0e04b246115398c73bb6..3be004b700e0ba95efadccb6cff8404585c3a0c6 100644 --- a/src/proto_020_PsParisC/lib_delegate/baking_nonces.ml +++ b/src/proto_020_PsParisC/lib_delegate/baking_nonces.ml @@ -28,6 +28,8 @@ open Protocol open Alpha_context module Events = Baking_events.Nonces +module Profiler = (val Profiler.wrap Baking_profiler.nonce_profiler) + type state = { cctxt : Protocol_client_context.full; chain : Chain_services.chain; @@ -328,7 +330,10 @@ let partition_unrevealed_nonces {cctxt; chain; _} nonces current_cycle | cycle when Cycle.(cycle = previous_cycle) -> ( (* Only process nonces that are part of previous cycle. *) let+ nonce_info = - Alpha_services.Nonce.get cctxt (chain, `Head 0) level + (Alpha_services.Nonce.get + cctxt + (chain, `Head 0) + level [@profiler.aggregate_s "get nonce information"]) in match (nonce_state, nonce_info) with | Committed, Missing expected_nonce_hash @@ -390,34 +395,42 @@ let generate_seed_nonce (nonce_config : Baking_configuration.nonce_config) let register_nonce (cctxt : #Protocol_client_context.full) ~chain_id block_hash nonce ~cycle ~level ~round = let open Lwt_result_syntax in - let*! () = Events.(emit registering_nonce block_hash) in - (* Register the nonce *) - let legacy_location = Baking_files.resolve_location ~chain_id `Legacy_nonce in - let stateful_location = - Baking_files.resolve_location ~chain_id `Stateful_nonce - in - let orphaned_location = - Baking_files.resolve_location ~chain_id `Orphaned_nonce - in - cctxt#with_lock @@ fun () -> - let* nonces = load cctxt ~stateful_location in - let nonces = - add + (let*! () = Events.(emit registering_nonce block_hash) in + (* Register the nonce *) + let legacy_location = + Baking_files.resolve_location ~chain_id `Legacy_nonce + in + let stateful_location = + Baking_files.resolve_location ~chain_id `Stateful_nonce + in + let orphaned_location = + Baking_files.resolve_location ~chain_id `Orphaned_nonce + in + () [@profiler.record_f "waiting lock"] ; + cctxt#with_lock @@ fun () -> + let* nonces = + (load cctxt ~stateful_location [@profiler.record_s "load nonces"]) + in + let nonces = + (add + nonces + { + nonce; + nonce_hash = Nonce.hash nonce; + block_hash; + cycle; + level; + round = Some round; + nonce_state = Committed; + } [@profiler.record_f "add nonces"]) + in + (save + cctxt + ~legacy_location + ~stateful_location nonces - { - nonce; - nonce_hash = Nonce.hash nonce; - block_hash; - cycle; - level; - round = Some round; - nonce_state = Committed; - } - in - let* () = - save cctxt ~legacy_location ~stateful_location nonces ~orphaned_location - in - return_unit + ~orphaned_location [@profiler.record_s "save nonces"])) + [@profiler.record_s "register nonce"] (** [inject_seed_nonce_revelation cctxt ~chain ~block ~branch nonces] forges one [Seed_nonce_revelation] operation per each nonce to be revealed, together with @@ -433,17 +446,21 @@ let inject_seed_nonce_revelation (cctxt : #Protocol_client_context.full) ~chain List.iter_es (fun (level, nonce) -> let* bytes = - Plugin.RPC.Forge.seed_nonce_revelation - cctxt - (chain, block) - ~branch - ~level - ~nonce - () + (Plugin.RPC.Forge.seed_nonce_revelation + cctxt + (chain, block) + ~branch + ~level + ~nonce + () [@profiler.aggregate_s "forge seed nonce revelation"]) in let bytes = Signature.concat bytes Signature.zero in let* oph = - Shell_services.Injection.operation ~async:true cctxt ~chain bytes + (Shell_services.Injection.operation + ~async:true + cctxt + ~chain + bytes [@profiler.aggregate_s "inject seed nonce revelation"]) in let*! () = Events.( @@ -480,8 +497,11 @@ let reveal_potential_nonces state new_proposal = let block = `Head 0 in let branch = new_predecessor_hash in (* improve concurrency *) + () [@profiler.record_f "waiting lock"] ; cctxt#with_lock @@ fun () -> - let*! nonces = load cctxt ~stateful_location in + let*! nonces = + (load cctxt ~stateful_location [@profiler.record_s "load nonce file"]) + in match nonces with | Error err -> let*! () = Events.(emit cannot_read_nonces err) in @@ -491,7 +511,11 @@ let reveal_potential_nonces state new_proposal = Plugin.RPC.current_level cctxt (chain, `Head 0) in let*! partitioned_nonces = - partition_unrevealed_nonces state nonces cycle level + (partition_unrevealed_nonces + state + nonces + cycle + level [@profiler.record_s "partition unrevealed nonces"]) in match partitioned_nonces with | Error err -> @@ -507,12 +531,13 @@ let reveal_potential_nonces state new_proposal = [] in let*! result = - inject_seed_nonce_revelation - cctxt - ~chain - ~block - ~branch - prepared_nonces + (inject_seed_nonce_revelation + cctxt + ~chain + ~block + ~branch + prepared_nonces + [@profiler.record_s "inject seed nonce revelation"]) in match result with | Error err -> @@ -531,15 +556,12 @@ let reveal_potential_nonces state new_proposal = nonce_with_new_states live_nonces in - let* () = - save - cctxt - ~legacy_location - ~stateful_location - ~orphaned_location - updated_nonces - in - return_unit))) + (save + cctxt + ~legacy_location + ~stateful_location + ~orphaned_location + updated_nonces [@profiler.record_s "save nonces"])))) else return_unit (* We suppose that the block stream is cloned by the caller *) @@ -570,6 +592,7 @@ let start_revelation_worker cctxt config chain_id constants block_stream = format. *) let* () = try_migrate_legacy_nonces state in + let last_proposal = ref None in let rec worker_loop () = Lwt_canceler.on_cancel canceler (fun () -> should_shutdown := true ; @@ -581,9 +604,18 @@ let start_revelation_worker cctxt config chain_id constants block_stream = with the node was interrupted: exit *) return_unit | Some new_proposal -> + Option.iter (fun _ -> (() [@profiler.stop])) !last_proposal ; + () + [@profiler.record + Block_hash.to_b58check new_proposal.Baking_state.block.hash] ; + last_proposal := Some new_proposal.Baking_state.block.hash ; if !should_shutdown then return_unit else - let* _ = reveal_potential_nonces state new_proposal in + let* _ = + (reveal_potential_nonces + state + new_proposal [@profiler.record_s "reveal potential nonces"]) + in worker_loop () in Lwt.dont_wait diff --git a/src/proto_020_PsParisC/lib_delegate/baking_profiler.ml b/src/proto_020_PsParisC/lib_delegate/baking_profiler.ml new file mode 100644 index 0000000000000000000000000000000000000000..2dc54c31b5e2e59fe92d69aeaee218f52e8d7e31 --- /dev/null +++ b/src/proto_020_PsParisC/lib_delegate/baking_profiler.ml @@ -0,0 +1,29 @@ +(*****************************************************************************) +(* *) +(* SPDX-License-Identifier: MIT *) +(* SPDX-FileCopyrightText: 2024 Nomadic Labs *) +(* *) +(*****************************************************************************) + +open Profiler + +let nonce_profiler = unplugged () + +let node_rpc_profiler = unplugged () + +let init profiler_maker = + plug nonce_profiler (profiler_maker ~name:"nonce") ; + plug node_rpc_profiler (profiler_maker ~name:"node_rpc") + +let create_reset_block_section profiler = + let last_block = ref None in + fun b -> + match !last_block with + | None -> + record profiler (Block_hash.to_b58check b) ; + last_block := Some b + | Some b' when Block_hash.equal b' b -> () + | Some _ -> + stop profiler ; + record profiler (Block_hash.to_b58check b) ; + last_block := Some b diff --git a/src/proto_020_PsParisC/lib_delegate/client_daemon.ml b/src/proto_020_PsParisC/lib_delegate/client_daemon.ml index a51235b8547b16baa1e9a44b79e72484cef579a2..8e176054faf2e155efa99019829e158d412d9f26 100644 --- a/src/proto_020_PsParisC/lib_delegate/client_daemon.ml +++ b/src/proto_020_PsParisC/lib_delegate/client_daemon.ml @@ -56,6 +56,23 @@ let await_protocol_start (cctxt : #Protocol_client_context.full) ~chain = in Node_rpc.await_protocol_activation cctxt ~chain () +let may_start_profiler baking_dir = + match Option.map String.lowercase_ascii @@ Sys.getenv_opt "PROFILING" with + | Some (("true" | "on" | "yes" | "terse" | "detailed" | "verbose") as mode) -> + let max_lod = + match mode with + | "detailed" -> Profiler.Detailed + | "verbose" -> Profiler.Verbose + | _ -> Profiler.Terse + in + let profiler_maker ~name = + Profiler.instance + Tezos_base_unix.Simple_profiler.auto_write_to_txt_file + Filename.Infix.((baking_dir // name) ^ "_profiling.txt", max_lod) + in + Baking_profiler.init profiler_maker + | _ -> () + module Baker = struct let run (cctxt : Protocol_client_context.full) ?minimal_fees ?minimal_nanotez_per_gas_unit ?minimal_nanotez_per_byte ?votes @@ -134,6 +151,7 @@ module Baker = struct let*! _ = Lwt_canceler.cancel canceler in Lwt.return_unit) in + let () = may_start_profiler cctxt#get_base_dir in let consumer = Protocol_logging.make_log_message_consumer () in Lifted_protocol.set_log_message_consumer consumer ; Baking_scheduling.run cctxt ~canceler ~chain ~constants config delegates diff --git a/src/proto_020_PsParisC/lib_delegate/dune b/src/proto_020_PsParisC/lib_delegate/dune index 955aba951667d9edea4d8ca433c428e30a07bfe0..79d0086bde7599564b2a7d85cdedf209b0b90d5a 100644 --- a/src/proto_020_PsParisC/lib_delegate/dune +++ b/src/proto_020_PsParisC/lib_delegate/dune @@ -30,6 +30,8 @@ lwt-canceler lwt-exit uri) + (preprocess (pps octez-libs.ppx_profiler)) + (preprocessor_deps (env_var TEZOS_PPX_PROFILER)) (library_flags (:standard -linkall)) (flags (:standard) diff --git a/src/proto_020_PsParisC/lib_delegate/node_rpc.ml b/src/proto_020_PsParisC/lib_delegate/node_rpc.ml index 8538f928049fad188619d723ba15107be9d1ba53..f7bee5a8b44e89cff50f0d8fd1bfd83abe26e867 100644 --- a/src/proto_020_PsParisC/lib_delegate/node_rpc.ml +++ b/src/proto_020_PsParisC/lib_delegate/node_rpc.ml @@ -30,6 +30,13 @@ open Baking_state module Block_services = Block_services.Make (Protocol) (Protocol) module Events = Baking_events.Node_rpc +module Profiler = struct + include (val Profiler.wrap Baking_profiler.node_rpc_profiler) + + let[@warning "-32"] reset_block_section = + Baking_profiler.create_reset_block_section Baking_profiler.node_rpc_profiler +end + let inject_block cctxt ?(force = false) ~chain signed_block_header operations = let signed_shell_header_bytes = Data_encoding.Binary.to_bytes_exn Block_header.encoding signed_block_header @@ -99,9 +106,10 @@ let info_of_header_and_ops ~in_protocol block_hash block_header operations = | None -> assert false in let preattestations, quorum, payload = - WithExceptions.Option.get - ~loc:__LOC__ - (Operation_pool.extract_operations_of_list_list operations) + (WithExceptions.Option.get + ~loc:__LOC__ + (Operation_pool.extract_operations_of_list_list operations) + [@profiler.record_f "operations classification"]) in let prequorum = Option.bind preattestations extract_prequorum in (payload_hash, payload_round, prequorum, quorum, payload) @@ -121,43 +129,60 @@ let info_of_header_and_ops ~in_protocol block_hash block_header operations = let compute_block_info cctxt ~in_protocol ?operations ~chain block_hash block_header = let open Lwt_result_syntax in - let* operations = - match operations with - | None when not in_protocol -> return_nil - | None -> - let open Protocol_client_context in - let* operations = - Alpha_block_services.Operations.operations - cctxt - ~chain - ~block:(`Hash (block_hash, 0)) - () - in - let packed_operations = - List.map - (fun l -> - List.map - (fun {Alpha_block_services.shell; protocol_data; _} -> - {Alpha_context.shell; protocol_data}) - l) - operations - in - return packed_operations - | Some operations -> - let parse_op (raw_op : Tezos_base.Operation.t) = - let protocol_data = - Data_encoding.Binary.of_bytes_exn - Operation.protocol_data_encoding - raw_op.proto + (let* operations = + match operations with + | None when not in_protocol -> return_nil + | None -> + let open Protocol_client_context in + (let* operations = + Alpha_block_services.Operations.operations + cctxt + ~chain + ~block:(`Hash (block_hash, 0)) + () in - {shell = raw_op.shell; protocol_data} - in - protect @@ fun () -> return (List.map (List.map parse_op) operations) - in - let*? block_info = - info_of_header_and_ops ~in_protocol block_hash block_header operations - in - return block_info + let packed_operations = + List.map + (fun l -> + List.map + (fun {Alpha_block_services.shell; protocol_data; _} -> + {Alpha_context.shell; protocol_data}) + l) + operations + in + return packed_operations) + [@profiler.record_s + "retrieve block " + ^ Block_hash.to_short_b58check block_hash + ^ " operations"] + | Some operations -> + let parse_op (raw_op : Tezos_base.Operation.t) = + let protocol_data = + (Data_encoding.Binary.of_bytes_exn + Operation.protocol_data_encoding + raw_op.proto [@profiler.aggregate_f "parse operation"]) + in + {shell = raw_op.shell; protocol_data} + in + protect @@ fun () -> + return + (List.mapi + (fun [@warning "-27"] i -> function + | [] -> [] + | l -> + List.map + parse_op + l + [@profiler.record_f + Printf.sprintf "parse operations (pass:%d)" i]) + operations) + in + let*? block_info = + info_of_header_and_ops ~in_protocol block_hash block_header operations + in + return block_info) + [@profiler.record_s + "compute block " ^ Block_hash.to_short_b58check block_hash ^ " info"] let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain block_hash (block_header : Tezos_base.Block_header.t) = @@ -170,15 +195,33 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain let* is_proposal_in_protocol, predecessor = match predecessor_opt with | Some predecessor -> + () + [@profiler.mark + [ + "pred_block(" + ^ Block_hash.to_short_b58check predecessor_hash + ^ "):cache_hit"; + ]] ; return ( predecessor.shell.proto_level = block_header.shell.proto_level, predecessor ) | None -> + () + [@profiler.mark + [ + "pred_block(" + ^ Block_hash.to_short_b58check predecessor_hash + ^ "):cache_miss"; + ]] ; let* { current_protocol = pred_current_protocol; next_protocol = pred_next_protocol; } = - Shell_services.Blocks.protocols cctxt ~chain ~block:pred_block () + (Shell_services.Blocks.protocols + cctxt + ~chain + ~block:pred_block + () [@profiler.record_s "pred block protocol RPC"]) in let is_proposal_in_protocol = Protocol_hash.(pred_next_protocol = Protocol.hash) @@ -191,9 +234,9 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain Shell_services.Blocks.raw_header cctxt ~chain ~block:pred_block () in let predecessor_header = - Data_encoding.Binary.of_bytes_exn - Tezos_base.Block_header.encoding - raw_header_b + (Data_encoding.Binary.of_bytes_exn + Tezos_base.Block_header.encoding + raw_header_b [@profiler.record_f "parse pred block header"]) in compute_block_info cctxt @@ -212,8 +255,19 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain in let* block = match block_opt with - | Some pi -> return pi + | Some pi -> + () + [@profiler.mark + ["new_block(" ^ Block_hash.to_short_b58check pi.hash ^ "):cache_hit"]] ; + return pi | None -> + () + [@profiler.mark + [ + "new_block(" + ^ Block_hash.to_short_b58check block_hash + ^ "):cache_miss"; + ]] ; let* pi = compute_block_info cctxt @@ -229,8 +283,9 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain return {block; predecessor} let proposal cctxt ?cache ?operations ~chain block_hash block_header = - protect @@ fun () -> - proposal cctxt ?cache ?operations ~chain block_hash block_header + ( (protect @@ fun () -> + proposal cctxt ?cache ?operations ~chain block_hash block_header) + [@profiler.record_s "proposal_computation"] ) let monitor_valid_proposals cctxt ~chain ?cache () = let open Lwt_result_syntax in @@ -240,14 +295,18 @@ let monitor_valid_proposals cctxt ~chain ?cache () = in let stream = let map (_chain_id, block_hash, block_header, operations) = - let*! map_result = - proposal cctxt ?cache ~operations ~chain block_hash block_header - in - match map_result with - | Ok proposal -> Lwt.return_some proposal - | Error err -> - let*! () = Events.(emit error_while_monitoring_valid_proposals err) in - Lwt.return_none + () [@profiler.reset_block_section block_hash] ; + (let*! map_result = + proposal cctxt ?cache ~operations ~chain block_hash block_header + in + match map_result with + | Ok proposal -> Lwt.return_some proposal + | Error err -> + let*! () = + Events.(emit error_while_monitoring_valid_proposals err) + in + Lwt.return_none) + [@profiler.record_s "received valid proposal"] in Lwt_stream.filter_map_s map block_stream in @@ -261,12 +320,16 @@ let monitor_heads cctxt ~chain ?cache () = in let stream = let map (block_hash, block_header) = - let*! map_result = proposal cctxt ?cache ~chain block_hash block_header in - match map_result with - | Ok proposal -> Lwt.return_some proposal - | Error err -> - let*! () = Events.(emit error_while_monitoring_heads err) in - Lwt.return_none + () [@profiler.reset_block_section block_hash] ; + (let*! map_result = + proposal cctxt ?cache ~chain block_hash block_header + in + match map_result with + | Ok proposal -> Lwt.return_some proposal + | Error err -> + let*! () = Events.(emit error_while_monitoring_heads err) in + Lwt.return_none) + [@profiler.record_s "received new head"] in Lwt_stream.filter_map_s map block_stream in diff --git a/src/proto_021_PsquebeC/lib_delegate/baking_nonces.ml b/src/proto_021_PsquebeC/lib_delegate/baking_nonces.ml index 7d38c52f8db91ab70ccf0e04b246115398c73bb6..3be004b700e0ba95efadccb6cff8404585c3a0c6 100644 --- a/src/proto_021_PsquebeC/lib_delegate/baking_nonces.ml +++ b/src/proto_021_PsquebeC/lib_delegate/baking_nonces.ml @@ -28,6 +28,8 @@ open Protocol open Alpha_context module Events = Baking_events.Nonces +module Profiler = (val Profiler.wrap Baking_profiler.nonce_profiler) + type state = { cctxt : Protocol_client_context.full; chain : Chain_services.chain; @@ -328,7 +330,10 @@ let partition_unrevealed_nonces {cctxt; chain; _} nonces current_cycle | cycle when Cycle.(cycle = previous_cycle) -> ( (* Only process nonces that are part of previous cycle. *) let+ nonce_info = - Alpha_services.Nonce.get cctxt (chain, `Head 0) level + (Alpha_services.Nonce.get + cctxt + (chain, `Head 0) + level [@profiler.aggregate_s "get nonce information"]) in match (nonce_state, nonce_info) with | Committed, Missing expected_nonce_hash @@ -390,34 +395,42 @@ let generate_seed_nonce (nonce_config : Baking_configuration.nonce_config) let register_nonce (cctxt : #Protocol_client_context.full) ~chain_id block_hash nonce ~cycle ~level ~round = let open Lwt_result_syntax in - let*! () = Events.(emit registering_nonce block_hash) in - (* Register the nonce *) - let legacy_location = Baking_files.resolve_location ~chain_id `Legacy_nonce in - let stateful_location = - Baking_files.resolve_location ~chain_id `Stateful_nonce - in - let orphaned_location = - Baking_files.resolve_location ~chain_id `Orphaned_nonce - in - cctxt#with_lock @@ fun () -> - let* nonces = load cctxt ~stateful_location in - let nonces = - add + (let*! () = Events.(emit registering_nonce block_hash) in + (* Register the nonce *) + let legacy_location = + Baking_files.resolve_location ~chain_id `Legacy_nonce + in + let stateful_location = + Baking_files.resolve_location ~chain_id `Stateful_nonce + in + let orphaned_location = + Baking_files.resolve_location ~chain_id `Orphaned_nonce + in + () [@profiler.record_f "waiting lock"] ; + cctxt#with_lock @@ fun () -> + let* nonces = + (load cctxt ~stateful_location [@profiler.record_s "load nonces"]) + in + let nonces = + (add + nonces + { + nonce; + nonce_hash = Nonce.hash nonce; + block_hash; + cycle; + level; + round = Some round; + nonce_state = Committed; + } [@profiler.record_f "add nonces"]) + in + (save + cctxt + ~legacy_location + ~stateful_location nonces - { - nonce; - nonce_hash = Nonce.hash nonce; - block_hash; - cycle; - level; - round = Some round; - nonce_state = Committed; - } - in - let* () = - save cctxt ~legacy_location ~stateful_location nonces ~orphaned_location - in - return_unit + ~orphaned_location [@profiler.record_s "save nonces"])) + [@profiler.record_s "register nonce"] (** [inject_seed_nonce_revelation cctxt ~chain ~block ~branch nonces] forges one [Seed_nonce_revelation] operation per each nonce to be revealed, together with @@ -433,17 +446,21 @@ let inject_seed_nonce_revelation (cctxt : #Protocol_client_context.full) ~chain List.iter_es (fun (level, nonce) -> let* bytes = - Plugin.RPC.Forge.seed_nonce_revelation - cctxt - (chain, block) - ~branch - ~level - ~nonce - () + (Plugin.RPC.Forge.seed_nonce_revelation + cctxt + (chain, block) + ~branch + ~level + ~nonce + () [@profiler.aggregate_s "forge seed nonce revelation"]) in let bytes = Signature.concat bytes Signature.zero in let* oph = - Shell_services.Injection.operation ~async:true cctxt ~chain bytes + (Shell_services.Injection.operation + ~async:true + cctxt + ~chain + bytes [@profiler.aggregate_s "inject seed nonce revelation"]) in let*! () = Events.( @@ -480,8 +497,11 @@ let reveal_potential_nonces state new_proposal = let block = `Head 0 in let branch = new_predecessor_hash in (* improve concurrency *) + () [@profiler.record_f "waiting lock"] ; cctxt#with_lock @@ fun () -> - let*! nonces = load cctxt ~stateful_location in + let*! nonces = + (load cctxt ~stateful_location [@profiler.record_s "load nonce file"]) + in match nonces with | Error err -> let*! () = Events.(emit cannot_read_nonces err) in @@ -491,7 +511,11 @@ let reveal_potential_nonces state new_proposal = Plugin.RPC.current_level cctxt (chain, `Head 0) in let*! partitioned_nonces = - partition_unrevealed_nonces state nonces cycle level + (partition_unrevealed_nonces + state + nonces + cycle + level [@profiler.record_s "partition unrevealed nonces"]) in match partitioned_nonces with | Error err -> @@ -507,12 +531,13 @@ let reveal_potential_nonces state new_proposal = [] in let*! result = - inject_seed_nonce_revelation - cctxt - ~chain - ~block - ~branch - prepared_nonces + (inject_seed_nonce_revelation + cctxt + ~chain + ~block + ~branch + prepared_nonces + [@profiler.record_s "inject seed nonce revelation"]) in match result with | Error err -> @@ -531,15 +556,12 @@ let reveal_potential_nonces state new_proposal = nonce_with_new_states live_nonces in - let* () = - save - cctxt - ~legacy_location - ~stateful_location - ~orphaned_location - updated_nonces - in - return_unit))) + (save + cctxt + ~legacy_location + ~stateful_location + ~orphaned_location + updated_nonces [@profiler.record_s "save nonces"])))) else return_unit (* We suppose that the block stream is cloned by the caller *) @@ -570,6 +592,7 @@ let start_revelation_worker cctxt config chain_id constants block_stream = format. *) let* () = try_migrate_legacy_nonces state in + let last_proposal = ref None in let rec worker_loop () = Lwt_canceler.on_cancel canceler (fun () -> should_shutdown := true ; @@ -581,9 +604,18 @@ let start_revelation_worker cctxt config chain_id constants block_stream = with the node was interrupted: exit *) return_unit | Some new_proposal -> + Option.iter (fun _ -> (() [@profiler.stop])) !last_proposal ; + () + [@profiler.record + Block_hash.to_b58check new_proposal.Baking_state.block.hash] ; + last_proposal := Some new_proposal.Baking_state.block.hash ; if !should_shutdown then return_unit else - let* _ = reveal_potential_nonces state new_proposal in + let* _ = + (reveal_potential_nonces + state + new_proposal [@profiler.record_s "reveal potential nonces"]) + in worker_loop () in Lwt.dont_wait diff --git a/src/proto_021_PsquebeC/lib_delegate/baking_profiler.ml b/src/proto_021_PsquebeC/lib_delegate/baking_profiler.ml new file mode 100644 index 0000000000000000000000000000000000000000..2dc54c31b5e2e59fe92d69aeaee218f52e8d7e31 --- /dev/null +++ b/src/proto_021_PsquebeC/lib_delegate/baking_profiler.ml @@ -0,0 +1,29 @@ +(*****************************************************************************) +(* *) +(* SPDX-License-Identifier: MIT *) +(* SPDX-FileCopyrightText: 2024 Nomadic Labs *) +(* *) +(*****************************************************************************) + +open Profiler + +let nonce_profiler = unplugged () + +let node_rpc_profiler = unplugged () + +let init profiler_maker = + plug nonce_profiler (profiler_maker ~name:"nonce") ; + plug node_rpc_profiler (profiler_maker ~name:"node_rpc") + +let create_reset_block_section profiler = + let last_block = ref None in + fun b -> + match !last_block with + | None -> + record profiler (Block_hash.to_b58check b) ; + last_block := Some b + | Some b' when Block_hash.equal b' b -> () + | Some _ -> + stop profiler ; + record profiler (Block_hash.to_b58check b) ; + last_block := Some b diff --git a/src/proto_021_PsquebeC/lib_delegate/client_daemon.ml b/src/proto_021_PsquebeC/lib_delegate/client_daemon.ml index 0acfd412a565327765f3ab6d0bdf4a72cec9b748..f9619e202b0474213236a495ee73d67538390bb2 100644 --- a/src/proto_021_PsquebeC/lib_delegate/client_daemon.ml +++ b/src/proto_021_PsquebeC/lib_delegate/client_daemon.ml @@ -56,6 +56,23 @@ let await_protocol_start (cctxt : #Protocol_client_context.full) ~chain = in Node_rpc.await_protocol_activation cctxt ~chain () +let may_start_profiler baking_dir = + match Option.map String.lowercase_ascii @@ Sys.getenv_opt "PROFILING" with + | Some (("true" | "on" | "yes" | "terse" | "detailed" | "verbose") as mode) -> + let max_lod = + match mode with + | "detailed" -> Profiler.Detailed + | "verbose" -> Profiler.Verbose + | _ -> Profiler.Terse + in + let profiler_maker ~name = + Profiler.instance + Tezos_base_unix.Simple_profiler.auto_write_to_txt_file + Filename.Infix.((baking_dir // name) ^ "_profiling.txt", max_lod) + in + Baking_profiler.init profiler_maker + | _ -> () + module Baker = struct let run (cctxt : Protocol_client_context.full) ?minimal_fees ?minimal_nanotez_per_gas_unit ?minimal_nanotez_per_byte ?votes @@ -134,6 +151,7 @@ module Baker = struct let*! _ = Lwt_canceler.cancel canceler in Lwt.return_unit) in + let () = may_start_profiler cctxt#get_base_dir in let consumer = Protocol_logging.make_log_message_consumer () in Lifted_protocol.set_log_message_consumer consumer ; Baking_scheduling.run cctxt ~canceler ~chain ~constants config delegates diff --git a/src/proto_021_PsquebeC/lib_delegate/dune b/src/proto_021_PsquebeC/lib_delegate/dune index 7b0e41b44ffcf8337268afd6762910ac3d3fc280..4a35ee19283485e925fcbebec3f0b68d7c7450ed 100644 --- a/src/proto_021_PsquebeC/lib_delegate/dune +++ b/src/proto_021_PsquebeC/lib_delegate/dune @@ -29,6 +29,8 @@ lwt-canceler lwt-exit uri) + (preprocess (pps octez-libs.ppx_profiler)) + (preprocessor_deps (env_var TEZOS_PPX_PROFILER)) (library_flags (:standard -linkall)) (flags (:standard) diff --git a/src/proto_021_PsquebeC/lib_delegate/node_rpc.ml b/src/proto_021_PsquebeC/lib_delegate/node_rpc.ml index 8538f928049fad188619d723ba15107be9d1ba53..bd5fe2e76f36e25f798762770af70400eb47a4c9 100644 --- a/src/proto_021_PsquebeC/lib_delegate/node_rpc.ml +++ b/src/proto_021_PsquebeC/lib_delegate/node_rpc.ml @@ -2,6 +2,7 @@ (* *) (* Open Source License *) (* Copyright (c) 2020 Nomadic Labs *) +(* Copyright (c) 2023 Marigold *) (* *) (* Permission is hereby granted, free of charge, to any person obtaining a *) (* copy of this software and associated documentation files (the "Software"),*) @@ -30,6 +31,13 @@ open Baking_state module Block_services = Block_services.Make (Protocol) (Protocol) module Events = Baking_events.Node_rpc +module Profiler = struct + include (val Profiler.wrap Baking_profiler.node_rpc_profiler) + + let[@warning "-32"] reset_block_section = + Baking_profiler.create_reset_block_section Baking_profiler.node_rpc_profiler +end + let inject_block cctxt ?(force = false) ~chain signed_block_header operations = let signed_shell_header_bytes = Data_encoding.Binary.to_bytes_exn Block_header.encoding signed_block_header @@ -99,9 +107,10 @@ let info_of_header_and_ops ~in_protocol block_hash block_header operations = | None -> assert false in let preattestations, quorum, payload = - WithExceptions.Option.get - ~loc:__LOC__ - (Operation_pool.extract_operations_of_list_list operations) + (WithExceptions.Option.get + ~loc:__LOC__ + (Operation_pool.extract_operations_of_list_list operations) + [@profiler.record_f "operations classification"]) in let prequorum = Option.bind preattestations extract_prequorum in (payload_hash, payload_round, prequorum, quorum, payload) @@ -121,43 +130,60 @@ let info_of_header_and_ops ~in_protocol block_hash block_header operations = let compute_block_info cctxt ~in_protocol ?operations ~chain block_hash block_header = let open Lwt_result_syntax in - let* operations = - match operations with - | None when not in_protocol -> return_nil - | None -> - let open Protocol_client_context in - let* operations = - Alpha_block_services.Operations.operations - cctxt - ~chain - ~block:(`Hash (block_hash, 0)) - () - in - let packed_operations = - List.map - (fun l -> - List.map - (fun {Alpha_block_services.shell; protocol_data; _} -> - {Alpha_context.shell; protocol_data}) - l) - operations - in - return packed_operations - | Some operations -> - let parse_op (raw_op : Tezos_base.Operation.t) = - let protocol_data = - Data_encoding.Binary.of_bytes_exn - Operation.protocol_data_encoding - raw_op.proto + (let* operations = + match operations with + | None when not in_protocol -> return_nil + | None -> + let open Protocol_client_context in + (let* operations = + Alpha_block_services.Operations.operations + cctxt + ~chain + ~block:(`Hash (block_hash, 0)) + () in - {shell = raw_op.shell; protocol_data} - in - protect @@ fun () -> return (List.map (List.map parse_op) operations) - in - let*? block_info = - info_of_header_and_ops ~in_protocol block_hash block_header operations - in - return block_info + let packed_operations = + List.map + (fun l -> + List.map + (fun {Alpha_block_services.shell; protocol_data; _} -> + {Alpha_context.shell; protocol_data}) + l) + operations + in + return packed_operations) + [@profiler.record_s + "retrieve block " + ^ Block_hash.to_short_b58check block_hash + ^ " operations"] + | Some operations -> + let parse_op (raw_op : Tezos_base.Operation.t) = + let protocol_data = + (Data_encoding.Binary.of_bytes_exn + Operation.protocol_data_encoding + raw_op.proto [@profiler.aggregate_f "parse operation"]) + in + {shell = raw_op.shell; protocol_data} + in + protect @@ fun () -> + return + (List.mapi + (fun [@warning "-27"] i -> function + | [] -> [] + | l -> + List.map + parse_op + l + [@profiler.record_f + Printf.sprintf "parse operations (pass:%d)" i]) + operations) + in + let*? block_info = + info_of_header_and_ops ~in_protocol block_hash block_header operations + in + return block_info) + [@profiler.record_s + "compute block " ^ Block_hash.to_short_b58check block_hash ^ " info"] let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain block_hash (block_header : Tezos_base.Block_header.t) = @@ -170,15 +196,33 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain let* is_proposal_in_protocol, predecessor = match predecessor_opt with | Some predecessor -> + () + [@profiler.mark + [ + "pred_block(" + ^ Block_hash.to_short_b58check predecessor_hash + ^ "):cache_hit"; + ]] ; return ( predecessor.shell.proto_level = block_header.shell.proto_level, predecessor ) | None -> + () + [@profiler.mark + [ + "pred_block(" + ^ Block_hash.to_short_b58check predecessor_hash + ^ "):cache_miss"; + ]] ; let* { current_protocol = pred_current_protocol; next_protocol = pred_next_protocol; } = - Shell_services.Blocks.protocols cctxt ~chain ~block:pred_block () + (Shell_services.Blocks.protocols + cctxt + ~chain + ~block:pred_block + () [@profiler.record_s "pred block protocol RPC"]) in let is_proposal_in_protocol = Protocol_hash.(pred_next_protocol = Protocol.hash) @@ -191,9 +235,9 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain Shell_services.Blocks.raw_header cctxt ~chain ~block:pred_block () in let predecessor_header = - Data_encoding.Binary.of_bytes_exn - Tezos_base.Block_header.encoding - raw_header_b + (Data_encoding.Binary.of_bytes_exn + Tezos_base.Block_header.encoding + raw_header_b [@profiler.record_f "parse pred block header"]) in compute_block_info cctxt @@ -212,8 +256,19 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain in let* block = match block_opt with - | Some pi -> return pi + | Some pi -> + () + [@profiler.mark + ["new_block(" ^ Block_hash.to_short_b58check pi.hash ^ "):cache_hit"]] ; + return pi | None -> + () + [@profiler.mark + [ + "new_block(" + ^ Block_hash.to_short_b58check block_hash + ^ "):cache_miss"; + ]] ; let* pi = compute_block_info cctxt @@ -229,8 +284,9 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain return {block; predecessor} let proposal cctxt ?cache ?operations ~chain block_hash block_header = - protect @@ fun () -> - proposal cctxt ?cache ?operations ~chain block_hash block_header + ( (protect @@ fun () -> + proposal cctxt ?cache ?operations ~chain block_hash block_header) + [@profiler.record_s "proposal_computation"] ) let monitor_valid_proposals cctxt ~chain ?cache () = let open Lwt_result_syntax in @@ -240,14 +296,18 @@ let monitor_valid_proposals cctxt ~chain ?cache () = in let stream = let map (_chain_id, block_hash, block_header, operations) = - let*! map_result = - proposal cctxt ?cache ~operations ~chain block_hash block_header - in - match map_result with - | Ok proposal -> Lwt.return_some proposal - | Error err -> - let*! () = Events.(emit error_while_monitoring_valid_proposals err) in - Lwt.return_none + () [@profiler.reset_block_section block_hash] ; + (let*! map_result = + proposal cctxt ?cache ~operations ~chain block_hash block_header + in + match map_result with + | Ok proposal -> Lwt.return_some proposal + | Error err -> + let*! () = + Events.(emit error_while_monitoring_valid_proposals err) + in + Lwt.return_none) + [@profiler.record_s "received valid proposal"] in Lwt_stream.filter_map_s map block_stream in @@ -261,12 +321,16 @@ let monitor_heads cctxt ~chain ?cache () = in let stream = let map (block_hash, block_header) = - let*! map_result = proposal cctxt ?cache ~chain block_hash block_header in - match map_result with - | Ok proposal -> Lwt.return_some proposal - | Error err -> - let*! () = Events.(emit error_while_monitoring_heads err) in - Lwt.return_none + () [@profiler.reset_block_section block_hash] ; + (let*! map_result = + proposal cctxt ?cache ~chain block_hash block_header + in + match map_result with + | Ok proposal -> Lwt.return_some proposal + | Error err -> + let*! () = Events.(emit error_while_monitoring_heads err) in + Lwt.return_none) + [@profiler.record_s "received new head"] in Lwt_stream.filter_map_s map block_stream in diff --git a/src/proto_alpha/lib_delegate/baking_nonces.ml b/src/proto_alpha/lib_delegate/baking_nonces.ml index b1309f6cfe704561974e7fae3706bd462c866ec3..d21e83926c8a2ffb0267a646d319f28b702669a6 100644 --- a/src/proto_alpha/lib_delegate/baking_nonces.ml +++ b/src/proto_alpha/lib_delegate/baking_nonces.ml @@ -28,6 +28,8 @@ open Protocol open Alpha_context module Events = Baking_events.Nonces +module Profiler = (val Profiler.wrap Baking_profiler.nonce_profiler) + type state = { cctxt : Protocol_client_context.full; chain : Chain_services.chain; @@ -333,7 +335,10 @@ let partition_unrevealed_nonces {cctxt; chain; _} nonces nonce_revelation_threshold has not passed. See [Nonce_storage.check_unrevealed] *) let+ nonce_info = - Alpha_services.Nonce.get cctxt (chain, `Head 0) level + (Alpha_services.Nonce.get + cctxt + (chain, `Head 0) + level [@profiler.aggregate_s "get nonce information"]) in match (nonce_state, nonce_info) with | Committed, Missing expected_nonce_hash @@ -395,34 +400,42 @@ let generate_seed_nonce (nonce_config : Baking_configuration.nonce_config) let register_nonce (cctxt : #Protocol_client_context.full) ~chain_id block_hash nonce ~cycle ~level ~round = let open Lwt_result_syntax in - let*! () = Events.(emit registering_nonce block_hash) in - (* Register the nonce *) - let legacy_location = Baking_files.resolve_location ~chain_id `Legacy_nonce in - let stateful_location = - Baking_files.resolve_location ~chain_id `Stateful_nonce - in - let orphaned_location = - Baking_files.resolve_location ~chain_id `Orphaned_nonce - in - cctxt#with_lock @@ fun () -> - let* nonces = load cctxt ~stateful_location in - let nonces = - add + (let*! () = Events.(emit registering_nonce block_hash) in + (* Register the nonce *) + let legacy_location = + Baking_files.resolve_location ~chain_id `Legacy_nonce + in + let stateful_location = + Baking_files.resolve_location ~chain_id `Stateful_nonce + in + let orphaned_location = + Baking_files.resolve_location ~chain_id `Orphaned_nonce + in + () [@profiler.record_f "waiting lock"] ; + cctxt#with_lock @@ fun () -> + let* nonces = + (load cctxt ~stateful_location [@profiler.record_s "load nonces"]) + in + let nonces = + (add + nonces + { + nonce; + nonce_hash = Nonce.hash nonce; + block_hash; + cycle; + level; + round = Some round; + nonce_state = Committed; + } [@profiler.record_f "add nonces"]) + in + (save + cctxt + ~legacy_location + ~stateful_location nonces - { - nonce; - nonce_hash = Nonce.hash nonce; - block_hash; - cycle; - level; - round = Some round; - nonce_state = Committed; - } - in - let* () = - save cctxt ~legacy_location ~stateful_location nonces ~orphaned_location - in - return_unit + ~orphaned_location [@profiler.record_s "save nonces"])) + [@profiler.record_s "register nonce"] (** [inject_seed_nonce_revelation cctxt ~chain ~block ~branch nonces] forges one [Seed_nonce_revelation] operation per each nonce to be revealed, together with @@ -438,17 +451,21 @@ let inject_seed_nonce_revelation (cctxt : #Protocol_client_context.full) ~chain List.iter_es (fun (level, nonce) -> let* bytes = - Plugin.RPC.Forge.seed_nonce_revelation - cctxt - (chain, block) - ~branch - ~level - ~nonce - () + (Plugin.RPC.Forge.seed_nonce_revelation + cctxt + (chain, block) + ~branch + ~level + ~nonce + () [@profiler.aggregate_s "forge seed nonce revelation"]) in let bytes = Signature.concat bytes Signature.zero in let* oph = - Shell_services.Injection.operation ~async:true cctxt ~chain bytes + (Shell_services.Injection.operation + ~async:true + cctxt + ~chain + bytes [@profiler.aggregate_s "inject seed nonce revelation"]) in let*! () = Events.( @@ -485,8 +502,11 @@ let reveal_potential_nonces state (new_proposal : Baking_state.proposal) = let block = `Head 0 in let branch = new_predecessor_hash in (* improve concurrency *) + () [@profiler.record_f "waiting lock"] ; cctxt#with_lock @@ fun () -> - let*! nonces = load cctxt ~stateful_location in + let*! nonces = + (load cctxt ~stateful_location [@profiler.record_s "load nonce file"]) + in match nonces with | Error err -> let*! () = Events.(emit cannot_read_nonces err) in @@ -494,11 +514,12 @@ let reveal_potential_nonces state (new_proposal : Baking_state.proposal) = | Ok nonces -> ( let* current_level = Plugin.RPC.current_level cctxt (chain, `Head 0) in let*! partitioned_nonces = - partition_unrevealed_nonces - state - nonces - current_level - state.constants.parametric.nonce_revelation_threshold + (partition_unrevealed_nonces + state + nonces + current_level + state.constants.parametric.nonce_revelation_threshold + [@profiler.record_s "partition unrevealed nonces"]) in match partitioned_nonces with | Error err -> @@ -514,12 +535,13 @@ let reveal_potential_nonces state (new_proposal : Baking_state.proposal) = [] in let*! result = - inject_seed_nonce_revelation - cctxt - ~chain - ~block - ~branch - prepared_nonces + (inject_seed_nonce_revelation + cctxt + ~chain + ~block + ~branch + prepared_nonces + [@profiler.record_s "inject seed nonce revelation"]) in match result with | Error err -> @@ -541,15 +563,12 @@ let reveal_potential_nonces state (new_proposal : Baking_state.proposal) = nonce_with_new_states live_nonces in - let* () = - save - cctxt - ~legacy_location - ~stateful_location - ~orphaned_location - updated_nonces - in - return_unit))) + (save + cctxt + ~legacy_location + ~stateful_location + ~orphaned_location + updated_nonces [@profiler.record_s "save nonces"])))) else return_unit (* We suppose that the block stream is cloned by the caller *) @@ -580,6 +599,7 @@ let start_revelation_worker cctxt config chain_id constants block_stream = format. *) let* () = try_migrate_legacy_nonces state in + let last_proposal = ref None in let rec worker_loop () = Lwt_canceler.on_cancel canceler (fun () -> should_shutdown := true ; @@ -591,9 +611,18 @@ let start_revelation_worker cctxt config chain_id constants block_stream = with the node was interrupted: exit *) return_unit | Some new_proposal -> + Option.iter (fun _ -> (() [@profiler.stop])) !last_proposal ; + () + [@profiler.record + Block_hash.to_b58check new_proposal.Baking_state.block.hash] ; + last_proposal := Some new_proposal.Baking_state.block.hash ; if !should_shutdown then return_unit else - let* _ = reveal_potential_nonces state new_proposal in + let* _ = + (reveal_potential_nonces + state + new_proposal [@profiler.record_s "reveal potential nonces"]) + in worker_loop () in Lwt.dont_wait diff --git a/src/proto_alpha/lib_delegate/baking_profiler.ml b/src/proto_alpha/lib_delegate/baking_profiler.ml new file mode 100644 index 0000000000000000000000000000000000000000..2dc54c31b5e2e59fe92d69aeaee218f52e8d7e31 --- /dev/null +++ b/src/proto_alpha/lib_delegate/baking_profiler.ml @@ -0,0 +1,29 @@ +(*****************************************************************************) +(* *) +(* SPDX-License-Identifier: MIT *) +(* SPDX-FileCopyrightText: 2024 Nomadic Labs *) +(* *) +(*****************************************************************************) + +open Profiler + +let nonce_profiler = unplugged () + +let node_rpc_profiler = unplugged () + +let init profiler_maker = + plug nonce_profiler (profiler_maker ~name:"nonce") ; + plug node_rpc_profiler (profiler_maker ~name:"node_rpc") + +let create_reset_block_section profiler = + let last_block = ref None in + fun b -> + match !last_block with + | None -> + record profiler (Block_hash.to_b58check b) ; + last_block := Some b + | Some b' when Block_hash.equal b' b -> () + | Some _ -> + stop profiler ; + record profiler (Block_hash.to_b58check b) ; + last_block := Some b diff --git a/src/proto_alpha/lib_delegate/client_daemon.ml b/src/proto_alpha/lib_delegate/client_daemon.ml index 0acfd412a565327765f3ab6d0bdf4a72cec9b748..f9619e202b0474213236a495ee73d67538390bb2 100644 --- a/src/proto_alpha/lib_delegate/client_daemon.ml +++ b/src/proto_alpha/lib_delegate/client_daemon.ml @@ -56,6 +56,23 @@ let await_protocol_start (cctxt : #Protocol_client_context.full) ~chain = in Node_rpc.await_protocol_activation cctxt ~chain () +let may_start_profiler baking_dir = + match Option.map String.lowercase_ascii @@ Sys.getenv_opt "PROFILING" with + | Some (("true" | "on" | "yes" | "terse" | "detailed" | "verbose") as mode) -> + let max_lod = + match mode with + | "detailed" -> Profiler.Detailed + | "verbose" -> Profiler.Verbose + | _ -> Profiler.Terse + in + let profiler_maker ~name = + Profiler.instance + Tezos_base_unix.Simple_profiler.auto_write_to_txt_file + Filename.Infix.((baking_dir // name) ^ "_profiling.txt", max_lod) + in + Baking_profiler.init profiler_maker + | _ -> () + module Baker = struct let run (cctxt : Protocol_client_context.full) ?minimal_fees ?minimal_nanotez_per_gas_unit ?minimal_nanotez_per_byte ?votes @@ -134,6 +151,7 @@ module Baker = struct let*! _ = Lwt_canceler.cancel canceler in Lwt.return_unit) in + let () = may_start_profiler cctxt#get_base_dir in let consumer = Protocol_logging.make_log_message_consumer () in Lifted_protocol.set_log_message_consumer consumer ; Baking_scheduling.run cctxt ~canceler ~chain ~constants config delegates diff --git a/src/proto_alpha/lib_delegate/dune b/src/proto_alpha/lib_delegate/dune index eee391da2a432cc8205e690c58f6e1de4a9985b5..986ffa20f167dae87638d5414c9260445466caa2 100644 --- a/src/proto_alpha/lib_delegate/dune +++ b/src/proto_alpha/lib_delegate/dune @@ -29,6 +29,8 @@ lwt-canceler lwt-exit uri) + (preprocess (pps octez-libs.ppx_profiler)) + (preprocessor_deps (env_var TEZOS_PPX_PROFILER)) (library_flags (:standard -linkall)) (flags (:standard) diff --git a/src/proto_alpha/lib_delegate/node_rpc.ml b/src/proto_alpha/lib_delegate/node_rpc.ml index 8538f928049fad188619d723ba15107be9d1ba53..f8e8807eaf5380a51730ce96fec71b7bf2ac402c 100644 --- a/src/proto_alpha/lib_delegate/node_rpc.ml +++ b/src/proto_alpha/lib_delegate/node_rpc.ml @@ -30,6 +30,13 @@ open Baking_state module Block_services = Block_services.Make (Protocol) (Protocol) module Events = Baking_events.Node_rpc +module Profiler = struct + include (val Profiler.wrap Baking_profiler.node_rpc_profiler) + + let[@warning "-32"] reset_block_section = + Baking_profiler.create_reset_block_section Baking_profiler.node_rpc_profiler +end + let inject_block cctxt ?(force = false) ~chain signed_block_header operations = let signed_shell_header_bytes = Data_encoding.Binary.to_bytes_exn Block_header.encoding signed_block_header @@ -99,9 +106,10 @@ let info_of_header_and_ops ~in_protocol block_hash block_header operations = | None -> assert false in let preattestations, quorum, payload = - WithExceptions.Option.get - ~loc:__LOC__ - (Operation_pool.extract_operations_of_list_list operations) + (WithExceptions.Option.get + ~loc:__LOC__ + (Operation_pool.extract_operations_of_list_list operations) + [@record_f "operations classification"]) in let prequorum = Option.bind preattestations extract_prequorum in (payload_hash, payload_round, prequorum, quorum, payload) @@ -121,43 +129,60 @@ let info_of_header_and_ops ~in_protocol block_hash block_header operations = let compute_block_info cctxt ~in_protocol ?operations ~chain block_hash block_header = let open Lwt_result_syntax in - let* operations = - match operations with - | None when not in_protocol -> return_nil - | None -> - let open Protocol_client_context in - let* operations = - Alpha_block_services.Operations.operations - cctxt - ~chain - ~block:(`Hash (block_hash, 0)) - () - in - let packed_operations = - List.map - (fun l -> - List.map - (fun {Alpha_block_services.shell; protocol_data; _} -> - {Alpha_context.shell; protocol_data}) - l) - operations - in - return packed_operations - | Some operations -> - let parse_op (raw_op : Tezos_base.Operation.t) = - let protocol_data = - Data_encoding.Binary.of_bytes_exn - Operation.protocol_data_encoding - raw_op.proto + (let* operations = + match operations with + | None when not in_protocol -> return_nil + | None -> + let open Protocol_client_context in + (let* operations = + Alpha_block_services.Operations.operations + cctxt + ~chain + ~block:(`Hash (block_hash, 0)) + () in - {shell = raw_op.shell; protocol_data} - in - protect @@ fun () -> return (List.map (List.map parse_op) operations) - in - let*? block_info = - info_of_header_and_ops ~in_protocol block_hash block_header operations - in - return block_info + let packed_operations = + List.map + (fun l -> + List.map + (fun {Alpha_block_services.shell; protocol_data; _} -> + {Alpha_context.shell; protocol_data}) + l) + operations + in + return packed_operations) + [@profiler.record_s + "retrieve block " + ^ Block_hash.to_short_b58check block_hash + ^ " operations"] + | Some operations -> + let parse_op (raw_op : Tezos_base.Operation.t) = + let protocol_data = + (Data_encoding.Binary.of_bytes_exn + Operation.protocol_data_encoding + raw_op.proto [@profiler.aggregate_f "parse operation"]) + in + {shell = raw_op.shell; protocol_data} + in + protect @@ fun () -> + return + (List.mapi + (fun [@warning "-27"] i -> function + | [] -> [] + | l -> + List.map + parse_op + l + [@profiler.record_f + Printf.sprintf "parse operations (pass:%d)" i]) + operations) + in + let*? block_info = + info_of_header_and_ops ~in_protocol block_hash block_header operations + in + return block_info) + [@profiler.record_s + "compute block " ^ Block_hash.to_short_b58check block_hash ^ " info"] let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain block_hash (block_header : Tezos_base.Block_header.t) = @@ -170,15 +195,33 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain let* is_proposal_in_protocol, predecessor = match predecessor_opt with | Some predecessor -> + () + [@profiler.mark + [ + "pred_block(" + ^ Block_hash.to_short_b58check predecessor_hash + ^ "):cache_hit"; + ]] ; return ( predecessor.shell.proto_level = block_header.shell.proto_level, predecessor ) | None -> + () + [@profiler.mark + [ + "pred_block(" + ^ Block_hash.to_short_b58check predecessor_hash + ^ "):cache_miss"; + ]] ; let* { current_protocol = pred_current_protocol; next_protocol = pred_next_protocol; } = - Shell_services.Blocks.protocols cctxt ~chain ~block:pred_block () + (Shell_services.Blocks.protocols + cctxt + ~chain + ~block:pred_block + () [@profiler.record_s "pred block protocol RPC"]) in let is_proposal_in_protocol = Protocol_hash.(pred_next_protocol = Protocol.hash) @@ -191,9 +234,9 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain Shell_services.Blocks.raw_header cctxt ~chain ~block:pred_block () in let predecessor_header = - Data_encoding.Binary.of_bytes_exn - Tezos_base.Block_header.encoding - raw_header_b + (Data_encoding.Binary.of_bytes_exn + Tezos_base.Block_header.encoding + raw_header_b [@profiler.record_f "parse pred block header"]) in compute_block_info cctxt @@ -212,8 +255,19 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain in let* block = match block_opt with - | Some pi -> return pi + | Some pi -> + () + [@profiler.mark + ["new_block(" ^ Block_hash.to_short_b58check pi.hash ^ "):cache_hit"]] ; + return pi | None -> + () + [@profiler.mark + [ + "new_block(" + ^ Block_hash.to_short_b58check block_hash + ^ "):cache_miss"; + ]] ; let* pi = compute_block_info cctxt @@ -229,8 +283,9 @@ let proposal cctxt ?(cache : block_info Block_cache.t option) ?operations ~chain return {block; predecessor} let proposal cctxt ?cache ?operations ~chain block_hash block_header = - protect @@ fun () -> - proposal cctxt ?cache ?operations ~chain block_hash block_header + ( (protect @@ fun () -> + proposal cctxt ?cache ?operations ~chain block_hash block_header) + [@profiler.record_s "proposal_computation"] ) let monitor_valid_proposals cctxt ~chain ?cache () = let open Lwt_result_syntax in @@ -240,14 +295,18 @@ let monitor_valid_proposals cctxt ~chain ?cache () = in let stream = let map (_chain_id, block_hash, block_header, operations) = - let*! map_result = - proposal cctxt ?cache ~operations ~chain block_hash block_header - in - match map_result with - | Ok proposal -> Lwt.return_some proposal - | Error err -> - let*! () = Events.(emit error_while_monitoring_valid_proposals err) in - Lwt.return_none + () [@profiler.reset_block_section block_hash] ; + (let*! map_result = + proposal cctxt ?cache ~operations ~chain block_hash block_header + in + match map_result with + | Ok proposal -> Lwt.return_some proposal + | Error err -> + let*! () = + Events.(emit error_while_monitoring_valid_proposals err) + in + Lwt.return_none) + [@profiler.record_s "received valid proposal"] in Lwt_stream.filter_map_s map block_stream in @@ -261,12 +320,16 @@ let monitor_heads cctxt ~chain ?cache () = in let stream = let map (block_hash, block_header) = - let*! map_result = proposal cctxt ?cache ~chain block_hash block_header in - match map_result with - | Ok proposal -> Lwt.return_some proposal - | Error err -> - let*! () = Events.(emit error_while_monitoring_heads err) in - Lwt.return_none + () [@profiler.reset_block_section block_hash] ; + (let*! map_result = + proposal cctxt ?cache ~chain block_hash block_header + in + match map_result with + | Ok proposal -> Lwt.return_some proposal + | Error err -> + let*! () = Events.(emit error_while_monitoring_heads err) in + Lwt.return_none) + [@profiler.record_s "received new head"] in Lwt_stream.filter_map_s map block_stream in