diff --git a/docs/developer/ppx_profiler.rst b/docs/developer/ppx_profiler.rst index 8a53ce509e3e459063cdd5c28a18c7c521b0eeea..572841b8adebf0529172e4358ff63d17d635df13 100644 --- a/docs/developer/ppx_profiler.rst +++ b/docs/developer/ppx_profiler.rst @@ -26,11 +26,11 @@ That can be used like this .. code-block:: OCaml - Profiler.aggregate_f "advertise mempool" @@ fun () -> + Profiler.aggregate_f ~verbosity:Info ("advertise mempool", []) @@ fun () -> advertise pv_shell advertisable_mempool; let* _res = - Profiler.aggregate_s "set mempool" @@ fun () -> + Profiler.aggregate_s ~verbosity:Info ("set mempool", []) @@ fun () -> set_mempool pv_shell our_mempool in ... @@ -48,13 +48,13 @@ This will allow to preprocess .. code-block:: OCaml - () [@profiler.record "merge store"] ; + () [@profiler.record {verbosity = Info} "merge store"] ; into .. code-block:: OCaml - Profiler.record "merge store" ; + Profiler.record ~verbosity:Info ("merge store", []) ; () ; It should be noted that a ``Profiler`` module has to be available and has to @@ -64,17 +64,17 @@ can be obtained with ``module Profiler = (val Profiler.wrap my_profiler)``. Of course you can create any module with this signature but in case you didn't name it ``Profiler`` (let's say you name it ``My_profiler``) you'll have to -declare your PPX attribute with a ``profiler_module`` field: +declare your PPX attributes with a ``profiler_module`` field: .. code-block:: OCaml - () [@profiler.record {profiler_module = My_profiler} "merge store"] ; + () [@profiler.record {verbosity = Info; profiler_module = My_profiler} "merge store"] ; This will be preprocessed into .. code-block:: OCaml - My_profiler.record "merge store" ; + My_profiler.record ~verbosity:Info ("merge store", []) ; () ; @@ -89,20 +89,18 @@ There are three types of functions in the Profiler library. These functions are (for details about them, look at the :doc:`./profiler_module` document) -- ``aggregate : ?verbosity:verbosity -> string -> unit`` -- ``mark : ?verbosity:verbosity -> string list -> unit`` -- ``record : ?verbosity:verbosity -> string -> unit`` -- ``stamp : ?verbosity:verbosity -> string -> unit`` +- ``aggregate : verbosity:verbosity -> string * metadata -> unit`` +- ``mark : verbosity:verbosity -> string list * metadata -> unit`` +- ``record : verbosity:verbosity -> string * metadata -> unit`` +- ``stamp : verbosity:verbosity -> string * metadata -> unit`` - ``stop : unit -> unit`` -- ``reset_block_section: Block_hash.t -> unit`` (a utility function that calls - ``stop`` and ``record`` for each new block profiled) The PPX allows to replace .. code-block:: OCaml - Profiler.reset_block_section Block_repr.hash new_head; - Profiler.record "merge store"; + Profiler.stop (); + Profiler.record ~verbosity:Info ("merge store", []); ... with @@ -110,16 +108,16 @@ with .. code-block:: OCaml () - [@profiler.reset_block_section Block_repr.hash new_head] - [@profiler.record "merge store"] ; + [@profiler.stop] + [@profiler.record {verbosity = Info} "merge store"] ; ... You can also decompose it to be sure of the evaluation order: .. code-block:: OCaml - () [@profiler.reset_block_section Block_repr.hash new_head] ; - () [@profiler.record "merge store"] ; + () [@profiler.stop] ; + () [@profiler.record {verbosity = Info} "merge store"] ; ... 2. Wrapping functions @@ -127,25 +125,25 @@ You can also decompose it to be sure of the evaluation order: These functions are: -- ``aggregate_f : ?verbosity:verbosity -> string -> (unit -> 'a) -> 'a`` -- ``aggregate_s : ?verbosity:verbosity -> string -> (unit -> 'a Lwt.t) -> 'a Lwt.t`` -- ``record_f : ?verbosity:verbosity -> string -> (unit -> 'a) -> 'a`` -- ``record_s : ?verbosity:verbosity -> string -> (unit -> 'a Lwt.t) -> 'a Lwt.t`` -- ``span_f : ?verbosity:verbosity -> string list -> (unit -> 'a) -> 'a`` -- ``span_s : ?verbosity:verbosity -> string list -> (unit -> 'a Lwt.t) -> 'a Lwt.t`` +- ``aggregate_f : verbosity:verbosity -> string * metadata -> (unit -> 'a) -> 'a`` +- ``aggregate_s : verbosity:verbosity -> string * metadata -> (unit -> 'a Lwt.t) -> 'a Lwt.t`` +- ``record_f : verbosity:verbosity -> string * metadata -> (unit -> 'a) -> 'a`` +- ``record_s : verbosity:verbosity -> string * metadata -> (unit -> 'a Lwt.t) -> 'a Lwt.t`` +- ``span_f : verbosity:verbosity -> string list * metadata -> (unit -> 'a) -> 'a`` +- ``span_s : verbosity:verbosity -> string list * metadata -> (unit -> 'a Lwt.t) -> 'a Lwt.t`` The PPX allows to replace .. code-block:: OCaml - (Profiler.record_f "read_test_line" @@ fun () -> read_test_line ()) + (Profiler.record_f ~verbosity:Info ("read_test_line", []) @@ fun () -> read_test_line ()) ... with .. code-block:: OCaml - (read_test_line () [@profiler.record_f "read_test_line"]) + (read_test_line () [@profiler.record_f {verbosity = Info} "read_test_line"]) ... 3. Custom functions @@ -214,6 +212,7 @@ The payload is made of two parts, the first one being optional: field ::= | verbosity = (Notice | Info | Debug) | profiler_module = module_ident + | metadata = <(string * string) list> args ::= | | | ident | empty @@ -230,7 +229,7 @@ will be preprocessed as .. code-block:: OCaml Profiler.aggregate_s ~verbosity:Info (g y z) @@ f x ; - Prof.span_f ~verbosity:Debug "label" @@ g x + Prof.span_f ~verbosity:Debug ("label", []) @@ g x ... Adding functionalities diff --git a/docs/developer/profiler_module.rst b/docs/developer/profiler_module.rst index 45f24e7d30a6c62654275db6c76ab447882e37b7..4e217d4545fa7132694c6820d81b056104d8a166 100644 --- a/docs/developer/profiler_module.rst +++ b/docs/developer/profiler_module.rst @@ -75,7 +75,7 @@ anything useful for now. Why is that? Because you need to attach it to a A ``backend`` is defined in two steps: -- Select a ``Driver`` (like "this driver writes text files in a unix +- Select a ``Driver`` (like "this driver writes text files in an unix filesystem") - Define a specific ``instance`` of a ``Driver`` (like "this driver will write in this file with this level of detail") @@ -84,13 +84,30 @@ Octez already provides two ``Drivers``: .. code-block:: OCaml - val auto_write_as_txt_to_file + val auto_write_as_txt_to_file : (string * Profiler.verbosity) Profiler.driver - val auto_write_as_json_to_file + val auto_write_as_json_to_file : (string * Profiler.verbosity) Profiler.driver -These ``Drivers`` are specifically crafted to write text or JSON files in a Unix +These ``Drivers`` are specifically crafted to write text or JSON files in an Unix filesystem. As you can see, they expect two 'arguments', a ``string`` (where to -write) and a ``Profiler.verbosity`` (the level of detail expected from the profiler). +write) and a ``Profiler.verbosity`` (the maximum level of detail/verbosity +expected from the profiler). + +.. code-block:: OCaml + + type verbosity = Notice | Info | Debug + +For this tutorial, we will use ``verbosity = Info``, but developers are +encouraged to use their preferred option. + +To choose the verbosity of the profiler at runtime, the ``PROFILING`` +environment variable is used. It follows the same pattern as the ``TEZOS_LOG`` +environment variable (see :doc:`../user/logging`). + +Starting a node with +``PROFILING='shell_profiling->Notice;mempool_profiling->Debug'`` will set the +maximum verbosity for these two profilers and execute the rest of the profilers +with no maximal verbosity. We can now easily create an instance for a ``Driver``: @@ -122,7 +139,7 @@ different files or with different format). Since it would be a little bit annoying to call each functions by giving it ``read_profiler`` as a parameter, the ``Profiler`` module offers a convenient -function that creates a module allowing to call all the ``profiler`` functions +function that creates a module allowing to call all the ``read_profiler`` functions without providing it: .. code-block:: OCaml @@ -140,7 +157,7 @@ code. module Read_profiler = (val Profiler.wrap read_profiler) -Since ``read_profiler`` is already plugged to ``read_instance``, calling +Since ``Read_profiler`` is already plugged to ``read_instance``, calling ``Read_profiler`` functions will work as expected. We can now start monitoring our code. We can start with a simple change: @@ -148,10 +165,15 @@ We can now start monitoring our code. We can start with a simple change: .. code-block:: OCaml let () = - Profiler.plug instance ; - (Profiler.record_f "read_test_line" @@ fun () -> read_test_line ()) ; - (Profiler.record_f "read_test_int" @@ fun () -> read_test_int ()) ; - Profiler.record_f "read_test_scanf" @@ fun () -> read_test_scanf () + Read_profiler.plug instance ; + (Read_profiler.record_f ~verbosity:Info ("read_test_line", []) @@ fun () -> read_test_line ()) ; + (Read_profiler.record_f ~verbosity:Info ("read_test_int", []) @@ fun () -> read_test_int ()) ; + Read_profiler.record_f ~verbosity:Info ("read_test_scanf", []) @@ fun () -> read_test_scanf () + +Note: the ``Read_profiler`` functions take a ``(id, metadata) : string * metadata`` as their +first parameter: +- ``id`` is used to create sections and represent the part being profiled by the function +- ``metadata`` is used by backends that need specific informations (like Prometheus) Looking at the result gives us: @@ -166,13 +188,12 @@ monitor our functions more precisely: .. code-block:: OCaml - let profiler = Profiler.unplugged () + let profiler = Read_profiler.unplugged () - module Profiler = (val Profiler.wrap profiler) + module Read_profiler = (val Profiler.wrap profiler) let instance = - Tezos_base.Profiler.instance - Tezos_base_unix.Simple_profiler.auto_write_as_txt_to_file + Profiler.instance Tezos_base_unix.Simple_profiler.auto_write_as_txt_to_file ("/tmp/test_profiler.txt", Profiler.Info) let read_int ic = @@ -184,54 +205,54 @@ monitor our functions more precisely: aux 0 let read_test_int () = - Profiler.record_f "read_test_int" @@ fun () -> - let ic = Profiler.aggregate_f "open_in" @@ fun () -> open_in sample in + Read_profiler.record_f ~verbosity:Info ("read_test_int", []) @@ fun () -> + let ic = Read_profiler.aggregate_f ~verbosity:Info ("open_in", []) @@ fun () -> open_in sample in let max = ref 0 in try while true do - Profiler.aggregate_f "read_int" @@ fun () -> + Read_profiler.aggregate_f ~verbosity:Info ("read_int", []) @@ fun () -> read_int ic |> fun e -> if e > !max then max := e done with End_of_file -> - Profiler.aggregate_f "close_in" @@ fun () -> + Read_profiler.aggregate_f ~verbosity:Info ("close_in", []) @@ fun () -> close_in ic ; Format.eprintf "%d@." !max let read_test_line () = - Profiler.record_f "read_test_line" @@ fun () -> - let ic = Profiler.aggregate_f "open_in" @@ fun () -> open_in sample in + Read_profiler.record_f ~verbosity:Info ("read_test_line", []) @@ fun () -> + let ic = Read_profiler.aggregate_f ~verbosity:Info ("open_in", []) @@ fun () -> open_in sample in let max = ref 0 in try while true do - Profiler.span_f ["input_line"] @@ fun () -> + Read_profiler.span_f ~verbosity:Info (["input_line"], []) @@ fun () -> input_line ic |> String.split_on_char ' ' |> List.iter (fun e -> let e = int_of_string e in if e > !max then max := e) done with End_of_file -> - Profiler.aggregate_f "close_in" @@ fun () -> + Read_profiler.aggregate_f ~verbosity:Info ("close_in", []) @@ fun () -> close_in ic ; Format.eprintf "%d@." !max let read_test_scanf () = - Profiler.record_f "read_test_scanf" @@ fun () -> + Read_profiler.record_f ~verbosity:Info ("read_test_scanf", []) @@ fun () -> let ic = - Profiler.aggregate_f "open_in" @@ fun () -> Scanf.Scanning.open_in sample + Read_profiler.aggregate_f ~verbosity:Info ("open_in", []) @@ fun () -> Scanf.Scanning.open_in sample in let max = ref 0 in try while true do - Profiler.mark ["Scanf.bscanf"] ; + Read_profiler.mark ~verbosity:Info (["Scanf.bscanf"], []) ; Scanf.bscanf ic "%d " (fun i -> i) |> fun e -> if e > !max then max := e done with End_of_file -> - Profiler.aggregate_f "close_in" @@ fun () -> + Read_profiler.aggregate_f ~verbosity:Info ("close_in", []) @@ fun () -> Scanf.Scanning.close_in ic ; Format.eprintf "%d@." !max let () = - Profiler.plug instance ; + Read_profiler.plug instance ; read_test_line () ; read_test_int () ; read_test_scanf () @@ -260,14 +281,14 @@ The execution time of ``read_int`` seems off. Replacing the following lines: .. code-block:: OCaml - Profiler.aggregate_f "read_int" @@ fun () -> + Read_profiler.aggregate_f ~verbosity:Info ("read_int", []) @@ fun () -> read_int ic |> fun e -> if e > !max then max := e By: .. code-block:: OCaml - Profiler.mark ["read_int"] ; + Read_profiler.mark ~verbosity:Info (["read_int"], []) ; read_int ic |> fun e -> if e > !max then max := e Gives a completely different result: diff --git a/src/lib_base/profiler.mli b/src/lib_base/profiler.mli index e7cf0f739cefb0a0ab0e1c2ec3d3f6b08d3b6237..478f99cd5580bf56c4c4489f17ec81f36274c9f4 100644 --- a/src/lib_base/profiler.mli +++ b/src/lib_base/profiler.mli @@ -238,9 +238,9 @@ val span : profiler -> verbosity -> span -> ids -> unit (** Include a report in the current sequence. *) val inc : profiler -> report -> unit -(** [record_f profiler ?verbosity label f] will call: +(** [record_f profiler verbosity label f] will call: {[ - record profiler ?verbosity name; + record profiler verbosity name; f (); stop (); ]} *) @@ -249,9 +249,9 @@ val record_f : profiler -> verbosity -> id -> (unit -> 'a) -> 'a (** Same as {!record_f} but for Lwt function *) val record_s : profiler -> verbosity -> id -> (unit -> 'a Lwt.t) -> 'a Lwt.t -(** [aggregate_f profiler ?verbosity label f] will call: +(** [aggregate_f profiler verbosity label f] will call: {[ - aggregate profiler ?verbosity name; + aggregate profiler verbosity name; f (); stop (); ]} *) @@ -260,7 +260,7 @@ val aggregate_f : profiler -> verbosity -> id -> (unit -> 'a) -> 'a (** Same as {!aggregate_f} but for Lwt functions *) val aggregate_s : profiler -> verbosity -> id -> (unit -> 'a Lwt.t) -> 'a Lwt.t -(** [span_f profiler ?verbosity label_list f] will compute [span] but +(** [span_f profiler verbosity label_list f] will compute [span] but specifically around [f] *) val span_f : profiler -> verbosity -> ids -> (unit -> 'a) -> 'a @@ -324,9 +324,9 @@ module type GLOBAL_PROFILER = sig (** Include a report in the current sequence. *) val inc : report -> unit - (** [record_f ?verbosity label f] will call: + (** [record_f verbosity label f] will call: {[ - record ?verbosity name; + record verbosity name; f (); stop (); ]} *) @@ -335,9 +335,9 @@ module type GLOBAL_PROFILER = sig (** Same as {!record_f} but for Lwt function *) val record_s : verbosity -> id -> (unit -> 'a Lwt.t) -> 'a Lwt.t - (** [aggregate_f ?verbosity label f] will call: + (** [aggregate_f verbosity label f] will call: {[ - aggregate ?verbosity name; + aggregate verbosity name; f (); stop (); ]} *) @@ -346,7 +346,7 @@ module type GLOBAL_PROFILER = sig (** Same as {!aggregate_f} but for Lwt functions *) val aggregate_s : verbosity -> id -> (unit -> 'a Lwt.t) -> 'a Lwt.t - (** [span_f ?verbosity label_list f] will compute [span] but specifically + (** [span_f verbosity label_list f] will compute [span] but specifically around [f] *) val span_f : verbosity -> ids -> (unit -> 'a) -> 'a