From 64734a75bac528a5f76bf12dd36af5684d55aa17 Mon Sep 17 00:00:00 2001 From: Pierrick Couderc Date: Fri, 21 Apr 2023 14:40:39 +0200 Subject: [PATCH 1/6] WASM/Debugger: call stack computation generic algorithm --- src/bin_wasm_debugger/profiling.ml | 124 +++++++++++++++++++++++++++++ 1 file changed, 124 insertions(+) create mode 100644 src/bin_wasm_debugger/profiling.ml diff --git a/src/bin_wasm_debugger/profiling.ml b/src/bin_wasm_debugger/profiling.ml new file mode 100644 index 000000000000..fc09cb754e52 --- /dev/null +++ b/src/bin_wasm_debugger/profiling.ml @@ -0,0 +1,124 @@ +(*****************************************************************************) +(* *) +(* Open Source License *) +(* Copyright (c) 2023 Nomadic Labs *) +(* *) +(* Permission is hereby granted, free of charge, to any person obtaining a *) +(* copy of this software and associated documentation files (the "Software"),*) +(* to deal in the Software without restriction, including without limitation *) +(* the rights to use, copy, modify, merge, publish, distribute, sublicense, *) +(* and/or sell copies of the Software, and to permit persons to whom the *) +(* Software is furnished to do so, subject to the following conditions: *) +(* *) +(* The above copyright notice and this permission notice shall be included *) +(* in all copies or substantial portions of the Software. *) +(* *) +(* THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR*) +(* IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, *) +(* FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL *) +(* THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER*) +(* LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING *) +(* FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER *) +(* DEALINGS IN THE SOFTWARE. *) +(* *) +(*****************************************************************************) + +open Tezos_scoru_wasm +open Tezos_lazy_containers +open Tezos_webassembly_interpreter +module Vector = Lazy_vector.Int32Vector + +(** Call graph representation and construction. *) + +(** The call stack computation algorithm is the following: + + There are two components: the current node (or stack frame) and the + continuation (a list of stack frames). There's a "toplevel node" describing + the execution at the toplevel of the interpreter. + A node contains: + - [id]: a function call representation (an identifier) + - [t]: the ticks elapsed during the call + - [sub]: the subcalls. + + The algorithm starts with an empty toplevel and an empty continuation. + - on function call (id, current_tick, current_node, continuation): + 1. create a node N_id: (id, t: current_tick, sub:[]) + 2. update current_node N_curr with t:(current_tick - t) + => the number of ticks is now the diff between the moment the call started + and the subcall started. + 3. push N_curr on the continuation + 4. return N_id, continuation + + - on function end (current_tick, current_node, continuation): + 1. update current_node N_curr with t:(current_tick - t) + 2. pop N_prev from the continuation + 3. update N_prev: t:(current_tick - t) sub:(sub + N_curr) + 4. return N_prev, continuation + + Let's take an example: + call: f () { ...... g () { .... h () { ...... } .......... } ......... } + tick: 0 ----------> 10 -------> 30 ---------> 60 --------> 100 -----> 160 + [ 10 ticks ] [ 20 ticks ] [ 30 ticks ] [ 40 ticks ] [ 60 ticks ] + + - `f` takes 10 + 60 = 70 ticks + - `g` takes 20 + 40 = 60 ticks + - `h` takes 30 ticks + + T ([nodes]) : toplevel + K : continuation (list) + N : current node (N(id) means it hasn't changed from previous step) + + N, K |- exec + + Start: + T, [] |- f () { g () { h () { } } } + ==> at tick 0 + N (f, 0, []), [T] |- g () { h () { } } } + ==> at tick 10 + N (g, 10, []), [N (f, 10 - 0 = 10, []); T] |- h () { } } } + ==> at tick 30 + N (h, 30, []), [N (g, 30 - 10 = 20, []); N(f); T] |- } } } + ==> at tick 60 + N (g, 60 - 20 = 40, [N (h, 60 - 30 = 30, [])]), [N(f); T] |- } } + ==> at tick 100 + N (f, 100 - 10 = 90, [N (g, 100 - 40 = 60, [N(h)])]), [T] |- } + ==> at tick 160 + T [N (f, 160 - 90 = 70, [N(g, 60, [N(h, 30, [])])])], [] |- _ + +*) + +type 'function_call call_stack = + | Node of 'function_call * Z.t * 'function_call call_stack list + | Toplevel of 'function_call call_stack list + +(** [end_function_call current_tick current_function call_stack] implements an + ending call. Please refer to the prelude of the file. *) +let end_function_call current_tick current_function call_stack = + match current_function with + | Node (call, starting_tick, subcalls) -> ( + let final_node = + Node (call, Z.sub current_tick starting_tick, List.rev subcalls) + in + match call_stack with + | [] -> assert false + | Toplevel finalized :: stack -> + (Toplevel (final_node :: finalized), stack) + | Node (call, ticks, subcalls) :: stack -> + (Node (call, Z.sub current_tick ticks, final_node :: subcalls), stack) + ) + (* A toplevel call cannot reduce. *) + | Toplevel _ -> (current_function, call_stack) + +(** [call_function called_function current_tick current_function call_stack] + implements a function start. Please refere to the prelude of the module. *) +let call_function called_function current_tick current_function call_stack = + match current_function with + | Toplevel _ as top -> + let func = Node (called_function, current_tick, []) in + (func, top :: call_stack) + | Node (current_call, ticks, subcalls) -> + let stack = + Node (current_call, Z.sub current_tick ticks, subcalls) :: call_stack + in + let func = Node (called_function, current_tick, []) in + (func, stack) -- GitLab From 9f73366ec1dcc11da0ee7db65b571d6d1a3e0186 Mon Sep 17 00:00:00 2001 From: Pierrick Couderc Date: Fri, 21 Apr 2023 14:41:53 +0200 Subject: [PATCH 2/6] WASM/Debugger: PVM call stack computation --- src/bin_wasm_debugger/profiling.ml | 196 ++++++++++++++++++++++++++++- 1 file changed, 195 insertions(+), 1 deletion(-) diff --git a/src/bin_wasm_debugger/profiling.ml b/src/bin_wasm_debugger/profiling.ml index fc09cb754e52..6a44ba0b4760 100644 --- a/src/bin_wasm_debugger/profiling.ml +++ b/src/bin_wasm_debugger/profiling.ml @@ -28,7 +28,7 @@ open Tezos_lazy_containers open Tezos_webassembly_interpreter module Vector = Lazy_vector.Int32Vector -(** Call graph representation and construction. *) +(** Call stack representation and construction. *) (** The call stack computation algorithm is the following: @@ -122,3 +122,197 @@ let call_function called_function current_tick current_function call_stack = in let func = Node (called_function, current_tick, []) in (func, stack) + +(** Profiling the execution of the PVM *) + +(** A function call can be either a direct call, a call through a reference or + an internal step of the PVM. *) +type function_call = + | CallDirect of int32 + | CallRef of int32 + | Internal of string + +let pp_call ppf = function + | CallDirect i -> Format.fprintf ppf "function[%ld]" i + | CallRef i -> Format.fprintf ppf "function_ref[%ld]" i + | Internal s -> Format.fprintf ppf "%%interpreter(%s)" s + +(** [initial_eval_call module_] creates the node with the correct identifier for + `kernel_run` according to the profiled module. *) +let initial_eval_call (module_exports : Ast.export Vector.t) = + let open Lwt_syntax in + let+ exports = Vector.to_list module_exports in + let var = + List.find_map + (function + | {Source.it = {Ast.name; edesc = {it = Ast.FuncExport var; _}}; _} + when name = Constants.wasm_entrypoint -> + Some var + | _ -> None) + exports + in + match var with Some {it = id; _} -> CallDirect id | None -> assert false + +(** [update_on_decode current_tick current_call_context] starts and stop + `internal` calls related to the {Decode} step of the PVM. *) +let update_on_decode current_tick (current_node, call_stack) = + let open Lwt_syntax in + function + | Decode.MKStart -> + return_some + @@ call_function (Internal "decode") current_tick current_node call_stack + | Decode.MKStop _ -> + let current_node, call_stack = + end_function_call current_tick current_node call_stack + in + return_some + @@ call_function (Internal "link") current_tick current_node call_stack + | _ -> return_none + +(** [update_on_link current_tick current_call_context] starts and stop + `internal` call to the {Link} step of the PVM. *) +let update_on_link current_tick (current_node, call_stack) module_ + imports_offset = + let open Lwt_syntax in + if imports_offset >= Vector.num_elements module_.Source.it.Ast.imports then + let current_node, call_stack = + end_function_call current_tick current_node call_stack + in + return_some + @@ call_function (Internal "init") current_tick current_node call_stack + else return_none + +(** [update_on_init current_tick current_call_context] starts and stop + `internal` call to the {Init} step of the PVM. *) +let update_on_init current_tick (current_node, call_stack) module_ = + let open Lwt_syntax in + function + | Eval.IK_Stop -> + let current_node, call_stack = + end_function_call current_tick current_node call_stack + in + let* start = initial_eval_call module_.Source.it.Ast.exports in + return_some @@ call_function start current_tick current_node call_stack + | _ -> return_none + +(** [update_on_instr current_tick current_node call_stack] handle function calls + during the evaluation. *) +let update_on_instr current_tick current_node call_stack = function + | Eval.Plain (Ast.Call f) -> + Lwt.return_some + (call_function + (CallDirect f.Source.it) + current_tick + current_node + call_stack) + | Eval.Plain (CallIndirect (f, _)) -> + Lwt.return_some + (call_function + (CallRef f.Source.it) + current_tick + current_node + call_stack) + | _ -> Lwt.return_none + +(** [update_on_eval current_tick current_call_context] handle function calls and + end during the evaluation. *) +let update_on_eval current_tick (current_node, call_stack) = + let open Lwt_syntax in + function + (* Instruction evaluation step *) + | Eval.(SK_Next (_, _, LS_Start (Label_stack (label, _)))) -> + let _, es = label.Eval.label_code in + if 0l < Vector.num_elements es then + let* e = Vector.get 0l es in + update_on_instr current_tick current_node call_stack e.Source.it + else return_none + (* Labels `result` or `trapped` implies the end of a function call and the pop of + the current stack frame, this can be interpreted as an end of the current + function. *) + | SK_Start ({frame_label_kont = Label_trapped _ | Label_result _; _}, _) -> + return_some @@ end_function_call current_tick current_node call_stack + (* An invocation of function that doesn't return a new stack frame implies the + current function is an host function, and it is the end of its call. *) + | SK_Next + ( _, + _, + LS_Craft_frame + (Label_stack (_, _), Inv_stop {fresh_frame = None; remaining_ticks; _}) + ) + when Z.equal Z.zero remaining_ticks -> + return_some @@ end_function_call current_tick current_node call_stack + | _ -> return_none + +(** [update_call_stack current_tick current_context_call state] returns the call + context changes for any state. Returns [None] if no change happened. *) +let update_call_stack current_tick (current_node, call_stack) state = + let open Lwt_syntax in + match state with + | Wasm_pvm_state.Internal_state.Decode {Decode.module_kont; _} -> + update_on_decode current_tick (current_node, call_stack) module_kont + | Link {ast_module; imports_offset; _} -> + update_on_link + current_tick + (current_node, call_stack) + ast_module + imports_offset + | Init {init_kont; _} -> + update_on_init current_tick (current_node, call_stack) init_kont + | Eval {config = {step_kont; _}; _} -> + update_on_eval current_tick (current_node, call_stack) step_kont + | _ -> return_none + +(** [eval_and_profile ?write_debug ?reveal_builtins tree] profiles a kernel up + to the next result, and returns the call stack. *) +let eval_and_profile ?write_debug ?reveal_builtins tree = + let open Lwt_syntax in + (* The call context is built as a side effect of the evaluation. *) + let call_stack = ref (Toplevel [], []) in + + let compute_and_snapshot pvm_state = + let* updated_stack = + update_call_stack + pvm_state.Wasm_pvm_state.Internal_state.current_tick + !call_stack + pvm_state.tick_state + in + Option.iter + (fun (current_node, current_call_stack) -> + call_stack := (current_node, current_call_stack)) + updated_stack ; + + let* input_request_val = Wasm_vm.get_info pvm_state in + match (input_request_val.input_request, pvm_state.tick_state) with + | Reveal_required _, _ when reveal_builtins = None -> return_false + | Input_required, _ | Reveal_required _, _ -> return_false + | _ -> return_true + in + let rec eval_until_input_requested accumulated_ticks tree = + let* pvm_state = + Encodings_util.Tree_encoding_runner.decode + Wasm_pvm.pvm_state_encoding + tree + in + let* info = Wasm_utils.Wasm.get_info tree in + match info.Wasm_pvm_state.input_request with + | No_input_required -> + let* tree, ticks = + Wasm_utils.Wasm.Internal_for_tests.compute_step_many_until + ?write_debug + ?reveal_builtins + ~max_steps:(Z.to_int64 pvm_state.max_nb_ticks) + compute_and_snapshot + tree + in + eval_until_input_requested + (Z.add accumulated_ticks @@ Z.of_int64 ticks) + tree + | Input_required | Reveal_required _ -> return (tree, accumulated_ticks) + in + let+ tree, ticks = eval_until_input_requested Z.zero tree in + let call_stack = + match !call_stack with + | Toplevel l, stack -> (Toplevel (List.rev l), stack) + | n -> n + in + (tree, ticks, call_stack) -- GitLab From 5f81d36d5ab2677c6eca29257a258cecfc0253fd Mon Sep 17 00:00:00 2001 From: Pierrick Couderc Date: Fri, 21 Apr 2023 14:42:40 +0200 Subject: [PATCH 3/6] WASM/Debugger: flamegraph generation and pretty-printing --- src/bin_wasm_debugger/profiling.ml | 131 +++++++++++++++++++++++++++++ 1 file changed, 131 insertions(+) diff --git a/src/bin_wasm_debugger/profiling.ml b/src/bin_wasm_debugger/profiling.ml index 6a44ba0b4760..18427199c145 100644 --- a/src/bin_wasm_debugger/profiling.ml +++ b/src/bin_wasm_debugger/profiling.ml @@ -316,3 +316,134 @@ let eval_and_profile ?write_debug ?reveal_builtins tree = | n -> n in (tree, ticks, call_stack) + +(** Flamegraph building + + Flamegraph are an aggregation of all the same callstacks, thus there is no + longer a notion of time. We can easily collapse all nodes into a single one. +*) + +module StringMap = Map.Make (String) + +(** [collapse_stack ~max_depth pp_call call_stack] collapses a call stack into a + valid flamegraph. Node deeper than [max_depth] are not considered. [pp_call] + is used to print the identifiers. *) +let collapse_stack ~max_depth pp_call call_stack = + let rec handle_node ~prefix ~depth ~max_depth accumulated_nodes = function + | Node (name, ticks, subnodes) -> + let prefix = + if prefix = "" then Format.asprintf "%a" pp_call name + else Format.asprintf "%s;%a" prefix pp_call name + in + let map = + StringMap.update + prefix + (function + | None -> Some ticks | Some prev -> Some (Z.add prev ticks)) + accumulated_nodes + in + handle_nodes ~prefix ~depth:(succ depth) ~max_depth map subnodes + | Toplevel nodes -> + handle_nodes ~prefix ~depth ~max_depth accumulated_nodes nodes + and handle_nodes ~prefix ~depth ~max_depth accumulated_nodes nodes = + if depth > max_depth then accumulated_nodes + else + List.fold_left + (fun acc node -> handle_node ~prefix ~depth ~max_depth acc node) + accumulated_nodes + nodes + in + handle_node ~prefix:"" ~depth:0 ~max_depth StringMap.empty call_stack + |> StringMap.bindings + +(** Pretty printing and flamegraph output *) + +(** [pp_indent ppf depth] prints an indentation corresponding to the given + [depth]. *) +let pp_indent ppf depth = Format.fprintf ppf "%s" (String.make (depth * 2) ' ') + +let rec pp_nodes ?(max_depth = 10) depth pp_call ppf nodes = + if depth > max_depth then () + else + Format.fprintf + ppf + "\n%a" + (Format.pp_print_list + ~pp_sep:(fun ppf () -> Format.fprintf ppf "\n") + (pp_stack (depth + 1) pp_call)) + nodes + +and pp_stack ?max_depth depth pp_call ppf = function + | Node (call, ticks, sub_nodes) -> + Format.fprintf + ppf + "%a- %a : %a ticks%a" + pp_indent + depth + pp_call + call + Z.pp_print + ticks + (pp_nodes ?max_depth depth pp_call) + sub_nodes + | Toplevel nodes -> pp_nodes ?max_depth depth pp_call ppf nodes + +(** [pp_stack ~max_depth ppf stack] pretty prints the stack. It should be used + for debug only. *) +let pp_stack ?max_depth = pp_stack ?max_depth 0 + +let rec pp_flame_callstack_node ~prefix ~depth ~max_depth pp_call ppf = function + | Node (call, ticks, subnodes) -> + let prefix = + if prefix = "" then Format.asprintf "%a" pp_call call + else Format.asprintf "%s;%a" prefix pp_call call + in + Format.fprintf + ppf + "%s %a\n%a" + prefix + Z.pp_print + ticks + (pp_flame_callstack_nodes + ~prefix + ~depth:(succ depth) + ~max_depth + pp_call) + subnodes + | Toplevel nodes -> + pp_flame_callstack_nodes ~prefix ~depth ~max_depth pp_call ppf nodes + +and pp_flame_callstack_nodes ~prefix ~depth ~max_depth pp_call ppf nodes = + if depth > max_depth then () + else + (Format.pp_print_list + ~pp_sep:(fun _ () -> ()) + (pp_flame_callstack_node ~prefix ~depth ~max_depth pp_call)) + ppf + nodes + +(** [pp_callstack_as_flamegraph] if [pp_stack] with the syntax of flamegraphs. *) +let pp_callstack_as_flamegraph ~max_depth pp_call = + (* `pp_call` is repeated to enforce generalization, it leads to a typechecking + error otherwise. *) + pp_flame_callstack_node ~prefix:"" ~depth:0 ~max_depth pp_call + +(** [pp_flamegraph] collapses the stack and print it as a valid flamegraph. *) +let pp_collapsed_flamegraph ~max_depth pp_call ppf call_stack = + let nodes = collapse_stack ~max_depth pp_call call_stack in + Format.fprintf + ppf + "%a" + (Format.pp_print_list + ~pp_sep:(fun ppf () -> Format.fprintf ppf "\n") + (fun ppf (name, ticks) -> + Format.fprintf ppf "%s %a" name Z.pp_print ticks)) + nodes + +(** [pp_flamegraph ~collapsed ~max_depth pp_call ppf call_stack] outputs the + given [call_stack] with its `flamegraph` representation. If [collapse = + true], the stacks are collapsed. This can be useful to output smaller files, + but the stack cannot be analyzed on a time basis (i.e. as a flamechart). *) +let pp_flamegraph ~collapse ~max_depth pp_call ppf call_stack = + if collapse then pp_collapsed_flamegraph ~max_depth pp_call ppf call_stack + else pp_callstack_as_flamegraph ~max_depth pp_call ppf call_stack -- GitLab From 5ec80ef44656a626014daa66bfd7a22f63b9d4d6 Mon Sep 17 00:00:00 2001 From: Pierrick Couderc Date: Fri, 21 Apr 2023 14:43:20 +0200 Subject: [PATCH 4/6] WASM/Debugger: add a `profile` command that load inputs and start profiling --- src/bin_wasm_debugger/commands.ml | 57 +++++++++++++++++++++++++++++++ 1 file changed, 57 insertions(+) diff --git a/src/bin_wasm_debugger/commands.ml b/src/bin_wasm_debugger/commands.ml index 8fb098cfa971..f0f25b053dae 100644 --- a/src/bin_wasm_debugger/commands.ml +++ b/src/bin_wasm_debugger/commands.ml @@ -50,6 +50,7 @@ type commands = | Load_inputs | Reveal_preimage of string option | Reveal_metadata + | Profile of bool | Unknown of string | Stop @@ -109,6 +110,8 @@ let parse_commands s = | ["reveal"; "metadata"] -> Reveal_metadata | ["stop"] -> Stop | ["bench"] -> Bench + | ["profile"] -> Profile false + | ["profile"; "--collapsed"] -> Profile true | _ -> Unknown s in go command @@ -220,6 +223,43 @@ let eval_until_input_requested config tree = ( tree, Z.to_int64 @@ Z.sub info_after.current_tick info_before.current_tick )) +let produce_flamegraph ~collapse ~max_depth (current_node, remaining_nodes) = + let filename = + Time.System.( + Format.asprintf "wasm-debugger-profiling-%a.out" pp_hum (now ())) + in + let path = Filename.(concat (get_temp_dir_name ()) filename) in + let file = open_out path in + if remaining_nodes <> [] then + Format.printf + "The resulting call graph is inconsistent, please open an issue.\n%!" ; + Profiling.pp_flamegraph + ~collapse + ~max_depth + Profiling.pp_call + (Format.formatter_of_out_channel file) + current_node ; + close_out file ; + Format.printf "Profiling result can be found in %s\n%!" path + +let eval_and_profile ~collapse config tree = + let open Lwt_syntax in + trap_exn (fun () -> + Format.printf + "Starting the profiling until new messages are expected. Please note \ + that it will take some time and does not reflect a real computation \ + time.\n\ + %!" ; + let+ tree, ticks, graph = + Profiling.eval_and_profile + ~write_debug + ~reveal_builtins:(reveal_builtins config) + tree + in + produce_flamegraph ~collapse ~max_depth:100 graph ; + Format.printf "The execution took %a ticks.\n%!" Z.pp_print ticks ; + tree) + let set_raw_message_input_step level counter encoded_message tree = Wasm.set_input_step (input_info level counter) encoded_message tree @@ -290,6 +330,18 @@ let eval level inboxes config step tree = return (tree, Int64.(add (of_int32 count1) count2), inboxes) | Error _ -> return' (eval_until_input_requested config tree)) +let profile ~collapse level inboxes config tree = + let open Lwt_result_syntax in + let*! status = check_input_request tree in + match status with + | Ok () -> + let* tree, inboxes, level = load_inputs inboxes level tree in + let* tree = eval_and_profile ~collapse config tree in + return (tree, inboxes, level) + | Error _ -> + let* tree = eval_and_profile ~collapse config tree in + return (tree, inboxes, level) + let pp_input_request ppf = function | Wasm_pvm_state.No_input_required -> Format.fprintf ppf "Evaluating" | Input_required -> Format.fprintf ppf "Waiting for input" @@ -608,6 +660,11 @@ let handle_command c config extra tree inboxes level = | Reveal_metadata -> let*! tree = reveal_metadata config tree in return ~tree () + | Profile collapse -> + let* tree, inboxes, level = + profile ~collapse level inboxes config tree + in + Lwt.return_ok (tree, inboxes, level) | Unknown s -> let*! () = Lwt_io.eprintf "Unknown command `%s`\n%!" s in return () -- GitLab From 4fb57af57763a732c42e89143cdfa7fab2b95377 Mon Sep 17 00:00:00 2001 From: Pierrick Couderc Date: Fri, 21 Apr 2023 15:02:40 +0200 Subject: [PATCH 5/6] WASM/Debugger: use the WASM custom section `name` for profiling --- src/bin_wasm_debugger/commands.ml | 15 ++++---- src/bin_wasm_debugger/profiling.ml | 59 +++++++++++++----------------- 2 files changed, 33 insertions(+), 41 deletions(-) diff --git a/src/bin_wasm_debugger/commands.ml b/src/bin_wasm_debugger/commands.ml index f0f25b053dae..81557496c25c 100644 --- a/src/bin_wasm_debugger/commands.ml +++ b/src/bin_wasm_debugger/commands.ml @@ -223,6 +223,8 @@ let eval_until_input_requested config tree = ( tree, Z.to_int64 @@ Z.sub info_after.current_tick info_before.current_tick )) +type extra = {functions : string Custom_section.FuncMap.t} + let produce_flamegraph ~collapse ~max_depth (current_node, remaining_nodes) = let filename = Time.System.( @@ -242,7 +244,7 @@ let produce_flamegraph ~collapse ~max_depth (current_node, remaining_nodes) = close_out file ; Format.printf "Profiling result can be found in %s\n%!" path -let eval_and_profile ~collapse config tree = +let eval_and_profile ~collapse config extra tree = let open Lwt_syntax in trap_exn (fun () -> Format.printf @@ -254,6 +256,7 @@ let eval_and_profile ~collapse config tree = Profiling.eval_and_profile ~write_debug ~reveal_builtins:(reveal_builtins config) + extra.functions tree in produce_flamegraph ~collapse ~max_depth:100 graph ; @@ -330,16 +333,16 @@ let eval level inboxes config step tree = return (tree, Int64.(add (of_int32 count1) count2), inboxes) | Error _ -> return' (eval_until_input_requested config tree)) -let profile ~collapse level inboxes config tree = +let profile ~collapse level inboxes config extra tree = let open Lwt_result_syntax in let*! status = check_input_request tree in match status with | Ok () -> let* tree, inboxes, level = load_inputs inboxes level tree in - let* tree = eval_and_profile ~collapse config tree in + let* tree = eval_and_profile ~collapse config extra tree in return (tree, inboxes, level) | Error _ -> - let* tree = eval_and_profile ~collapse config tree in + let* tree = eval_and_profile ~collapse config extra tree in return (tree, inboxes, level) let pp_input_request ppf = function @@ -562,8 +565,6 @@ let show_memory tree address length kind = state | exn -> Lwt_io.printf "Error: %s\n%!" (Printexc.to_string exn)) -type extra = {functions : string Custom_section.FuncMap.t} - let dump_function_symbols extra = let functions = Format.asprintf "%a" Custom_section.pp_function_subsection extra.functions @@ -662,7 +663,7 @@ let handle_command c config extra tree inboxes level = return ~tree () | Profile collapse -> let* tree, inboxes, level = - profile ~collapse level inboxes config tree + profile ~collapse level inboxes config extra tree in Lwt.return_ok (tree, inboxes, level) | Unknown s -> diff --git a/src/bin_wasm_debugger/profiling.ml b/src/bin_wasm_debugger/profiling.ml index 18427199c145..28d017525756 100644 --- a/src/bin_wasm_debugger/profiling.ml +++ b/src/bin_wasm_debugger/profiling.ml @@ -128,30 +128,19 @@ let call_function called_function current_tick current_function call_stack = (** A function call can be either a direct call, a call through a reference or an internal step of the PVM. *) type function_call = + | Function of string | CallDirect of int32 | CallRef of int32 | Internal of string let pp_call ppf = function + | Function f -> Format.fprintf ppf "%s" f | CallDirect i -> Format.fprintf ppf "function[%ld]" i | CallRef i -> Format.fprintf ppf "function_ref[%ld]" i | Internal s -> Format.fprintf ppf "%%interpreter(%s)" s -(** [initial_eval_call module_] creates the node with the correct identifier for - `kernel_run` according to the profiled module. *) -let initial_eval_call (module_exports : Ast.export Vector.t) = - let open Lwt_syntax in - let+ exports = Vector.to_list module_exports in - let var = - List.find_map - (function - | {Source.it = {Ast.name; edesc = {it = Ast.FuncExport var; _}}; _} - when name = Constants.wasm_entrypoint -> - Some var - | _ -> None) - exports - in - match var with Some {it = id; _} -> CallDirect id | None -> assert false +(** [initial_eval_call] is `kernel_run` function call. *) +let initial_eval_call = Function Constants.wasm_entrypoint (** [update_on_decode current_tick current_call_context] starts and stop `internal` calls related to the {Decode} step of the PVM. *) @@ -184,27 +173,27 @@ let update_on_link current_tick (current_node, call_stack) module_ (** [update_on_init current_tick current_call_context] starts and stop `internal` call to the {Init} step of the PVM. *) -let update_on_init current_tick (current_node, call_stack) module_ = +let update_on_init current_tick (current_node, call_stack) = let open Lwt_syntax in function | Eval.IK_Stop -> let current_node, call_stack = end_function_call current_tick current_node call_stack in - let* start = initial_eval_call module_.Source.it.Ast.exports in - return_some @@ call_function start current_tick current_node call_stack + return_some + @@ call_function initial_eval_call current_tick current_node call_stack | _ -> return_none (** [update_on_instr current_tick current_node call_stack] handle function calls during the evaluation. *) -let update_on_instr current_tick current_node call_stack = function +let update_on_instr current_tick current_node call_stack symbols = function | Eval.Plain (Ast.Call f) -> - Lwt.return_some - (call_function - (CallDirect f.Source.it) - current_tick - current_node - call_stack) + let id = + match Custom_section.FuncMap.find f.Source.it symbols with + | None -> CallDirect f.Source.it + | Some f -> Function f + in + Lwt.return_some (call_function id current_tick current_node call_stack) | Eval.Plain (CallIndirect (f, _)) -> Lwt.return_some (call_function @@ -216,7 +205,7 @@ let update_on_instr current_tick current_node call_stack = function (** [update_on_eval current_tick current_call_context] handle function calls and end during the evaluation. *) -let update_on_eval current_tick (current_node, call_stack) = +let update_on_eval current_tick (current_node, call_stack) symbols = let open Lwt_syntax in function (* Instruction evaluation step *) @@ -224,7 +213,7 @@ let update_on_eval current_tick (current_node, call_stack) = let _, es = label.Eval.label_code in if 0l < Vector.num_elements es then let* e = Vector.get 0l es in - update_on_instr current_tick current_node call_stack e.Source.it + update_on_instr current_tick current_node call_stack symbols e.Source.it else return_none (* Labels `result` or `trapped` implies the end of a function call and the pop of the current stack frame, this can be interpreted as an end of the current @@ -243,9 +232,10 @@ let update_on_eval current_tick (current_node, call_stack) = return_some @@ end_function_call current_tick current_node call_stack | _ -> return_none -(** [update_call_stack current_tick current_context_call state] returns the call - context changes for any state. Returns [None] if no change happened. *) -let update_call_stack current_tick (current_node, call_stack) state = +(** [update_call_stack current_tick current_context_call symbols state] returns + the call context changes for any state. Returns [None] if no change + happened. *) +let update_call_stack current_tick (current_node, call_stack) symbols state = let open Lwt_syntax in match state with | Wasm_pvm_state.Internal_state.Decode {Decode.module_kont; _} -> @@ -259,12 +249,12 @@ let update_call_stack current_tick (current_node, call_stack) state = | Init {init_kont; _} -> update_on_init current_tick (current_node, call_stack) init_kont | Eval {config = {step_kont; _}; _} -> - update_on_eval current_tick (current_node, call_stack) step_kont + update_on_eval current_tick (current_node, call_stack) symbols step_kont | _ -> return_none -(** [eval_and_profile ?write_debug ?reveal_builtins tree] profiles a kernel up - to the next result, and returns the call stack. *) -let eval_and_profile ?write_debug ?reveal_builtins tree = +(** [eval_and_profile ?write_debug ?reveal_builtins symbols tree] profiles a + kernel up to the next result, and returns the call stack. *) +let eval_and_profile ?write_debug ?reveal_builtins symbols tree = let open Lwt_syntax in (* The call context is built as a side effect of the evaluation. *) let call_stack = ref (Toplevel [], []) in @@ -274,6 +264,7 @@ let eval_and_profile ?write_debug ?reveal_builtins tree = update_call_stack pvm_state.Wasm_pvm_state.Internal_state.current_tick !call_stack + symbols pvm_state.tick_state in Option.iter -- GitLab From 42f8b35304ebf455fde50499e42233f984373e56 Mon Sep 17 00:00:00 2001 From: Pierrick Couderc Date: Tue, 2 May 2023 13:00:25 +0200 Subject: [PATCH 6/6] Changelog: add an entry for the WASM profiler --- CHANGES.rst | 3 +++ 1 file changed, 3 insertions(+) diff --git a/CHANGES.rst b/CHANGES.rst index dbc762391337..9e6b3fc07b47 100644 --- a/CHANGES.rst +++ b/CHANGES.rst @@ -191,6 +191,9 @@ Smart Rollup WASM Debugger - Added a command ``show function symbols`` to inspect the custom section ``name`` of unstripped kernels (MR :gl:`!8522`) +- Added a command ``profile`` that runs a full ``kernel_run`` and produces a + flamegraph of the execution (MR :gl:`!8510`). + Miscellaneous ------------- -- GitLab