diff --git a/manifest/product_octez.ml b/manifest/product_octez.ml index 24870e498b7bffd846cc4791bee0464c35fff3e8..33a47c2d6a24bd74a43790689ac2c3af85904c6e 100644 --- a/manifest/product_octez.ml +++ b/manifest/product_octez.ml @@ -3157,11 +3157,14 @@ let octez_protocol_environment_structs = ] let octez_protocol_environment = + let (PPX {preprocess; preprocessor_deps}) = ppx_profiler in octez_proto_lib "protocol-environment" ~internal_name:"tezos_protocol_environment" ~path:"src/lib_protocol_environment" ~documentation:[Dune.[S "package"; S "octez-proto-libs"]] + ~preprocess + ~preprocessor_deps ~deps: [ zarith; @@ -3443,12 +3446,15 @@ let octez_protocol_updater = ] let octez_validation = + let (PPX {preprocess; preprocessor_deps}) = ppx_profiler in octez_shell_lib "validation" ~internal_name:"tezos_validation" ~path:"src/lib_validation" ~synopsis:"Library for block validation" ~time_measurement_ppx:true + ~preprocess + ~preprocessor_deps ~deps: [ octez_base |> open_ ~m:"TzPervasives"; diff --git a/src/bin_node/node_replay_command.ml b/src/bin_node/node_replay_command.ml index 459413942c7ceab4172596a4690b5882e4e79d17..cd6abe1be2b396441dc6abc31764cab26ff6755e 100644 --- a/src/bin_node/node_replay_command.ml +++ b/src/bin_node/node_replay_command.ml @@ -428,8 +428,8 @@ let replay ~internal_events ~singleprocess ~strict process_path = Sys.executable_name; }) in - let commit_genesis = - Block_validator_process.commit_genesis validator_process + let commit_genesis ~chain_id = + Block_validator_process.commit_genesis validator_process ~chain_id in let* store = Store.init @@ -500,13 +500,10 @@ let run ?verbosity ~singleprocess ~strict ~operation_metadata_size_limit | "verbose" -> Profiler.Verbose | _ -> Profiler.Terse in - let instance = - Profiler.instance - Tezos_base_unix.Simple_profiler.auto_write_to_txt_file - Filename.Infix.(config.data_dir // "/node_profiling.txt", max_lod) + let profiler_maker = + Tezos_shell.Profiler_directory.profiler_maker config.data_dir max_lod in - Tezos_base.Profiler.(plug main) instance ; - Tezos_protocol_environment.Environment_profiler.plug instance + Shell_profiling.activate_all ~profiler_maker | _ -> ()) ; Updater.init (Data_version.protocol_dir config.data_dir) ; Lwt_exit.( diff --git a/src/lib_base/unix/external_process.ml b/src/lib_base/unix/external_process.ml index 04ebfb99a2d7319f77465c229a8eebc0e19c79c6..571b9decc4b71cc4de9c6acc077a844e3113d6a5 100644 --- a/src/lib_base/unix/external_process.ml +++ b/src/lib_base/unix/external_process.ml @@ -466,7 +466,10 @@ module Make (P : External_process_parameters.S) = struct let*! res = Lwt_unix_socket.recv_result process_output - (P.result_encoding request) + Data_encoding.( + tup2 + (P.result_encoding request) + (option Profiler.report_encoding)) in let timespan = let then_ = Time.System.now () in @@ -518,7 +521,11 @@ module Make (P : External_process_parameters.S) = struct return process let reconfigure_event_logging process config = - send_request process (P.reconfigure_event_logging_request config) + let open Lwt_result_syntax in + let* (), _report = + send_request process (P.reconfigure_event_logging_request config) + in + return_unit let close p = let open Lwt_syntax in diff --git a/src/lib_base/unix/external_process.mli b/src/lib_base/unix/external_process.mli index 0425af10fa7784a24bd5ab471254c72ae6dbeccf..22bc1ca3eb56950ca0ec4c17d7d6db8c9abc316c 100644 --- a/src/lib_base/unix/external_process.mli +++ b/src/lib_base/unix/external_process.mli @@ -22,7 +22,8 @@ module Make (P : External_process_parameters.S) : sig (** [send_request p req] sends the request [req] to the external process [p], waits for the answer from the process and returns the result. *) - val send_request : t -> 'a P.request -> 'a tzresult Lwt.t + val send_request : + t -> 'a P.request -> ('a * Profiler.report option) tzresult Lwt.t (** [reconfigure_event_logging p config] sends the request to the external process [p] to reconfigure the event logging system using the new diff --git a/src/lib_base/unix/external_process_main.ml b/src/lib_base/unix/external_process_main.ml index f510d2f5486047d203e987ab67ee890e6d96368b..f655f426664f511b2bea42d7987d272fe8db6c3f 100644 --- a/src/lib_base/unix/external_process_main.ml +++ b/src/lib_base/unix/external_process_main.ml @@ -20,7 +20,8 @@ module type EXTERNAL_PROCESSING = sig parameters -> state -> 'response request -> - [`Continue of 'response tzresult * state | `Stop] Lwt.t + [`Continue of ('response * Profiler.report option) tzresult * state | `Stop] + Lwt.t end module Make @@ -153,7 +154,11 @@ struct let*! () = Lwt_unix_socket.send output - (Error_monad.result_encoding (Params.result_encoding recved)) + (Error_monad.result_encoding + Data_encoding.( + tup2 + (Params.result_encoding recved) + (option Profiler.report_encoding))) res in loop state diff --git a/src/lib_base/unix/external_process_main.mli b/src/lib_base/unix/external_process_main.mli index 90b061ac60638f7825e5bc24f386b018715d33e1..2bbba5854c0c4210e646d2ebde25c78b33647dea 100644 --- a/src/lib_base/unix/external_process_main.mli +++ b/src/lib_base/unix/external_process_main.mli @@ -29,7 +29,8 @@ module type EXTERNAL_PROCESSING = sig parameters -> state -> 'response request -> - [`Continue of 'response tzresult * state | `Stop] Lwt.t + [`Continue of ('response * Profiler.report option) tzresult * state | `Stop] + Lwt.t end module Make diff --git a/src/lib_protocol_environment/dune b/src/lib_protocol_environment/dune index d6e3160109390308c73f615afe5107dddb304d3b..3f61237ae33c517d17fc6f56b061cb78a5efa25d 100644 --- a/src/lib_protocol_environment/dune +++ b/src/lib_protocol_environment/dune @@ -22,6 +22,8 @@ octez-libs.tezos-context-brassaia.memory octez-l2-libs.scoru-wasm octez-libs.event-logging) + (preprocess (pps octez-libs.ppx_profiler)) + (preprocessor_deps (env_var TEZOS_PPX_PROFILER)) (flags (:standard) -open Plonk diff --git a/src/lib_protocol_environment/environment_V10.ml b/src/lib_protocol_environment/environment_V10.ml index 15378729c7e9c944d347efa0e92f6b05086c46b3..8d74d510715ffed95127dd360686a275dbf4dd86 100644 --- a/src/lib_protocol_environment/environment_V10.ml +++ b/src/lib_protocol_environment/environment_V10.ml @@ -189,6 +189,7 @@ struct module CamlinternalFormatBasics = CamlinternalFormatBasics include Stdlib module Pervasives = Stdlib + module Profiler = Environment_profiler module Logging = struct type level = Internal_event.level = @@ -319,7 +320,26 @@ struct module Secp256k1 = Tezos_crypto.Signature.Secp256k1 module P256 = Tezos_crypto.Signature.P256 module Bls = Tezos_crypto.Signature.Bls - module Signature = Tezos_crypto.Signature.V1 + + module Signature = struct + include Tezos_crypto.Signature.V1 + + let check ?watermark pk s bytes = + (check + ?watermark + pk + s + bytes + [@profiler.span_f + [ + (match (pk : public_key) with + | Ed25519 _ -> "check_signature_ed25519" + | Secp256k1 _ -> "check_signature_secp256k1" + | P256 _ -> "check_signature_p256" + | Bls _ -> "check_signature_bls"); + ]]) + end + module Timelock = Tezos_crypto.Timelock module Vdf = Class_group_vdf.Vdf_self_contained @@ -1234,33 +1254,40 @@ struct in let*? f = wrap_tzresult r in return (fun x -> - let*! r = f x in - Lwt.return (wrap_tzresult r)) + (let*! r = f x in + Lwt.return (wrap_tzresult r)) + [@profiler.record_s + Format.asprintf "load_key(%s)" (Context.Cache.identifier_of_key x)]) (** Ensure that the cache is correctly loaded in memory before running any operations. *) let load_predecessor_cache predecessor_context chain_id mode (predecessor_header : Block_header.shell_header) cache = let open Lwt_result_syntax in - let predecessor_hash, timestamp = - match mode with - | Application block_header | Partial_validation block_header -> - (block_header.shell.predecessor, block_header.shell.timestamp) - | Construction {predecessor_hash; timestamp; _} - | Partial_construction {predecessor_hash; timestamp} -> - (predecessor_hash, timestamp) - in - let* value_of_key = - value_of_key - ~chain_id - ~predecessor_context - ~predecessor_timestamp:predecessor_header.timestamp - ~predecessor_level:predecessor_header.level - ~predecessor_fitness:predecessor_header.fitness - ~predecessor:predecessor_hash - ~timestamp - in - Context.load_cache predecessor_hash predecessor_context cache value_of_key + (let predecessor_hash, timestamp = + match mode with + | Application block_header | Partial_validation block_header -> + (block_header.shell.predecessor, block_header.shell.timestamp) + | Construction {predecessor_hash; timestamp; _} + | Partial_construction {predecessor_hash; timestamp} -> + (predecessor_hash, timestamp) + in + let* value_of_key = + value_of_key + ~chain_id + ~predecessor_context + ~predecessor_timestamp:predecessor_header.timestamp + ~predecessor_level:predecessor_header.level + ~predecessor_fitness:predecessor_header.fitness + ~predecessor:predecessor_hash + ~timestamp + in + Context.load_cache + predecessor_hash + predecessor_context + cache + value_of_key) + [@profiler.record_s "load_predecessor_cache"] let begin_validation ctxt chain_id mode ~predecessor ~cache = let open Lwt_result_syntax in diff --git a/src/lib_protocol_environment/environment_V11.ml b/src/lib_protocol_environment/environment_V11.ml index 7ec8dcaa2f42e5e5d17d06da52b58edd9ebf0df2..8e087c8ceac6036b67add8bb0b9633ba034ed063 100644 --- a/src/lib_protocol_environment/environment_V11.ml +++ b/src/lib_protocol_environment/environment_V11.ml @@ -189,6 +189,7 @@ struct module CamlinternalFormatBasics = CamlinternalFormatBasics include Stdlib module Pervasives = Stdlib + module Profiler = Environment_profiler module Logging = struct type level = Internal_event.level = @@ -330,7 +331,26 @@ struct module Secp256k1 = Tezos_crypto.Signature.Secp256k1 module P256 = Tezos_crypto.Signature.P256 module Bls = Tezos_crypto.Signature.Bls - module Signature = Tezos_crypto.Signature.V1 + + module Signature = struct + include Tezos_crypto.Signature.V1 + + let check ?watermark pk s bytes = + (check + ?watermark + pk + s + bytes + [@profiler.span_f + [ + (match (pk : public_key) with + | Ed25519 _ -> "check_signature_ed25519" + | Secp256k1 _ -> "check_signature_secp256k1" + | P256 _ -> "check_signature_p256" + | Bls _ -> "check_signature_bls"); + ]]) + end + module Timelock = Tezos_crypto.Timelock module Vdf = Class_group_vdf.Vdf_self_contained @@ -1208,33 +1228,40 @@ struct in let*? f = wrap_tzresult r in return (fun x -> - let*! r = f x in - Lwt.return (wrap_tzresult r)) + (let*! r = f x in + Lwt.return (wrap_tzresult r)) + [@profiler.record_s + Format.asprintf "load_key(%s)" (Context.Cache.identifier_of_key x)]) (** Ensure that the cache is correctly loaded in memory before running any operations. *) let load_predecessor_cache predecessor_context chain_id mode (predecessor_header : Block_header.shell_header) cache = let open Lwt_result_syntax in - let predecessor_hash, timestamp = - match mode with - | Application block_header | Partial_validation block_header -> - (block_header.shell.predecessor, block_header.shell.timestamp) - | Construction {predecessor_hash; timestamp; _} - | Partial_construction {predecessor_hash; timestamp} -> - (predecessor_hash, timestamp) - in - let* value_of_key = - value_of_key - ~chain_id - ~predecessor_context - ~predecessor_timestamp:predecessor_header.timestamp - ~predecessor_level:predecessor_header.level - ~predecessor_fitness:predecessor_header.fitness - ~predecessor:predecessor_hash - ~timestamp - in - Context.load_cache predecessor_hash predecessor_context cache value_of_key + (let predecessor_hash, timestamp = + match mode with + | Application block_header | Partial_validation block_header -> + (block_header.shell.predecessor, block_header.shell.timestamp) + | Construction {predecessor_hash; timestamp; _} + | Partial_construction {predecessor_hash; timestamp} -> + (predecessor_hash, timestamp) + in + let* value_of_key = + value_of_key + ~chain_id + ~predecessor_context + ~predecessor_timestamp:predecessor_header.timestamp + ~predecessor_level:predecessor_header.level + ~predecessor_fitness:predecessor_header.fitness + ~predecessor:predecessor_hash + ~timestamp + in + Context.load_cache + predecessor_hash + predecessor_context + cache + value_of_key) + [@profiler.record_s "load_predecessor_cache"] let begin_validation ctxt chain_id mode ~predecessor ~cache = let open Lwt_result_syntax in diff --git a/src/lib_protocol_environment/environment_V12.ml b/src/lib_protocol_environment/environment_V12.ml index 17c5cec9035839979656eb9dab0a902f17558cef..345362e9e90e9a7195524c983f8d4e13eee8f7f4 100644 --- a/src/lib_protocol_environment/environment_V12.ml +++ b/src/lib_protocol_environment/environment_V12.ml @@ -189,6 +189,7 @@ struct module CamlinternalFormatBasics = CamlinternalFormatBasics include Stdlib module Pervasives = Stdlib + module Profiler = Environment_profiler module Logging = struct type level = Internal_event.level = @@ -330,7 +331,26 @@ struct module Secp256k1 = Tezos_crypto.Signature.Secp256k1 module P256 = Tezos_crypto.Signature.P256 module Bls = Tezos_crypto.Signature.Bls - module Signature = Tezos_crypto.Signature.V1 + + module Signature = struct + include Tezos_crypto.Signature.V1 + + let check ?watermark pk s bytes = + (check + ?watermark + pk + s + bytes + [@profiler.span_f + [ + (match (pk : public_key) with + | Ed25519 _ -> "check_signature_ed25519" + | Secp256k1 _ -> "check_signature_secp256k1" + | P256 _ -> "check_signature_p256" + | Bls _ -> "check_signature_bls"); + ]]) + end + module Timelock = Tezos_crypto.Timelock module Vdf = Class_group_vdf.Vdf_self_contained @@ -1209,33 +1229,40 @@ struct in let*? f = wrap_tzresult r in return (fun x -> - let*! r = f x in - Lwt.return (wrap_tzresult r)) + (let*! r = f x in + Lwt.return (wrap_tzresult r)) + [@profiler.record_s + Format.asprintf "load_key(%s)" (Context.Cache.identifier_of_key x)]) (** Ensure that the cache is correctly loaded in memory before running any operations. *) let load_predecessor_cache predecessor_context chain_id mode (predecessor_header : Block_header.shell_header) cache = let open Lwt_result_syntax in - let predecessor_hash, timestamp = - match mode with - | Application block_header | Partial_validation block_header -> - (block_header.shell.predecessor, block_header.shell.timestamp) - | Construction {predecessor_hash; timestamp; _} - | Partial_construction {predecessor_hash; timestamp} -> - (predecessor_hash, timestamp) - in - let* value_of_key = - value_of_key - ~chain_id - ~predecessor_context - ~predecessor_timestamp:predecessor_header.timestamp - ~predecessor_level:predecessor_header.level - ~predecessor_fitness:predecessor_header.fitness - ~predecessor:predecessor_hash - ~timestamp - in - Context.load_cache predecessor_hash predecessor_context cache value_of_key + (let predecessor_hash, timestamp = + match mode with + | Application block_header | Partial_validation block_header -> + (block_header.shell.predecessor, block_header.shell.timestamp) + | Construction {predecessor_hash; timestamp; _} + | Partial_construction {predecessor_hash; timestamp} -> + (predecessor_hash, timestamp) + in + let* value_of_key = + value_of_key + ~chain_id + ~predecessor_context + ~predecessor_timestamp:predecessor_header.timestamp + ~predecessor_level:predecessor_header.level + ~predecessor_fitness:predecessor_header.fitness + ~predecessor:predecessor_hash + ~timestamp + in + Context.load_cache + predecessor_hash + predecessor_context + cache + value_of_key) + [@profiler.record_s "load_predecessor_cache"] let begin_validation ctxt chain_id mode ~predecessor ~cache = let open Lwt_result_syntax in diff --git a/src/lib_protocol_environment/environment_V13.ml b/src/lib_protocol_environment/environment_V13.ml index e16c5f632521ac7151ff035ba92e653b1903e19c..bb59f0b18b6f3fdc0876432b1588d1c7922b7d9e 100644 --- a/src/lib_protocol_environment/environment_V13.ml +++ b/src/lib_protocol_environment/environment_V13.ml @@ -189,6 +189,7 @@ struct module CamlinternalFormatBasics = CamlinternalFormatBasics include Stdlib module Pervasives = Stdlib + module Profiler = Environment_profiler module Logging = struct type level = Internal_event.level = @@ -330,7 +331,26 @@ struct module Secp256k1 = Tezos_crypto.Signature.Secp256k1 module P256 = Tezos_crypto.Signature.P256 module Bls = Tezos_crypto.Signature.Bls - module Signature = Tezos_crypto.Signature.V1 + + module Signature = struct + include Tezos_crypto.Signature.V1 + + let check ?watermark pk s bytes = + (check + ?watermark + pk + s + bytes + [@profiler.span_f + [ + (match (pk : public_key) with + | Ed25519 _ -> "check_signature_ed25519" + | Secp256k1 _ -> "check_signature_secp256k1" + | P256 _ -> "check_signature_p256" + | Bls _ -> "check_signature_bls"); + ]]) + end + module Timelock = Tezos_crypto.Timelock module Vdf = Class_group_vdf.Vdf_self_contained @@ -1209,33 +1229,40 @@ struct in let*? f = wrap_tzresult r in return (fun x -> - let*! r = f x in - Lwt.return (wrap_tzresult r)) + (let*! r = f x in + Lwt.return (wrap_tzresult r)) + [@profiler.record_s + Format.asprintf "load_key(%s)" (Context.Cache.identifier_of_key x)]) (** Ensure that the cache is correctly loaded in memory before running any operations. *) let load_predecessor_cache predecessor_context chain_id mode (predecessor_header : Block_header.shell_header) cache = let open Lwt_result_syntax in - let predecessor_hash, timestamp = - match mode with - | Application block_header | Partial_validation block_header -> - (block_header.shell.predecessor, block_header.shell.timestamp) - | Construction {predecessor_hash; timestamp; _} - | Partial_construction {predecessor_hash; timestamp} -> - (predecessor_hash, timestamp) - in - let* value_of_key = - value_of_key - ~chain_id - ~predecessor_context - ~predecessor_timestamp:predecessor_header.timestamp - ~predecessor_level:predecessor_header.level - ~predecessor_fitness:predecessor_header.fitness - ~predecessor:predecessor_hash - ~timestamp - in - Context.load_cache predecessor_hash predecessor_context cache value_of_key + (let predecessor_hash, timestamp = + match mode with + | Application block_header | Partial_validation block_header -> + (block_header.shell.predecessor, block_header.shell.timestamp) + | Construction {predecessor_hash; timestamp; _} + | Partial_construction {predecessor_hash; timestamp} -> + (predecessor_hash, timestamp) + in + let* value_of_key = + value_of_key + ~chain_id + ~predecessor_context + ~predecessor_timestamp:predecessor_header.timestamp + ~predecessor_level:predecessor_header.level + ~predecessor_fitness:predecessor_header.fitness + ~predecessor:predecessor_hash + ~timestamp + in + Context.load_cache + predecessor_hash + predecessor_context + cache + value_of_key) + [@profiler.record_s "load_predecessor_cache"] let begin_validation ctxt chain_id mode ~predecessor ~cache = let open Lwt_result_syntax in diff --git a/src/lib_protocol_environment/environment_V9.ml b/src/lib_protocol_environment/environment_V9.ml index 819d385438129ca161feb1012cce7e76fae735aa..3b209af4b86324cb038cbec96cfe949fd394e76f 100644 --- a/src/lib_protocol_environment/environment_V9.ml +++ b/src/lib_protocol_environment/environment_V9.ml @@ -177,6 +177,7 @@ struct module CamlinternalFormatBasics = CamlinternalFormatBasics include Stdlib module Pervasives = Stdlib + module Profiler = Environment_profiler module Logging = struct type level = Internal_event.level = @@ -307,7 +308,26 @@ struct module Secp256k1 = Tezos_crypto.Signature.Secp256k1 module P256 = Tezos_crypto.Signature.P256 module Bls = Tezos_crypto.Signature.Bls - module Signature = Tezos_crypto.Signature.V1 + + module Signature = struct + include Tezos_crypto.Signature.V1 + + let check ?watermark pk s bytes = + (check + ?watermark + pk + s + bytes + [@profiler.span_f + [ + (match (pk : public_key) with + | Ed25519 _ -> "check_signature_ed25519" + | Secp256k1 _ -> "check_signature_secp256k1" + | P256 _ -> "check_signature_p256" + | Bls _ -> "check_signature_bls"); + ]]) + end + module Timelock = Tezos_crypto.Timelock_legacy module Vdf = Class_group_vdf.Vdf_self_contained @@ -1206,33 +1226,40 @@ struct in let*? f = wrap_tzresult r in return (fun x -> - let*! r = f x in - Lwt.return (wrap_tzresult r)) + (let*! r = f x in + Lwt.return (wrap_tzresult r)) + [@profiler.record_s + Format.asprintf "load_key(%s)" (Context.Cache.identifier_of_key x)]) (** Ensure that the cache is correctly loaded in memory before running any operations. *) let load_predecessor_cache predecessor_context chain_id mode (predecessor_header : Block_header.shell_header) cache = let open Lwt_result_syntax in - let predecessor_hash, timestamp = - match mode with - | Application block_header | Partial_validation block_header -> - (block_header.shell.predecessor, block_header.shell.timestamp) - | Construction {predecessor_hash; timestamp; _} - | Partial_construction {predecessor_hash; timestamp} -> - (predecessor_hash, timestamp) - in - let* value_of_key = - value_of_key - ~chain_id - ~predecessor_context - ~predecessor_timestamp:predecessor_header.timestamp - ~predecessor_level:predecessor_header.level - ~predecessor_fitness:predecessor_header.fitness - ~predecessor:predecessor_hash - ~timestamp - in - Context.load_cache predecessor_hash predecessor_context cache value_of_key + (let predecessor_hash, timestamp = + match mode with + | Application block_header | Partial_validation block_header -> + (block_header.shell.predecessor, block_header.shell.timestamp) + | Construction {predecessor_hash; timestamp; _} + | Partial_construction {predecessor_hash; timestamp} -> + (predecessor_hash, timestamp) + in + let* value_of_key = + value_of_key + ~chain_id + ~predecessor_context + ~predecessor_timestamp:predecessor_header.timestamp + ~predecessor_level:predecessor_header.level + ~predecessor_fitness:predecessor_header.fitness + ~predecessor:predecessor_hash + ~timestamp + in + Context.load_cache + predecessor_hash + predecessor_context + cache + value_of_key) + [@profiler.record_s "load_predecessor_cache"] let begin_validation ctxt chain_id mode ~predecessor ~cache = let open Lwt_result_syntax in diff --git a/src/lib_shell/block_validator.ml b/src/lib_shell/block_validator.ml index 583f449470d0936ee8ece61c20662a48f9500f7f..b40cfa93895aeb5cb441468ade668acb8e4924cc 100644 --- a/src/lib_shell/block_validator.ml +++ b/src/lib_shell/block_validator.ml @@ -28,6 +28,14 @@ open Block_validator_worker_state open Block_validator_errors +module Profiler = struct + include (val Profiler.wrap Shell_profiling.block_validator_profiler) + + let[@warning "-32"] reset_block_section = + Shell_profiling.create_reset_block_section + Shell_profiling.block_validator_profiler +end + type validation_result = | Already_committed | Already_known_invalid of error trace @@ -149,22 +157,23 @@ let check_chain_liveness chain_db hash (header : Block_header.t) = let check_operations_merkle_root hash header operations = let open Result_syntax in - let fail_unless b e = if b then return_unit else tzfail e in - let computed_hash = - let hashes = List.map (List.map Operation.hash) operations in - Operation_list_list_hash.compute - (List.map Operation_list_hash.compute hashes) - in - fail_unless - (Operation_list_list_hash.equal - computed_hash - header.Block_header.shell.operations_hash) - (Inconsistent_operations_hash - { - block = hash; - expected = header.shell.operations_hash; - found = computed_hash; - }) + (let fail_unless b e = if b then return_unit else tzfail e in + let computed_hash = + let hashes = List.map (List.map Operation.hash) operations in + Operation_list_list_hash.compute + (List.map Operation_list_hash.compute hashes) + in + fail_unless + (Operation_list_list_hash.equal + computed_hash + header.Block_header.shell.operations_hash) + (Inconsistent_operations_hash + { + block = hash; + expected = header.shell.operations_hash; + found = computed_hash; + })) + [@profiler.span_f ["checks"; "merkle_root"]] (* [with_retry_to_load_protocol bv peer f] tries to call [f], if it fails with an [Unavailable_protocol] error, it fetches the protocol from the [peer] and retries @@ -324,11 +333,13 @@ let on_validation_request w advertise_after_validation; } = let open Lwt_result_syntax in + () [@profiler.reset_block_section hash] ; let bv = Worker.state w in let chain_store = Distributed_db.chain_store chain_db in let*! b = Store.Block.is_known_valid chain_store hash in match b with - | true -> return Already_committed + | true -> + return Already_committed [@profiler.mark ["checks"; "already_commited"]] | false -> ( (* This check might be redundant as operation paths are already checked when each pass is received from the network. However, @@ -349,7 +360,10 @@ let on_validation_request w | Some {errors; _} -> return (Already_known_invalid errors) | None -> ( let* pred = - Store.Block.read_block chain_store header.shell.predecessor + (Store.Block.read_block + chain_store + header.shell.predecessor + [@profiler.record_s "read_predecessor"]) in let*! mempool = Store.Chain.mempool chain_store in let bv_operations = @@ -426,7 +440,8 @@ let on_validation_request w hash header operations - application_result)))) + application_result [@profiler.record_s "commit_block"])) + )) let on_preapplication_request w { @@ -654,6 +669,7 @@ let validate_and_apply w ?canceler ?peer ?(notify_new_block = fun _ -> ()) ~advertise_after_validation chain_db hash (header : Block_header.t) operations = let open Lwt_syntax in + () [@profiler.reset_block_section hash] ; let chain_store = Distributed_db.chain_store chain_db in let* b = Store.Block.is_known_valid chain_store hash in match b with @@ -664,8 +680,9 @@ let validate_and_apply w ?canceler ?peer ?(notify_new_block = fun _ -> ()) let* r = let open Lwt_result_syntax in let* () = - check_chain_liveness chain_db hash header - |> Lwt_result.map_error (fun e -> Worker.Request_error e) + (check_chain_liveness chain_db hash header + |> Lwt_result.map_error (fun e -> Worker.Request_error e)) + [@profiler.span_s ["checks"; "chain_liveness"]] in Worker.Queue.push_request_and_wait w diff --git a/src/lib_shell/block_validator_process.ml b/src/lib_shell/block_validator_process.ml index 154c14c165a84abe99a086ca8c34335e8d29f4c5..ffd8c45b910f032cb74418a517e6dc31b8e34ccb 100644 --- a/src/lib_shell/block_validator_process.ml +++ b/src/lib_shell/block_validator_process.ml @@ -196,6 +196,7 @@ module Internal_validator_process = struct mutable preapply_result : (Block_validation.apply_result * Tezos_protocol_environment.Context.t) option; + headless : Tezos_base.Profiler.instance; } let init @@ -207,6 +208,13 @@ module Internal_validator_process = struct validator_environment) chain_store = let open Lwt_syntax in let* () = Events.(emit init ()) in + let headless = + Tezos_base.Profiler.instance + Tezos_base_unix.Simple_profiler.headless + Profiler.Detailed + in + Tezos_base.Profiler.(plug main) headless ; + Tezos_protocol_environment.Environment_profiler.plug headless ; return_ok { chain_store; @@ -215,6 +223,7 @@ module Internal_validator_process = struct operation_metadata_size_limit; cache = None; preapply_result = None; + headless; } let kind = Single_process @@ -318,6 +327,12 @@ module Internal_validator_process = struct Events.(emit validation_success (block_hash, timespan)) else Events.(emit application_success (block_hash, timespan)) in + let report = Tezos_base.Profiler.report validator.headless in + (match report with + | None -> () + | Some report -> ( + try Profiler.inc Shell_profiling.block_validator_profiler report + with _ -> ())) ; return result let preapply_block validator ~chain_id ~timestamp ~protocol_data ~live_blocks @@ -405,15 +420,24 @@ module Internal_validator_process = struct `Inherited (block_cache, predecessor_resulting_context_hash) in let predecessor_block_hash = Store.Block.hash predecessor in - Block_validation.validate - ~chain_id - ~predecessor_block_header - ~predecessor_block_hash - ~predecessor_context - ~predecessor_resulting_context_hash - ~cache - header - operations + let* res = + Block_validation.validate + ~chain_id + ~predecessor_block_header + ~predecessor_block_hash + ~predecessor_context + ~predecessor_resulting_context_hash + ~cache + header + operations + in + let report = Tezos_base.Profiler.report validator.headless in + (match report with + | None -> () + | Some report -> ( + try Profiler.inc Shell_profiling.block_validator_profiler report + with _ -> ())) ; + return res let context_garbage_collection _validator context_index context_hash ~gc_lockfile_path:_ = @@ -479,13 +503,20 @@ module External_validator_process = struct simulate; } in - send_request validator request + let* res, report = send_request validator request in + (match report with + | None -> () + | Some report -> ( + try Profiler.inc Shell_profiling.block_validator_profiler report + with _ -> ())) ; + return res let preapply_block validator ~chain_id ~timestamp ~protocol_data ~live_blocks ~live_operations ~predecessor_shell_header ~predecessor_hash ~predecessor_max_operations_ttl ~predecessor_block_metadata_hash ~predecessor_ops_metadata_hash ~predecessor_resulting_context_hash operations = + let open Lwt_result_syntax in let request = External_validation.Preapply { @@ -503,7 +534,8 @@ module External_validator_process = struct operations; } in - send_request validator request + let* res, _report = send_request validator request in + return res let validate_block validator chain_store ~predecessor header hash operations = let open Lwt_result_syntax in @@ -525,37 +557,55 @@ module External_validator_process = struct hash; } in - send_request validator request + let* res, report = send_request validator request in + (match report with + | None -> () + | Some report -> ( + try Profiler.inc Shell_profiling.block_validator_profiler report + with _ -> ())) ; + return res let context_garbage_collection validator _index context_hash ~gc_lockfile_path = + let open Lwt_result_syntax in let request = External_validation.Context_garbage_collection {context_hash; gc_lockfile_path} in - send_request validator request + let* (), _report = send_request validator request in + return_unit let context_split validator _index = + let open Lwt_result_syntax in let request = External_validation.Context_split in - send_request validator request + let* (), _report = send_request validator request in + return_unit let commit_genesis validator ~chain_id = + let open Lwt_result_syntax in let request = External_validation.Commit_genesis {chain_id} in - send_request validator request + let* res, _report = send_request validator request in + return res let init_test_chain validator chain_id forking_block = + let open Lwt_result_syntax in let forked_header = Store.Block.header forking_block in let context_hash = forked_header.shell.context in let request = External_validation.Fork_test_chain {chain_id; context_hash; forked_header} in - send_request validator request + let* res, _report = send_request validator request in + return res let reconfigure_event_logging validator config = - send_request - validator - (External_validation.Reconfigure_event_logging config) + let open Lwt_result_syntax in + let* (), _report = + send_request + validator + (External_validation.Reconfigure_event_logging config) + in + return_unit end let init validator_kind = diff --git a/src/lib_validation/block_validation.ml b/src/lib_validation/block_validation.ml index 6e7880c6094c5a5a6ebfcb34912cf8191179fd88..3dc02ef8f7ed486b578982218a6295dc4d5b3ae4 100644 --- a/src/lib_validation/block_validation.ml +++ b/src/lib_validation/block_validation.ml @@ -28,6 +28,10 @@ open Block_validator_errors open Validation_errors +module Profiler = struct + include (val Profiler.wrap Tezos_base.Profiler.main) +end + module Event = struct include Internal_event.Simple @@ -614,30 +618,48 @@ module Make (Proto : Protocol_plugin.T) = struct chain_id (Application block_header) ~predecessor:predecessor_block_header.shell - ~cache [@time.duration_lwt application_beginning]) + ~cache + [@time.duration_lwt application_beginning] + [@profiler.record_s "begin_application"]) in let* state, ops_metadata = - (List.fold_left_es - (fun (state, acc) ops -> - let* state, ops_metadata = - List.fold_left_es - (fun (state, acc) (oph, op, _check_signature) -> - let* state, op_metadata = - Proto.apply_operation state oph op - in - return (state, op_metadata :: acc)) - (state, []) - ops + (List.fold_left_i_es + (fun i (state, acc) ops -> + let[@warning "-26"] sec = + "operation_list(" ^ string_of_int i ^ ")" in - return (state, List.rev ops_metadata :: acc)) + (let* state, ops_metadata = + List.fold_left_es + (fun (state, acc) (oph, op, _check_signature) -> + let* state, op_metadata = + let[@warning "-26"] sec = + "operation(" ^ Operation_hash.to_b58check oph ^ ")" + in + (Proto.apply_operation + state + oph + op + [@profiler.record_s sec] + (* TODO: Add a ~lod:detailed payload *)) + in + return (state, op_metadata :: acc)) + (state, []) + ops + in + return (state, List.rev ops_metadata :: acc)) + [@profiler.record_s sec]) (state, []) - operations [@time.duration_lwt operations_application]) + operations + [@time.duration_lwt operations_application] + [@profiler.record_s "apply_operations"]) in let ops_metadata = List.rev ops_metadata in let* validation_result, block_data = (Proto.finalize_application state - (Some block_header.shell) [@time.duration_lwt block_finalization]) + (Some block_header.shell) + [@time.duration_lwt block_finalization] + [@profiler.record_s "finalize_application"]) in return (validation_result, block_data, ops_metadata)) @@ -725,15 +747,17 @@ module Make (Proto : Protocol_plugin.T) = struct let* operations = (parse_operations block_hash - operations [@time.duration_lwt operations_parsing]) + operations + [@time.duration_lwt operations_parsing] + [@profiler.record_s "parse_operations"]) in let* context = - prepare_context - predecessor_block_metadata_hash - predecessor_ops_metadata_hash - block_header - predecessor_context - predecessor_hash + (prepare_context + predecessor_block_metadata_hash + predecessor_ops_metadata_hash + block_header + predecessor_context + predecessor_hash [@profiler.record_s "prepare_context"]) in let* validation_result, block_metadata, ops_metadata = proto_apply_operations @@ -745,120 +769,122 @@ module Make (Proto : Protocol_plugin.T) = struct block_hash operations in - let*! validation_result = - may_patch_protocol - ~user_activated_upgrades - ~user_activated_protocol_overrides - ~level:block_header.shell.level - validation_result - in - let context = validation_result.context in - let*! new_protocol = Context_ops.get_protocol context in - let expected_proto_level = - if Protocol_hash.equal new_protocol Proto.hash then - predecessor_block_header.shell.proto_level - else (predecessor_block_header.shell.proto_level + 1) mod 256 - in - let* () = - fail_when - (block_header.shell.proto_level <> expected_proto_level) - (invalid_block - block_hash - (Invalid_proto_level - { - found = block_header.shell.proto_level; - expected = expected_proto_level; - })) - in - let* () = - fail_when - Fitness.(validation_result.fitness <> block_header.shell.fitness) - (invalid_block - block_hash - (Invalid_fitness - { - expected = block_header.shell.fitness; - found = validation_result.fitness; - })) - in - let* validation_result, new_protocol_env_version, expected_context_hash - = - may_init_new_protocol - chain_id - new_protocol - block_header - block_hash - validation_result - in - let max_operations_ttl = - max - 0 - (min (max_operations_ttl + 1) validation_result.max_operations_ttl) - in - let validation_result = {validation_result with max_operations_ttl} in - let* block_metadata, ops_metadata = - compute_metadata - ~operation_metadata_size_limit - new_protocol_env_version - block_metadata - ops_metadata - in - let (Context {cache; _}) = validation_result.context in - let context = validation_result.context in - let*! resulting_context_hash = - if simulate then - Lwt.return - @@ Context_ops.hash - ~time:block_header.shell.timestamp - ?message:validation_result.message - context - else - Context_ops.commit - ~time:block_header.shell.timestamp - ?message:validation_result.message - context [@time.duration_lwt context_commitment] [@time.flush] - in - let* () = - let is_context_consistent = - match expected_context_hash with - | Predecessor_resulting_context -> - (* The check that the header's context is the - predecessor's resulting context has already been - performed in the [check_block_header] call above. *) - true - | Resulting_context -> - Context_hash.equal - resulting_context_hash - block_header.shell.context - in - fail_unless - is_context_consistent - (Validation_errors.Inconsistent_hash - (resulting_context_hash, block_header.shell.context)) - in - let validation_store = - { - resulting_context_hash; - timestamp = block_header.shell.timestamp; - message = validation_result.message; - max_operations_ttl = validation_result.max_operations_ttl; - last_finalized_block_level = - validation_result.last_finalized_block_level; - last_preserved_block_level = - validation_result.last_preserved_block_level; - } - in - return - { - result = - { - shell_header_hash = hash_shell_header block_header.shell; - validation_store; - block_metadata; - ops_metadata; - }; - cache; - } + (let*! validation_result = + may_patch_protocol + ~user_activated_upgrades + ~user_activated_protocol_overrides + ~level:block_header.shell.level + validation_result + in + let context = validation_result.context in + let*! new_protocol = Context_ops.get_protocol context in + let expected_proto_level = + if Protocol_hash.equal new_protocol Proto.hash then + predecessor_block_header.shell.proto_level + else (predecessor_block_header.shell.proto_level + 1) mod 256 + in + let* () = + fail_when + (block_header.shell.proto_level <> expected_proto_level) + (invalid_block + block_hash + (Invalid_proto_level + { + found = block_header.shell.proto_level; + expected = expected_proto_level; + })) + in + let* () = + fail_when + Fitness.(validation_result.fitness <> block_header.shell.fitness) + (invalid_block + block_hash + (Invalid_fitness + { + expected = block_header.shell.fitness; + found = validation_result.fitness; + })) + in + let* validation_result, new_protocol_env_version, expected_context_hash + = + (may_init_new_protocol + chain_id + new_protocol + block_header + block_hash + validation_result [@profiler.record_s "record_protocol"]) + in + let max_operations_ttl = + max + 0 + (min (max_operations_ttl + 1) validation_result.max_operations_ttl) + in + let validation_result = {validation_result with max_operations_ttl} in + let* block_metadata, ops_metadata = + (compute_metadata + ~operation_metadata_size_limit + new_protocol_env_version + block_metadata + ops_metadata [@profiler.record_s "compute_metadata"]) + in + let (Context {cache; _}) = validation_result.context in + let context = validation_result.context in + let*! resulting_context_hash = + (if simulate then + Lwt.return + @@ Context_ops.hash + ~time:block_header.shell.timestamp + ?message:validation_result.message + context + else + Context_ops.commit + ~time:block_header.shell.timestamp + ?message:validation_result.message + context [@time.duration_lwt context_commitment] [@time.flush]) + [@profiler.record_s "commit"] + in + let* () = + let is_context_consistent = + match expected_context_hash with + | Predecessor_resulting_context -> + (* The check that the header's context is the + predecessor's resulting context has already been + performed in the [check_block_header] call above. *) + true + | Resulting_context -> + Context_hash.equal + resulting_context_hash + block_header.shell.context + in + fail_unless + is_context_consistent + (Validation_errors.Inconsistent_hash + (resulting_context_hash, block_header.shell.context)) + in + let validation_store = + { + resulting_context_hash; + timestamp = block_header.shell.timestamp; + message = validation_result.message; + max_operations_ttl = validation_result.max_operations_ttl; + last_finalized_block_level = + validation_result.last_finalized_block_level; + last_preserved_block_level = + validation_result.last_preserved_block_level; + } + in + return + { + result = + { + shell_header_hash = hash_shell_header block_header.shell; + validation_store; + block_metadata; + ops_metadata; + }; + cache; + }) + [@profiler.record_s "post_validation"] let recompute_metadata chain_id ~cache ~(predecessor_block_header : Block_header.t) @@ -1286,28 +1312,46 @@ module Make (Proto : Protocol_plugin.T) = struct ~predecessor_hash:predecessor_block_hash block_header.shell.timestamp in - let* operations = parse_operations block_hash operations in + let* operations = + (parse_operations + block_hash + operations [@profiler.record_s "parse_operations"]) + in let* state = - Proto.begin_validation - context - chain_id - (Application block_header) - ~predecessor:predecessor_block_header.shell - ~cache + (Proto.begin_validation + context + chain_id + (Application block_header) + ~predecessor:predecessor_block_header.shell + ~cache [@profiler.record_s "begin_validation"]) in - let* state = - List.fold_left_es - (fun state ops -> - List.fold_left_es - (fun state (oph, op, check_signature) -> - Proto.validate_operation ~check_signature state oph op) - state - ops) - state - operations + (List.fold_left_i_es + (fun i state ops -> + let[@warning "-26"] sec = + "operation_list(" ^ string_of_int i ^ ")" + in + (List.fold_left_es + (fun state (oph, op, check_signature) -> + let[@warning "-26"] sec = + "operation(" ^ Operation_hash.to_b58check oph ^ ")" + in + (Proto.validate_operation + ~check_signature + state + oph + op + [@profiler.record_s sec] + (* TODO: add a ~lod option for record_s *))) + state + ops [@profiler.record_s sec])) + state + operations [@profiler.record_s "validate_operations"]) + in + let* () = + (Proto.finalize_validation + state [@profiler.record_s "finalize_validation"]) in - let* () = Proto.finalize_validation state in return_unit let validate chain_id ~(predecessor_block_header : Block_header.t) diff --git a/src/lib_validation/dune b/src/lib_validation/dune index af4aa84baa3d131e1e595e127f0748084ea6055a..732bf7769b45f50da2568e64b20626e3f99cee3f 100644 --- a/src/lib_validation/dune +++ b/src/lib_validation/dune @@ -15,6 +15,8 @@ octez-shell-libs.protocol-updater octez-libs.stdlib-unix octez-version.value) + (preprocess (pps octez-libs.ppx_profiler)) + (preprocessor_deps (env_var TEZOS_PPX_PROFILER)) (flags (:standard) -open Tezos_base.TzPervasives diff --git a/src/lib_validation/external_validator.ml b/src/lib_validation/external_validator.ml index cc0d18f68c08780405e3363d4414e28654c46592..3a928f0ba4e1e15b14f30e4b7f6f39de445376aa 100644 --- a/src/lib_validation/external_validator.ml +++ b/src/lib_validation/external_validator.ml @@ -24,6 +24,8 @@ (* *) (*****************************************************************************) +module Profiler = Tezos_protocol_environment.Environment_profiler + module Events = struct open Internal_event.Simple @@ -49,6 +51,7 @@ module Processing = struct cache : Context_ops.Environment_context.block_cache option; cached_result : (Block_validation.apply_result * Context_ops.Environment_context.t) option; + headless : Tezos_base.Profiler.instance; } let load_protocol proto protocol_root = @@ -104,14 +107,23 @@ module Processing = struct ~readonly context_root in - return {context_index; cache = None; cached_result = None} + let headless = + Tezos_base.Profiler.instance + Tezos_base_unix.Simple_profiler.headless + Profiler.Detailed + in + Tezos_base.Profiler.(plug main) headless ; + Tezos_protocol_environment.Environment_profiler.plug headless ; + return {context_index; cache = None; cached_result = None; headless} let handle_request : type a. External_validation.parameters -> state -> a External_validation.request -> - [`Continue of a tzresult * state | `Stop] Lwt.t = + [ `Continue of (a * Tezos_base.Profiler.report option) tzresult * state + | `Stop ] + Lwt.t = fun { protocol_root; genesis; @@ -120,10 +132,14 @@ module Processing = struct operation_metadata_size_limit; _; } - {context_index; cache; cached_result} -> + {context_index; cache; cached_result; headless} -> let open Lwt_result_syntax in - let continue res cache cached_result = - Lwt.return (`Continue (res, {context_index; cache; cached_result})) + let continue res cache cached_result report = + let res = + match res with Error errs -> Error errs | Ok res -> Ok (res, report) + in + Lwt.return + (`Continue (res, {context_index; cache; cached_result; headless})) in function | Commit_genesis {chain_id} -> @@ -135,7 +151,7 @@ module Processing = struct ~time:genesis.time ~protocol:genesis.protocol) in - continue commit cache None + continue commit cache None None | Apply { chain_id; @@ -149,6 +165,7 @@ module Processing = struct should_validate; simulate; } -> + () [@profiler.record "apply_block"] ; let*! block_application_result = let* predecessor_context = Error_monad.catch_es (fun () -> @@ -207,7 +224,9 @@ module Processing = struct cache; } ) in - continue block_application_result cache None + Tezos_protocol_environment.Environment_profiler.stop () ; + let report = Tezos_base.Profiler.report headless in + continue block_application_result cache None report | Preapply { chain_id; @@ -272,7 +291,7 @@ module Processing = struct Lwt.return (Ok res, Some last_preapplied_context) | Error _ as err -> Lwt.return (err, None) in - continue res cache cachable_result + continue res cache cachable_result None | External_validation.Validate { chain_id; @@ -283,6 +302,7 @@ module Processing = struct operations; _; } -> + () [@profiler.record "validate_block"] ; let*! block_validate_result = let* predecessor_context = Error_monad.catch_es (fun () -> @@ -317,7 +337,9 @@ module Processing = struct header operations) in - continue block_validate_result cache cached_result + Tezos_protocol_environment.Environment_profiler.stop () ; + let report = Tezos_base.Profiler.report headless in + continue block_validate_result cache cached_result report | External_validation.Fork_test_chain {chain_id; context_hash; forked_header} -> let*! context_opt = Context_ops.checkout context_index context_hash in @@ -330,7 +352,7 @@ module Processing = struct tzfail (Block_validator_errors.Failed_to_checkout_context context_hash) in - continue res cache cached_result + continue res cache cached_result None | External_validation.Context_garbage_collection {context_hash; gc_lockfile_path} -> let*! () = Context_ops.gc context_index context_hash in @@ -356,10 +378,10 @@ module Processing = struct (fun () -> Lwt_unix.close lockfile) in let () = Lwt.dont_wait gc_waiter (fun _exn -> ()) in - continue (Ok ()) cache cached_result + continue (Ok ()) cache cached_result None | External_validation.Context_split -> let*! () = Context_ops.split context_index in - continue (Ok ()) cache cached_result + continue (Ok ()) cache cached_result None | External_validation.Terminate -> let*! () = Lwt_io.flush_all () in Lwt.return `Stop @@ -367,7 +389,7 @@ module Processing = struct let*! res = Tezos_base_unix.Internal_event_unix.Configuration.reapply config in - continue res cache cached_result + continue res cache cached_result None end include