diff --git a/src/bin_validation/validator.ml b/src/bin_validation/validator.ml index 284310099d0cf0221f6567266b04dcaa190397a9..a292b8eebf5b6b39b79dfc851a3aedec5e23c1f0 100644 --- a/src/bin_validation/validator.ml +++ b/src/bin_validation/validator.ml @@ -141,6 +141,19 @@ let handshake input output = (not (Bytes.equal magic External_validation.magic)) (inconsistent_handshake "bad magic") +let timer f ~msg ~loc = + let start = Systime_os.now () in + f () + >>= fun res -> + let elapsed = Ptime.diff (Systime_os.now ()) start in + Format.printf + "[Validator RW]: %s executed in %a@.loc: %s@." + msg + Ptime.Span.pp + elapsed + loc ; + Lwt.return res + let init input = Events.(emit initialization_request ()) >>= fun () -> @@ -154,9 +167,13 @@ let init input = let sandbox_param = Option.map (fun p -> ("sandbox_parameter", p)) sandbox_parameters in - Context.init - ~patch_context:(Patch_context.patch_context genesis sandbox_param) - context_root + timer + (fun () -> + Context.init + ~patch_context:(Patch_context.patch_context genesis sandbox_param) + context_root) + ~msg:"init request -> Context.init" + ~loc:__LOC__ >>= fun context_index -> Lwt.return ( context_index, @@ -190,11 +207,15 @@ let run input output = Events.(emit commit_genesis_request genesis.block) >>= fun () -> Error_monad.protect (fun () -> + timer + (fun () -> Context.commit_genesis context_index ~chain_id ~time:genesis.time ~protocol:genesis.protocol) + ~msg:"Commit_genesis request -> Context.commit_genesis" + ~loc:__LOC__ ) >>= fun commit -> External_validation.send output @@ -224,7 +245,11 @@ let run input output = >>= fun () -> Error_monad.protect (fun () -> let pred_context_hash = predecessor_block_header.shell.context in - Context.checkout context_index pred_context_hash + timer + (fun () -> + Context.checkout context_index pred_context_hash) + ~msg:"validate request -> Context.checkout" + ~loc:__LOC__ >>= function | Some context -> return context @@ -233,7 +258,10 @@ let run input output = (Block_validator_errors.Failed_to_checkout_context pred_context_hash)) >>=? (fun predecessor_context -> - Context.get_protocol predecessor_context + timer + (fun () -> Context.get_protocol predecessor_context) + ~msg:"validate request -> Context.get_protocol" + ~loc:__LOC__ >>= fun protocol_hash -> load_protocol protocol_hash protocol_root >>=? fun () -> @@ -274,7 +302,10 @@ let run input output = let fork_test_chain : unit Lwt.t = Events.(emit fork_test_chain_request forked_header) >>= fun () -> - Context.checkout context_index context_hash + timer + (fun () -> Context.checkout context_index context_hash) + ~msg:"Fork_test_chain request -> Context.checkout" + ~loc:__LOC__ >>= function | Some ctxt -> Block_validation.init_test_chain ctxt forked_header diff --git a/src/lib_storage/context.ml b/src/lib_storage/context.ml index 1954e17a6cc48ba179e0d82aa2a0dbcdbd218b85..3f0a12f3963dfcc85e74aefc19293ff01133433f 100644 --- a/src/lib_storage/context.ml +++ b/src/lib_storage/context.ml @@ -52,10 +52,16 @@ let reporter () = let index_log_size = ref None let () = - let verbose () = + let verbose_info () = + Logs.set_level (Some Logs.Info) ; + Logs.set_reporter (reporter ()) + in + let verbose_debug () = Logs.set_level (Some Logs.Debug) ; Logs.set_reporter (reporter ()) in + (* while testing the layered store, print stats and logs from irmin *) + verbose_info () ; let index_log_size n = index_log_size := Some (int_of_string n) in match Unix.getenv "TEZOS_STORAGE" with | exception Not_found -> @@ -64,8 +70,10 @@ let () = let args = String.split ',' v in List.iter (function - | "v" | "verbose" | "vv" -> - verbose () + | "v" | "verbose" -> + verbose_info () + | "vv" -> + verbose_debug () | v -> ( match String.split '=' v with | ["index-log-size"; n] -> @@ -81,19 +89,10 @@ module Conf = struct end module Store = - Irmin_pack.Make_ext - (struct - let io_version = `V1 - end) - (Conf) - (Metadata) - (Contents) - (Path) - (Branch) + Irmin_pack_layered.Make_ext (Conf) (Metadata) (Contents) (Path) (Branch) (Hash) (Node) (Commit) - module P = Store.Private type index = { @@ -123,19 +122,7 @@ let current_predecessor_block_metadata_hash_key = let current_predecessor_ops_metadata_hash_key = ["predecessor_ops_metadata_hash"] -let restore_integrity ?ppf index = - match Store.integrity_check ?ppf ~auto_repair:true index.repo with - | Ok (`Fixed n) -> - Ok (Some n) - | Ok `No_error -> - Ok None - | Error (`Cannot_fix msg) -> - error (failure "%s" msg) - | Error (`Corrupted n) -> - error - (failure - "unable to fix the corrupted context: %d bad entries detected" - n) +let restore_integrity ?ppf index = ignore ppf ; ignore index ; Ok None let sync index = if index.readonly then Store.sync index.repo ; @@ -182,7 +169,78 @@ let unshallow context = >|= fun _ -> ()) children) +let counter = ref 0 + +let count = ref 0 + +let first = ref true + +let total = ref 0 + +let pp_commit_stats () = + (*let get_maxrss () = + let usage = Rusage.(get Self) in + let ( / ) = Int64.div in + Int64.to_int (usage.maxrss / 1024L / 1024L) + in*) + let objs = Irmin_layers.Stats.get_adds () in + total := !total + objs ; + Irmin_layers.Stats.reset_adds () ; + Format.printf + "commit_number %d, maxrss --, objects %d\n%!" + !count + (* (get_maxrss ()) *) + objs ; + incr count + +let pp_stats () = + let stats = Irmin_layers.Stats.get () in + let pp_comma ppf () = Fmt.pf ppf "," in + let copied_objects = + let ls' = + match + List.map2 + ~when_different_lengths:() + (fun x y -> x + y) + stats.copied_contents + stats.copied_commits + with + | Error () -> + stats.copied_contents + | Ok ls -> + ls + in + match + List.map2 + ~when_different_lengths:() + (fun x y -> x + y) + ls' + stats.copied_nodes + with + | Error () -> + stats.copied_nodes + | Ok ls'' -> + ls'' + in + Format.printf + "%a Irmin stats: nb_freeze = %d copied_objects = %a waiting_freeze = %a \ + completed_freeze = %a \n\ + \ objects added in upper since last freeze = %d \n\ + @." + Time.System.pp_hum + (Systime_os.now ()) + stats.nb_freeze + Fmt.(list ~sep:pp_comma int) + copied_objects + Fmt.(list ~sep:pp_comma float) + stats.waiting_freeze + Fmt.(list ~sep:pp_comma float) + stats.completed_freeze + !total ; + total := 0 + let raw_commit ~time ?(message = "") context = + counter := succ !counter ; let info = Irmin.Info.v ~date:(Time.Protocol.to_seconds time) ~author:"Tezos" message in @@ -190,7 +248,20 @@ let raw_commit ~time ?(message = "") context = unshallow context >>= fun () -> Store.Commit.v context.index.repo ~info ~parents context.tree - >|= fun h -> + >>= fun h -> + pp_commit_stats () ; + ( if !first then ( + first := false ; + pp_stats () ; + Store.freeze ~max:[h] context.index.repo ) + else Lwt.return_unit ) + >>= fun () -> + ( if !counter = 4000 then ( + counter := 0 ; + pp_stats () ; + Store.freeze ~max:[h] context.index.repo ) + else Lwt.return_unit ) + >|= fun () -> Store.Tree.clear context.tree ; h @@ -338,10 +409,37 @@ let add_predecessor_ops_metadata_hash v hash = (*-- Initialisation ----------------------------------------------------------*) +let config ?readonly root = + let conf = + Irmin_pack.config + ?readonly + ?index_log_size:!index_log_size + ~freeze_throttle:`Cancel_existing + root + in + Irmin_pack_layered.config + ~conf + ~copy_in_upper:true + ~with_lower:false + ~blocking_copy_size:1000000 + () + let init ?patch_context ?mapsize:_ ?(readonly = false) root = - Store.Repo.v - (Irmin_pack.config ~readonly ?index_log_size:!index_log_size root) - >|= fun repo -> {path = root; repo; patch_context; readonly} + let config = config ~readonly root in + let open_store () = + Store.Repo.v config + >>= fun repo -> + let v = {path = root; repo; patch_context; readonly} in + Lwt.return v + in + Lwt.catch open_store (function + | Irmin_pack.Unsupported_version `V1 -> + Logs.app (fun l -> l "Migrating store to v2, this may take a while") ; + Store.migrate config ; + Logs.app (fun l -> l "Migration ended, opening the store") ; + open_store () + | exn -> + Lwt.fail exn) let close index = Store.Repo.close index.repo diff --git a/src/lib_storage/dune b/src/lib_storage/dune index fe4bbee2f8bcceb622c8162407ae57ab198749d4..ae59425bdf94707d81dc21154b19aaa5247ba3bd 100644 --- a/src/lib_storage/dune +++ b/src/lib_storage/dune @@ -8,6 +8,7 @@ digestif.c irmin irmin-pack + irmin-pack.layered tezos-stdlib-unix tezos-storage.sigs tezos-storage.helpers diff --git a/src/lib_validation/block_validation.ml b/src/lib_validation/block_validation.ml index 35674c427fe3fd2f73c2b811199c87ccdd9da82d..c5fa583347349e8774506a94f2fa202c3c3fc8e3 100644 --- a/src/lib_validation/block_validation.ml +++ b/src/lib_validation/block_validation.ml @@ -447,11 +447,19 @@ module Make (Proto : Registered_protocol.T) = struct ops_metadata), Some (Block_metadata_hash.hash_bytes [block_metadata]) ) ) >>=? fun (ops_metadata_hashes, block_metadata_hash) -> + let start = Systime_os.now () in Context.commit ~time:block_header.shell.timestamp ?message:validation_result.message context >>= fun context_hash -> + let elapsed = Ptime.diff (Systime_os.now ()) start in + Format.printf + "[Validator RW]: %s executed in %a@.loc: %s@." + "apply -> Context.commit" + Ptime.Span.pp + elapsed + __LOC__ ; let validation_store = { context_hash;