From be1367b5cc8519d9c24e3bfcde62e307f8d6b235 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ole=20Kr=C3=BCger?= Date: Tue, 17 Sep 2024 13:22:00 +0100 Subject: [PATCH] WasmDebugger: Write timings to file --- src/lib_wasm_debugger/commands.ml | 60 +++++++++++++--------- src/lib_wasm_debugger/config.ml | 4 +- src/lib_wasm_debugger/timing_buffer.ml | 68 +++++++++++++++++++++++++ src/lib_wasm_debugger/timing_buffer.mli | 18 +++++++ src/lib_wasm_debugger/wasm_debugger.ml | 28 ++++++++-- 5 files changed, 148 insertions(+), 30 deletions(-) create mode 100644 src/lib_wasm_debugger/timing_buffer.ml create mode 100644 src/lib_wasm_debugger/timing_buffer.mli diff --git a/src/lib_wasm_debugger/commands.ml b/src/lib_wasm_debugger/commands.ml index 876a0f349c65..da513686471a 100644 --- a/src/lib_wasm_debugger/commands.ml +++ b/src/lib_wasm_debugger/commands.ml @@ -435,9 +435,18 @@ let reveals config request = request_dal_page config num_retries published_level index page_index let write_debug_default config = - if config.Config.kernel_debug then - Tezos_scoru_wasm.Builtins.Printer (fun msg -> Lwt_fmt.printf "%s%!" msg) - else Tezos_scoru_wasm.Builtins.Noop + match config.Config.timings_file with + | None when config.Config.kernel_debug -> + Tezos_scoru_wasm.Builtins.Printer (Lwt_io.printf "%s%!") + | None -> Tezos_scoru_wasm.Builtins.Noop + | Some timings_file -> + let console = Timing_buffer.create () in + let out = open_out timings_file in + Gc.finalise (Timing_buffer.flush_buffer console) out ; + Tezos_scoru_wasm.Builtins.Printer + (fun msg -> + Timing_buffer.add_message console out msg ; + Lwt.return_unit) module Make (Wasm_utils : Wasm_utils_intf.S) = struct module Prof = Profiling.Make (Wasm_utils) @@ -445,13 +454,13 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct (* [compute_step tree] is a wrapper around [Wasm_pvm.compute_step] that also returns the number of ticks elapsed (whi is always 1). *) - let compute_step config tree = + let compute_step ~write_debug tree = let open Lwt_syntax in trap_exn (fun () -> let+ tree = Wasm.compute_step_with_debug ~wasm_entrypoint:Constants.wasm_entrypoint - ~write_debug:(write_debug_default config) + ~write_debug tree in (tree, 1L)) @@ -459,16 +468,13 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct (** [eval_to_result tree] tries to evaluates the PVM until the next `SK_Result` or `SK_Trap`, and stops in case of reveal tick or input tick. It has the property that the memory hasn't been flushed yet and can be inspected. *) - let eval_to_result config tree = + let eval_to_result ?write_debug config tree = trap_exn (fun () -> - eval_to_result - ~write_debug:(write_debug_default config) - ~reveal_builtins:(reveals config) - tree) + eval_to_result ?write_debug ~reveal_builtins:(reveals config) tree) (* [eval_kernel_run tree] evals up to the end of the current `kernel_run` (or starts a new one if already at snapshot point). *) - let eval_kernel_run ?hooks ~wasm_entrypoint config tree = + let eval_kernel_run ?hooks ?write_debug ~wasm_entrypoint config tree = let open Lwt_syntax in trap_exn (fun () -> let* info_before = Wasm.get_info tree in @@ -477,7 +483,7 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct ?hooks ~wasm_entrypoint ~reveal_builtins:(reveals config) - ~write_debug:(write_debug_default config) + ?write_debug ~stop_at_snapshot:true ~max_steps:Int64.max_int tree @@ -491,9 +497,6 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct let eval_until_input_requested ?hooks ?write_debug ~wasm_entrypoint config tree = let open Lwt_syntax in - let write_debug = - Option.value ~default:(write_debug_default config) write_debug - in trap_exn (fun () -> let* info_before = Wasm.get_info tree in let* tree = @@ -502,7 +505,7 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct ~wasm_entrypoint ~fast_exec:true ~reveal_builtins:(Some (reveals config)) - ~write_debug + ?write_debug ~max_steps:Int64.max_int tree in @@ -635,7 +638,7 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct return (tree, inboxes, level) (* Eval dispatcher. *) - let eval ?hooks ?migrate_to ?write_debug ~wasm_entrypoint level inboxes config + let eval ?hooks ?migrate_to ~write_debug ~wasm_entrypoint level inboxes config step tree = let open Lwt_result_syntax in let return' ?(inboxes = inboxes) f = @@ -643,10 +646,11 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct return (tree, count, inboxes, level) in match step with - | Tick -> return' (compute_step config tree) - | Result -> return' (eval_to_result config tree) + | Tick -> return' (compute_step ~write_debug tree) + | Result -> return' (eval_to_result ~write_debug config tree) | Kernel_run -> - return' (eval_kernel_run ?hooks ~wasm_entrypoint config tree) + return' + (eval_kernel_run ?hooks ~write_debug ~wasm_entrypoint config tree) | Inbox -> ( let*! status = check_input_request tree in match status with @@ -657,7 +661,7 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct let* tree, ticks = eval_until_input_requested ?hooks - ?write_debug + ~write_debug ~wasm_entrypoint config tree @@ -665,7 +669,12 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct return (tree, ticks, inboxes, level) | Error _ -> return' - (eval_until_input_requested ?hooks ~wasm_entrypoint config tree)) + (eval_until_input_requested + ?hooks + ~write_debug + ~wasm_entrypoint + config + tree)) let profile ?migrate_to ~collapse ~with_time ~no_reboot level inboxes config function_symbols tree = @@ -743,10 +752,10 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct (* [step level inboxes config kind tree] evals according to the step kind and prints the number of ticks elapsed and the new status. *) - let step ~wasm_entrypoint level inboxes config kind tree = + let step ~write_debug ~wasm_entrypoint level inboxes config kind tree = let open Lwt_result_syntax in let* tree, ticks, inboxes, level = - eval ~wasm_entrypoint level inboxes config kind tree + eval ~write_debug ~wasm_entrypoint level inboxes config kind tree in let*! () = Lwt_fmt.printf "Evaluation took %Ld ticks so far\n" ticks in let*! () = show_status tree in @@ -1052,7 +1061,7 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct (* [handle_command command tree inboxes level] dispatches the commands to their actual implementation. *) - let handle_command c config tree inboxes level = + let handle_command ~write_debug c config tree inboxes level = let open Lwt_result_syntax in let command = parse_commands c in let return ?(tree = tree) ?(inboxes = inboxes) () = @@ -1077,6 +1086,7 @@ module Make (Wasm_utils : Wasm_utils_intf.S) = struct return () | Step kind -> step + ~write_debug ~wasm_entrypoint:Constants.wasm_entrypoint level inboxes diff --git a/src/lib_wasm_debugger/config.ml b/src/lib_wasm_debugger/config.ml index a97f6f5ccb0c..0078ad790981 100644 --- a/src/lib_wasm_debugger/config.ml +++ b/src/lib_wasm_debugger/config.ml @@ -48,6 +48,7 @@ type config = { dal_pages_directory : string; kernel_debug : bool; flamecharts_directory : string; + timings_file : string option; } let config ?(sender = default_sender) ?(source = default_source) @@ -55,7 +56,7 @@ let config ?(sender = default_sender) ?(source = default_source) ?(preimage_directory = default_preimage_directory) ?preimage_endpoint ?(dal_pages_directory = default_dal_pages_directory) ?(kernel_debug = default_kernel_debug) - ?(flamecharts_directory = default_flamecharts_directory) () = + ?(flamecharts_directory = default_flamecharts_directory) ?timings_file () = { sender; source; @@ -65,4 +66,5 @@ let config ?(sender = default_sender) ?(source = default_source) dal_pages_directory; kernel_debug; flamecharts_directory; + timings_file; } diff --git a/src/lib_wasm_debugger/timing_buffer.ml b/src/lib_wasm_debugger/timing_buffer.ml new file mode 100644 index 000000000000..16775c209b31 --- /dev/null +++ b/src/lib_wasm_debugger/timing_buffer.ml @@ -0,0 +1,68 @@ +(*****************************************************************************) +(* *) +(* SPDX-License-Identifier: MIT *) +(* SPDX-FileCopyrightText: 2024 TriliTech *) +(* *) +(*****************************************************************************) + +type t = { + elapsed : float ref; (** Elapsed time at the start of the current line *) + base : float; (** Time at the start *) + buffer : Buffer.t; (** Current line being buffered *) +} + +let create () = + {elapsed = ref 0.0; base = Unix.gettimeofday (); buffer = Buffer.create 1024} + +let line_encoding = + let open Data_encoding in + let elapsed_encoding = + conv + (fun timestamp -> + (* The timestamp is in seconds, but we need to split it into seconds and nanoseconds. *) + let secs = Float.floor timestamp in + let nanos = (timestamp -. secs) *. 1_000_000_000.0 |> Float.round in + (secs, nanos)) + (fun (secs, nanos) -> secs +. (nanos /. 1_000_000_000.0)) + (obj2 (req "secs" float) (req "nanos" float)) + in + obj2 (req "elapsed" elapsed_encoding) (req "message" string) + +let flush_buffer console out = + (* Add a line of JSON representing the timed message to the output channel. *) + let add_json elapsed line = + let json = + let open Data_encoding in + Json.construct line_encoding (elapsed, line) + |> Json.to_string ~newline:false ~minify:true + in + Printf.fprintf out "%s\n%!" json + in + (* There is no point in flushing anything if the message is going to be empty. *) + if Buffer.length console.buffer > 0 then ( + let line = Buffer.contents console.buffer in + let elapsed = !(console.elapsed) in + add_json elapsed line ; + (* The buffer must be emptied to avoid sending the same message prefix multiple times. *) + Buffer.reset console.buffer) + +let check_elapsed_time console = + (* If we're starting a new buffered line, we need to track when it began. *) + if Buffer.length console.buffer = 0 then + console.elapsed := Unix.gettimeofday () -. console.base + +let rec add_lines console out lines = + check_elapsed_time console ; + match lines with + | [] -> () + | [message] -> + (* There are no line endings in the message, so we don't flush. *) + Buffer.add_string console.buffer message + | first :: remaining_lines -> + Buffer.add_string console.buffer first ; + (* There is a line ending after `first`, so we flush it. *) + flush_buffer console out ; + add_lines console out remaining_lines + +let add_message console out line = + add_lines console out (String.split_on_char '\n' line) diff --git a/src/lib_wasm_debugger/timing_buffer.mli b/src/lib_wasm_debugger/timing_buffer.mli new file mode 100644 index 000000000000..7dbacccad314 --- /dev/null +++ b/src/lib_wasm_debugger/timing_buffer.mli @@ -0,0 +1,18 @@ +(*****************************************************************************) +(* *) +(* SPDX-License-Identifier: MIT *) +(* SPDX-FileCopyrightText: 2024 TriliTech *) +(* *) +(*****************************************************************************) + +(** Timing buffer which records elapsed time associated with each line written to it *) +type t + +(** Create a new timing buffer. *) +val create : unit -> t + +(** Add a message. If there is something to output it will be written to the provided channel. *) +val add_message : t -> out_channel -> string -> unit + +(** Flush the buffer contents to the given channel. *) +val flush_buffer : t -> out_channel -> unit diff --git a/src/lib_wasm_debugger/wasm_debugger.ml b/src/lib_wasm_debugger/wasm_debugger.ml index 4a0748f9174e..58f38d7475ae 100644 --- a/src/lib_wasm_debugger/wasm_debugger.ml +++ b/src/lib_wasm_debugger/wasm_debugger.ml @@ -24,6 +24,8 @@ (*****************************************************************************) module Make (Wasm : Wasm_utils_intf.S) = struct + let write_debug_default = Commands.write_debug_default + module Commands = Commands.Make (Wasm) let parse_binary_module name module_ = @@ -156,13 +158,20 @@ module Make (Wasm : Wasm_utils_intf.S) = struct (* REPL main loop: reads an input, does something out of it, then loops. *) let repl tree inboxes level config = let open Lwt_result_syntax in + let write_debug = write_debug_default config in let rec loop tree inboxes level = let*! () = Lwt_io.printf "> " in let*! input = Option.catch_s (fun () -> Lwt_io.read_line Lwt_io.stdin) in match input with | Some command -> let* ctx = - Commands.handle_command command config tree inboxes level + Commands.handle_command + ~write_debug + command + config + tree + inboxes + level in Option.fold_f ~none:(fun () -> return tree) @@ -305,6 +314,14 @@ module Make (Wasm : Wasm_utils_intf.S) = struct let open Tezos_clic in switch ~doc:"Hides the kernel debug messages." ~long:"no-kernel-debug" () + let timings_file_arg = + let open Tezos_clic in + arg + ~doc:"Write timed debug messages to this file" + ~long:"timings-file" + ~placeholder:"timings.log" + (Tezos_clic.parameter (fun _ -> Lwt_result.return)) + let flamecharts_directory_arg = let open Tezos_clic in arg @@ -336,7 +353,7 @@ module Make (Wasm : Wasm_utils_intf.S) = struct let global_options = Tezos_clic.( - args10 + args11 wasm_arg input_arg rollup_arg @@ -346,7 +363,8 @@ module Make (Wasm : Wasm_utils_intf.S) = struct no_kernel_debug_flag plugins_arg installer_config_arg - flamecharts_directory_arg) + flamecharts_directory_arg + timings_file_arg) let handle_plugin_file f = try Dynlink.loadfile f with @@ -370,7 +388,8 @@ module Make (Wasm : Wasm_utils_intf.S) = struct no_kernel_debug_flag, plugins, installer_config, - flamecharts_directory ), + flamecharts_directory, + timings_file ), _ ) = Tezos_clic.parse_global_options global_options () args in @@ -386,6 +405,7 @@ module Make (Wasm : Wasm_utils_intf.S) = struct ?preimage_directory ?dal_pages_directory ?flamecharts_directory + ?timings_file ~kernel_debug:(not no_kernel_debug_flag) () in -- GitLab