remove manual spans

there isn't a clear way to use them. The `tracing` library in Rust
doesn't have an equivalent of this, instead futures re-enter and
re-exit regular spans whenever they are polled. For us in OCaml the
equivalent is to create a regular span whenever we schedule a
future/fiber, and exit it when we yield.
This commit is contained in:
Simon Cruanes 2024-01-24 22:49:30 -05:00
parent d3e710605e
commit cb468a0440
No known key found for this signature in database
GPG key ID: EBFFF6F283F3A2B4
7 changed files with 876 additions and 1295 deletions

View file

@ -48,37 +48,10 @@ module type S = sig
other calls to enter/exit_span and {!with_span}. other calls to enter/exit_span and {!with_span}.
@since 0.6 *) @since 0.6 *)
val enter_manual_span :
parent:explicit_span option ->
flavor:[ `Sync | `Async ] option ->
__FUNCTION__:string option ->
__FILE__:string ->
__LINE__:int ->
data:(string * user_data) list ->
string ->
explicit_span
(** Enter an explicit span. Surrounding scope, if any, is provided by [parent],
and this function can store as much metadata as it wants in the hmap
in the {!explicit_span}'s [meta] field.
This means that the collector doesn't need to implement contextual
storage mapping {!span} to scopes, metadata, etc. on its side;
everything can be transmitted in the {!explicit_span}.
@since 0.3 *)
val exit_manual_span : explicit_span -> unit
(** Exit an explicit span.
@since 0.3 *)
val add_data_to_span : span -> (string * user_data) list -> unit val add_data_to_span : span -> (string * user_data) list -> unit
(** @since Adds data to the current span. (** @since Adds data to the current span.
0.4 *) 0.4 *)
val add_data_to_manual_span :
explicit_span -> (string * user_data) list -> unit
(** Adds data to the given span.
@since 0.4 *)
val message : ?span:span -> data:(string * user_data) list -> string -> unit val message : ?span:span -> data:(string * user_data) list -> string -> unit
(** Emit a message with associated metadata. *) (** Emit a message with associated metadata. *)

View file

@ -42,34 +42,6 @@ let[@inline] exit_span sp : unit =
| None -> () | None -> ()
| Some (module C) -> C.exit_span sp | Some (module C) -> C.exit_span sp
let enter_explicit_span_collector_ (module C : Collector.S) ~parent ~flavor
?__FUNCTION__ ~__FILE__ ~__LINE__ ?(data = data_empty_build_) name :
explicit_span =
let data = data () in
C.enter_manual_span ~parent ~flavor ~__FUNCTION__ ~__FILE__ ~__LINE__ ~data
name
let[@inline] enter_manual_sub_span ~parent ?flavor ?__FUNCTION__ ~__FILE__
~__LINE__ ?data name : explicit_span =
match A.get collector with
| None -> Collector.dummy_explicit_span
| Some coll ->
enter_explicit_span_collector_ coll ~parent:(Some parent) ~flavor
?__FUNCTION__ ~__FILE__ ~__LINE__ ?data name
let[@inline] enter_manual_toplevel_span ?flavor ?__FUNCTION__ ~__FILE__
~__LINE__ ?data name : explicit_span =
match A.get collector with
| None -> Collector.dummy_explicit_span
| Some coll ->
enter_explicit_span_collector_ coll ~parent:None ~flavor ?__FUNCTION__
~__FILE__ ~__LINE__ ?data name
let[@inline] exit_manual_span espan : unit =
match A.get collector with
| None -> ()
| Some (module C) -> C.exit_manual_span espan
let[@inline] add_data_to_span sp data : unit = let[@inline] add_data_to_span sp data : unit =
if data <> [] then ( if data <> [] then (
match A.get collector with match A.get collector with
@ -77,13 +49,6 @@ let[@inline] add_data_to_span sp data : unit =
| Some (module C) -> C.add_data_to_span sp data | Some (module C) -> C.add_data_to_span sp data
) )
let[@inline] add_data_to_manual_span esp data : unit =
if data <> [] then (
match A.get collector with
| None -> ()
| Some (module C) -> C.add_data_to_manual_span esp data
)
let message_collector_ (module C : Collector.S) ?span let message_collector_ (module C : Collector.S) ?span
?(data = data_empty_build_) msg : unit = ?(data = data_empty_build_) msg : unit =
let data = data () in let data = data () in

View file

@ -30,8 +30,7 @@ val with_span :
{b NOTE} an important restriction is that this is only supposed to {b NOTE} an important restriction is that this is only supposed to
work for synchronous, direct style code. Monadic concurrency, Effect-based work for synchronous, direct style code. Monadic concurrency, Effect-based
fibers, etc. might not play well with this style of spans on some fibers, etc. might not play well with this style of spans on some
or all backends. If you use cooperative concurrency, or all backends.
see {!enter_manual_span}.
*) *)
val enter_span : val enter_span :
@ -49,52 +48,6 @@ val add_data_to_span : span -> (string * user_data) list -> unit
Behavior is not specified if the span has been exited. Behavior is not specified if the span has been exited.
@since 0.4 *) @since 0.4 *)
val enter_manual_sub_span :
parent:explicit_span ->
?flavor:[ `Sync | `Async ] ->
?__FUNCTION__:string ->
__FILE__:string ->
__LINE__:int ->
?data:(unit -> (string * user_data) list) ->
string ->
explicit_span
(** Like {!with_span} but the caller is responsible for
obtaining the [parent] span from their {e own} caller, and carry the resulting
{!explicit_span} to the matching {!exit_manual_span}.
@param flavor a description of the span that can be used by the {!Collector.S}
to decide how to represent the span. Typically, [`Sync] spans
start and stop on one thread, and are nested purely by their timestamp;
and [`Async] spans can overlap, migrate between threads, etc. (as happens in
Lwt, Eio, Async, etc.) which impacts how the collector might represent them.
@since 0.3 *)
val enter_manual_toplevel_span :
?flavor:[ `Sync | `Async ] ->
?__FUNCTION__:string ->
__FILE__:string ->
__LINE__:int ->
?data:(unit -> (string * user_data) list) ->
string ->
explicit_span
(** Like {!with_span} but the caller is responsible for carrying this
[explicit_span] around until it's exited with {!exit_manual_span}.
The span can be used as a parent in {!enter_manual_sub_span}.
@param flavor see {!enter_manual_sub_span} for more details.
@since 0.3 *)
val exit_manual_span : explicit_span -> unit
(** Exit an explicit span. This can be on another thread, in a
fiber or lightweight thread, etc. and will be supported by backends
nonetheless.
The span can be obtained via {!enter_manual_sub_span} or
{!enter_manual_toplevel_span}.
@since 0.3 *)
val add_data_to_manual_span : explicit_span -> (string * user_data) list -> unit
(** [add_data_explicit esp data] adds [data] to the span [esp].
The behavior is not specified is the span has been exited already.
@since 0.4 *)
val message : val message :
?span:span -> ?data:(unit -> (string * user_data) list) -> string -> unit ?span:span -> ?data:(unit -> (string * user_data) list) -> string -> unit
(** [message msg] logs a message [msg] (if a collector is installed). (** [message msg] logs a message [msg] (if a collector is installed).

View file

@ -103,15 +103,6 @@ end = struct
with Found i -> Some i with Found i -> Some i
end end
type async_span_info = {
async_id: int;
flavor: [ `Sync | `Async ] option;
name: string;
mutable data: (string * user_data) list;
}
let key_async_data : async_span_info Meta_map.Key.t = Meta_map.Key.create ()
open struct open struct
let state_id_ = A.make 0 let state_id_ = A.make 0
@ -131,7 +122,6 @@ type per_thread_state = {
type state = { type state = {
active: bool A.t; active: bool A.t;
events: Bg_thread.event B_queue.t; events: Bg_thread.event B_queue.t;
span_id_gen: int A.t; (** Used for async spans *)
bg_thread: Thread.t; bg_thread: Thread.t;
buf_pool: Buf_pool.t; buf_pool: Buf_pool.t;
next_thread_ref: int A.t; (** in [0x01 .. 0xff], to allocate thread refs *) next_thread_ref: int A.t; (** in [0x01 .. 0xff], to allocate thread refs *)
@ -287,41 +277,6 @@ struct
| None -> !on_tracing_error (spf "unknown span %Ld" span) | None -> !on_tracing_error (spf "unknown span %Ld" span)
| Some idx -> Span_info_stack.add_data tls.spans idx data | Some idx -> Span_info_stack.add_data tls.spans idx data
let enter_manual_span ~(parent : explicit_span option) ~flavor ~__FUNCTION__:_
~__FILE__:_ ~__LINE__:_ ~data name : explicit_span =
let out, tls = get_thread_output () in
let time_ns = Time.now_ns () in
(* get the id, or make a new one *)
let async_id =
match parent with
| Some m -> (Meta_map.find_exn key_async_data m.meta).async_id
| None -> A.fetch_and_add st.span_id_gen 1
in
FWrite.Event.Async_begin.encode out ~name ~args:data ~t_ref:tls.thread_ref
~time_ns ~async_id ();
{
span = 0L;
meta =
Meta_map.(
empty |> add key_async_data { async_id; name; flavor; data = [] });
}
let exit_manual_span (es : explicit_span) : unit =
let { async_id; name; data; flavor = _ } =
Meta_map.find_exn key_async_data es.meta
in
let out, tls = get_thread_output () in
let time_ns = Time.now_ns () in
FWrite.Event.Async_end.encode out ~name ~t_ref:tls.thread_ref ~time_ns
~args:data ~async_id ()
let add_data_to_manual_span (es : explicit_span) data =
let m = Meta_map.find_exn key_async_data es.meta in
m.data <- List.rev_append data m.data
let message ?span:_ ~data msg : unit = let message ?span:_ ~data msg : unit =
let out, tls = get_thread_output () in let out, tls = get_thread_output () in
let time_ns = Time.now_ns () in let time_ns = Time.now_ns () in
@ -368,7 +323,6 @@ let create ~out () : collector =
buf_pool; buf_pool;
bg_thread; bg_thread;
events; events;
span_id_gen = A.make 0;
next_thread_ref = A.make 1; next_thread_ref = A.make 1;
per_thread = Array.init 16 (fun _ -> A.make Int_map.empty); per_thread = Array.init 16 (fun _ -> A.make Int_map.empty);
} }

View file

@ -49,23 +49,6 @@ type event =
id: span; id: span;
data: (string * user_data) list; data: (string * user_data) list;
} }
| E_enter_manual_span of {
tid: int;
name: string;
time_us: float;
id: int;
flavor: [ `Sync | `Async ] option;
fun_name: string option;
data: (string * user_data) list;
}
| E_exit_manual_span of {
tid: int;
name: string;
time_us: float;
flavor: [ `Sync | `Async ] option;
data: (string * user_data) list;
id: int;
}
| E_counter of { | E_counter of {
name: string; name: string;
tid: int; tid: int;
@ -91,15 +74,6 @@ type span_info = {
mutable data: (string * user_data) list; mutable data: (string * user_data) list;
} }
(** key used to carry a unique "id" for all spans in an async context *)
let key_async_id : int Meta_map.Key.t = Meta_map.Key.create ()
let key_async_data : (string * [ `Sync | `Async ] option) Meta_map.Key.t =
Meta_map.Key.create ()
let key_data : (string * user_data) list ref Meta_map.Key.t =
Meta_map.Key.create ()
(** Writer: knows how to write entries to a file in TEF format *) (** Writer: knows how to write entries to a file in TEF format *)
module Writer = struct module Writer = struct
type t = { type t = {
@ -200,30 +174,6 @@ module Writer = struct
args; args;
Buffer.output_buffer self.oc self.buf Buffer.output_buffer self.oc self.buf
let emit_manual_begin ~tid ~name ~id ~ts ~args ~flavor (self : t) : unit =
emit_sep_and_start_ self;
Printf.bprintf self.buf
{json|{"pid":%d,"cat":"trace","id":%d,"tid": %d,"ts": %.2f,"name":%a,"ph":"%c"%a}|json}
self.pid id tid ts str_val name
(match flavor with
| None | Some `Async -> 'b'
| Some `Sync -> 'B')
(emit_args_o_ pp_user_data_)
args;
Buffer.output_buffer self.oc self.buf
let emit_manual_end ~tid ~name ~id ~ts ~flavor ~args (self : t) : unit =
emit_sep_and_start_ self;
Printf.bprintf self.buf
{json|{"pid":%d,"cat":"trace","id":%d,"tid": %d,"ts": %.2f,"name":%a,"ph":"%c"%a}|json}
self.pid id tid ts str_val name
(match flavor with
| None | Some `Async -> 'e'
| Some `Sync -> 'E')
(emit_args_o_ pp_user_data_)
args;
Buffer.output_buffer self.oc self.buf
let emit_instant_event ~tid ~name ~ts ~args (self : t) : unit = let emit_instant_event ~tid ~name ~ts ~args (self : t) : unit =
emit_sep_and_start_ self; emit_sep_and_start_ self;
Printf.bprintf self.buf Printf.bprintf self.buf
@ -298,13 +248,6 @@ let bg_thread ~out (events : event B_queue.t) : unit =
(match Span_tbl.find_opt spans id with (match Span_tbl.find_opt spans id with
| None -> !on_tracing_error (Printf.sprintf "cannot find span %Ld" id) | None -> !on_tracing_error (Printf.sprintf "cannot find span %Ld" id)
| Some info -> info.data <- List.rev_append data info.data) | Some info -> info.data <- List.rev_append data info.data)
| E_enter_manual_span { tid; time_us; name; id; data; fun_name; flavor } ->
let data = add_fun_name_ fun_name data in
Writer.emit_manual_begin ~tid ~name ~id ~ts:time_us ~args:data ~flavor
writer
| E_exit_manual_span { tid; time_us; name; id; flavor; data } ->
Writer.emit_manual_end ~tid ~name ~id ~ts:time_us ~flavor ~args:data
writer
| E_counter { tid; name; time_us; n } -> | E_counter { tid; name; time_us; n } ->
Writer.emit_counter ~name ~tid ~ts:time_us writer n Writer.emit_counter ~name ~tid ~ts:time_us writer n
| E_name_process { name } -> Writer.emit_name_process ~name writer | E_name_process { name } -> Writer.emit_name_process ~name writer
@ -409,48 +352,6 @@ let collector ~out () : collector =
let add_data_to_span span data = let add_data_to_span span data =
if data <> [] then B_queue.push events (E_add_data { id = span; data }) if data <> [] then B_queue.push events (E_add_data { id = span; data })
let enter_manual_span ~(parent : explicit_span option) ~flavor
~__FUNCTION__:fun_name ~__FILE__:_ ~__LINE__:_ ~data name :
explicit_span =
(* get the id, or make a new one *)
let id =
match parent with
| Some m -> Meta_map.find_exn key_async_id m.meta
| None -> A.fetch_and_add span_id_gen_ 1
in
let time_us = now_us () in
B_queue.push events
(E_enter_manual_span
{ id; time_us; tid = get_tid_ (); data; name; fun_name; flavor });
{
span = 0L;
meta =
Meta_map.(
empty |> add key_async_id id |> add key_async_data (name, flavor));
}
let exit_manual_span (es : explicit_span) : unit =
let id = Meta_map.find_exn key_async_id es.meta in
let name, flavor = Meta_map.find_exn key_async_data es.meta in
let data =
try !(Meta_map.find_exn key_data es.meta) with Not_found -> []
in
let time_us = now_us () in
let tid = get_tid_ () in
B_queue.push events
(E_exit_manual_span { tid; id; name; time_us; data; flavor })
let add_data_to_manual_span (es : explicit_span) data =
if data <> [] then (
let data_ref, add =
try Meta_map.find_exn key_data es.meta, false
with Not_found -> ref [], true
in
let new_data = List.rev_append data !data_ref in
data_ref := new_data;
if add then es.meta <- Meta_map.add key_data data_ref es.meta
)
let message ?span:_ ~data msg : unit = let message ?span:_ ~data msg : unit =
let time_us = now_us () in let time_us = now_us () in
let tid = get_tid_ () in let tid = get_tid_ () in

File diff suppressed because it is too large Load diff

View file

@ -1,3 +1,5 @@
let ( let@ ) = ( @@ )
let run () = let run () =
Trace.set_process_name "main"; Trace.set_process_name "main";
Trace.set_thread_name "t1"; Trace.set_thread_name "t1";
@ -6,10 +8,6 @@ let run () =
for _i = 1 to 50 do for _i = 1 to 50 do
Trace.with_span ~__FILE__ ~__LINE__ "outer.loop" @@ fun _sp -> Trace.with_span ~__FILE__ ~__LINE__ "outer.loop" @@ fun _sp ->
let pseudo_async_sp =
Trace.enter_manual_toplevel_span ~__FILE__ ~__LINE__ "fake_sleep"
in
for _j = 2 to 5 do for _j = 2 to 5 do
incr n; incr n;
Trace.with_span ~__FILE__ ~__LINE__ "inner.loop" @@ fun _sp -> Trace.with_span ~__FILE__ ~__LINE__ "inner.loop" @@ fun _sp ->
@ -21,23 +19,10 @@ let run () =
if _j = 2 then ( if _j = 2 then (
Trace.add_data_to_span _sp [ "j", `Int _j ]; Trace.add_data_to_span _sp [ "j", `Int _j ];
let _sp = let@ _sp = Trace.with_span ~__LINE__ ~__FILE__ "sub-sleep" in
Trace.enter_manual_sub_span ~parent:pseudo_async_sp
~flavor:
(if _i mod 3 = 0 then
`Sync
else
`Async)
~__FILE__ ~__LINE__ "sub-sleep"
in
(* fake micro sleep *) (* fake micro sleep *)
Thread.delay 0.005; Thread.delay 0.005
Trace.exit_manual_span _sp
) else if _j = 3 then (
(* pretend some task finished. Note that this is not well scoped wrt other spans. *)
Trace.add_data_to_manual_span pseudo_async_sp [ "slept", `Bool true ];
Trace.exit_manual_span pseudo_async_sp
) )
done done
done done