第 25 章 使用运行时事件进行运行时跟踪

本章介绍运行时事件跟踪系统,该系统能够以极低的开销从 OCaml 运行时持续提取性能信息。该系统和接口属于底层,与运行时实现紧密耦合,旨在让最终用户依赖工具来使用和可视化感兴趣的数据。

发出的数据包括:

可以声明和使用其他事件,为 OCaml 库提供更高级别的监控功能。它们被称为自定义事件

1 概述

运行时事件系统发出的事件主要分为三类:

跨度
跨越一段时间发生的事件。例如,运行时事件跟踪系统会发出一个跨度事件,该事件从 OCaml 垃圾收集器开始进行次要收集时开始,并在收集完成时结束。跨度可以包含其他跨度,例如,可以在次要收集开始后和结束前发出其他跨度事件。
生命周期事件
在某个时间点发生的事件。例如,当一个域终止时,会发出一个相应的生命周期事件。
计数器
包含某些感兴趣数量的度量的事件。例如,上次次要垃圾收集期间从次要堆提升到主要堆的字数作为计数器事件发出。

运行时事件跟踪系统设计用于不同的上下文:

自我监控
OCaml 程序和库可以安装自己的回调来侦听运行时事件并以编程方式对其做出反应,例如,将事件导出到磁盘或网络。
外部监控
外部进程可以使用已启用运行时跟踪系统的 OCaml 程序的运行时事件,方法是设置相应的环境变量。

运行时事件跟踪系统将事件记录到环形缓冲区。因此,旧事件会被新事件覆盖。使用者可以连续使用事件,也可以选择仅在响应某些情况时使用事件,例如,如果特定查询或操作花费的时间比预期长。

2 架构

运行时跟踪系统从概念上由两部分组成:1) 发出事件的事件源和 2) 摄取和传输这些事件的事件传输。

2.1 事件源

事件源是发出事件的点。在 OCaml 运行时系统中,有许多这样的源。这些源进一步分为两组:1) 始终可用的事件源和 2) 仅在检测运行时中可用的事件源。检测运行时中的事件源主要对 OCaml 运行时和垃圾收集器的开发人员感兴趣,目前仅包含主要堆分配大小计数器事件。

事件源发出的所有事件及其文档可以在模块 Runtime_events中找到。

2.2 事件传输

系统的事件传输部分摄取事件源发出的事件,并使它们可供使用者使用。

环形缓冲区

事件使用称为环形缓冲区的数据结构传输。此数据结构包含指向线性后备数组的两个指针,尾指针指向可以写入新事件的位置,头指针指向缓冲区中可以读取的最旧事件。当后备数组中没有足够的空间来写入新事件时,头指针会向前移动,并且最旧的事件会被新事件覆盖。

运行时事件中使用的环形缓冲区实现一次最多只能由一个生产者写入,但可以由多个使用者同时读取,而无需生产者的协调。每个正在运行的域都有一个唯一的环形缓冲区,并且在域终止时,环形缓冲区可以重复用于新生成的域。仅在启用运行时事件时才会分配环形缓冲区(包括主域)。环形缓冲区本身存储在内存映射文件中,该文件以进程标识符作为名称,扩展名为.events,这使得它们可以从主 OCaml 进程外部读取。有关更多信息,请参阅Runtime_events

使用 API

运行时事件跟踪系统提供了基于光标和轮询驱动的 OCaml 和 C API。使用事件的高级过程如下:

  1. 通过Runtime_events.create_cursor为当前进程或外部进程(由路径和 PID 指定)创建一个光标。
  2. 调用Runtime_events.Callbacks.create来注册一个回调函数以接收事件。
  3. 使用上一步中创建的回调,通过Runtime_events.read_poll轮询光标。对于环形缓冲区中的每个匹配事件,都会调用提供的回调函数。除了发出的事件之外,回调还会获得发射域的 ID 和发射时间戳。

3 使用方法

3.1 使用 OCaml API

我们从一个简单的示例开始,该示例打印运行时事件跟踪系统发出的事件的名称、开始和结束时间:

let runtime_begin _ ts phase =
    Printf.printf "Begin\t%s\t%Ld\n"
        (Runtime_events.runtime_phase_name phase)
        (Runtime_events.Timestamp.to_int64 ts)

let runtime_end _ ts phase =
    Printf.printf "End\t%s\t%Ld\n"
        (Runtime_events.runtime_phase_name phase)
        (Runtime_events.Timestamp.to_int64 ts)

let () =
    Runtime_events.start ();
    let cursor = Runtime_events.create_cursor None in
    let callbacks = Runtime_events.Callbacks.create ~runtime_begin ~runtime_end ()
    in
    while true do
        let list_ref = ref [] in (* for later fake GC work *)
        for _ = 1 to 100 do
            (* here we do some fake GC work *)
            list_ref := [];
            for _ = 1 to 10 do
                list_ref := (Sys.opaque_identity(ref 42)) :: !list_ref
            done;
            Gc.full_major ();
        done;
        ignore(Runtime_events.read_poll cursor callbacks None);
        Unix.sleep 1
    done

下一步是使用 runtime_events 库编译和链接程序。这可以通过以下方式完成:

       ocamlopt -I +runtime_events -I +unix unix.cmxa runtime_events.cmxa
            example.ml -o example

使用dune构建系统时,可以按如下方式构建此示例:

(executable
 (name example)
 (modules example)
 (libraries unix runtime_events))

运行示例的编译二进制文件将产生类似于以下内容的输出:

Begin   explicit_gc_full_major  24086187297852
Begin   stw_leader      24086187298594
Begin   minor   24086187299404
Begin   minor_global_roots      24086187299807
End     minor_global_roots      24086187331461
Begin   minor_remembered_set    24086187331631
Begin   minor_finalizers_oldify 24086187544312
End     minor_finalizers_oldify 24086187544704
Begin   minor_remembered_set_promote    24086187544879
End     minor_remembered_set_promote    24086187606414
End     minor_remembered_set    24086187606584
Begin   minor_finalizers_admin  24086187606854
End     minor_finalizers_admin  24086187607152
Begin   minor_local_roots       24086187607329
Begin   minor_local_roots_promote       24086187609699
End     minor_local_roots_promote       24086187610539
End     minor_local_roots       24086187610709
End     minor   24086187611746
Begin   minor_clear     24086187612238
End     minor_clear     24086187612580
End     stw_leader      24086187613209
...

这是一个自我监控的示例,其中程序显式地开始侦听运行时事件并监控自身。

对于外部监控,程序不需要知道运行时事件的存在。可以通过环境变量OCAML_RUNTIME_EVENTS_START控制运行时事件,该变量如果设置,将在程序初始化时启动运行时跟踪系统。

我们可以从前面的示例中删除Runtime_events.start ();,并改为如下调用程序以产生相同的结果:

OCAML_RUNTIME_EVENTS_START=1 ./example

环境变量

环境变量可用于控制运行时事件跟踪系统的不同方面。以下环境变量可用:

可以通过 OCAMLRUNPARAM 配置运行时事件环形缓冲区的大小,有关更多信息,请参阅第15.2节。

使用检测运行时构建

某些事件仅由检测运行时发出。要接收它们,OCaml 程序需要针对检测运行时进行编译和链接。对于我们之前的示例程序,这可以通过以下方式实现:

ocamlopt -runtime-variant i -I +runtime_events -I +unix unix.cmxa runtime_events.cmxa example.ml -o example

对于 dune:

(executable
 (name example)
 (modules example)
 (flags "-runtime-variant=i")
 (libraries unix runtime_events))

3.2 使用工具

对事件进行编程访问主要用于可观察性库和最终用户工具的编写者。灵活的 API 使得能够将运行时事件中的性能数据用于日志记录和监控目的。

在本节中,我们介绍了 runtime_events_tools 包中的一些实用程序,这些实用程序提供了从运行时事件中提取和汇总数据的方法。特别是 trace 实用程序会生成与 OCaml 4.12 到 4.14 中可用的先前“eventlog”检测系统类似的数据。

首先,在 OCaml 5.0+ opam 切换中安装 runtime_events_tools

opam install runtime_events_tools

这应该会将 olly 工具安装到你的路径中。你现在可以使用 trace 子命令为使用 OCaml 5.0+ 编译的程序生成运行时跟踪:

olly trace trace.json 'your_program.exe .. args ..'

运行时跟踪数据将以 json 跟踪事件格式生成到 trace.json 中。然后可以将其加载到 Chrome 跟踪查看器或Perfetto中以可视化收集到的跟踪。

测量 GC 延迟

olly 实用程序还包含一个延迟子命令,该子命令使用运行时事件数据,并在程序完成时发出暂停持续时间的可解析直方图摘要。可以按如下方式运行它:

olly latency 'your_program.exe .. args ..'

这应该会产生类似于以下内容的输出:

GC latency profile:
#[Mean (ms):	2.46,	 Stddev (ms):	3.87]
#[Min (ms):	0.01,	 max (ms):	9.17]

Percentile 	 Latency (ms)
25.0000 	 0.01
50.0000 	 0.23
60.0000 	 0.23
70.0000 	 0.45
75.0000 	 0.45
80.0000 	 0.45
85.0000 	 0.45
90.0000 	 9.17
95.0000 	 9.17
96.0000 	 9.17
97.0000 	 9.17
98.0000 	 9.17
99.0000 	 9.17
99.9000 	 9.17
99.9900 	 9.17
99.9990 	 9.17
99.9999 	 9.17
100.0000 	 9.17

4 自定义事件

4.1 概述

运行时事件系统支持定义自定义事件。它们由全局唯一名称标识,并使用内置 (unitintspan) 和用户定义类型的有效负载发出。要了解自定义事件的操作,了解它们如何传输和存储很有用:它们的表示形式由名称字符串(实际上是所有自定义名称数组中的索引)和任意字节序列组成。自定义事件类型可以通过为字节序列提供编码和解码函数来注册,方法是使用函数Runtime_events.Type.register

定义新的自定义事件(无论其有效负载是内置类型还是自定义类型)是通过另一个注册函数Runtime_events.User.register完成的。此函数记录自定义事件名称、其类型和标签之间的关联。然后在发出或使用自定义事件时使用该标签;它充当事件名称的简写。

注册事件后,使用Runtime_events.User.write发出该事件的值。

总而言之,要让用户使用自定义类型发出和使用自定义事件,他们需要

  1. 注册自定义类型
  2. 使用新的构造函数扩展Runtime_events.User.tag变体
  3. 注册新的自定义事件,将自定义事件名称、新标签和新的自定义类型绑定在一起
  4. 使用Runtime_events.User.write发出事件的实例
  5. 指示应接收所有自定义类型事件的回调,使用Runtime_events.Callbacks.add_user_eventRuntime_events.Callbacks.t对象内注册它,以便在轮询时使用(请参见上面第25.3.1节)。
  6. (可选,如果有多个使用相同自定义类型注册的事件:)在该回调中,对事件标签进行模式匹配以区分相同自定义类型的不同事件标签。

请注意,如果发出者和使用者是不同的程序,则两者都必须执行步骤 1 到 3 以注册自定义事件和自定义事件类型(如果有)。请注意,标签值在两个程序中不必相同;唯一应匹配的值是名称。

目前忽略用户定义类型的未注册事件。作为后备方案,内置类型的未注册自定义事件可用,但都标记为UNK(未知)。

因此,当接收事件时,使用者有三种情况

请注意,事件使用者将回调绑定到事件类型,因此它们可以作为通用侦听器来解释来自未注册事件的有效负载。由于这仅适用于内置类型的事件,因此可以将事件成对发出:一个自定义类型的事件和一个内置类型的事件,从而能够设计专门的使用者,同时与通用跟踪工具保持兼容。

4.2 跟踪自定义事件:示例

以下程序使用Runtime_events.UserRuntime_events.Type模块声明两个提供spanint值的自定义事件。tag可扩展变体扩展了CustomSpanCustomInt

type Runtime_events.User.tag += CustomSpan | CustomInt

let count_span =
    Runtime_events.User.register "count.span" CustomSpan
        Runtime_events.Type.span

let count_value =
    Runtime_events.User.register "count.value" CustomInt
        Runtime_events.Type.int

let count () =
    Runtime_events.User.write count_span Begin;
    for i = 1 to 5 do
        Runtime_events.User.write count_value i
    done;
    Runtime_events.User.write count_span End

let () =
    Runtime_events.start ();
    for _ = 1 to 3 do
        count ()
    done

在使用者端,可以使用提供的事件标签和类型来匹配相关事件。为完整起见,我们假设使用者是不同的程序,并重复定义新的标签构造函数以及自定义事件的注册。

type Runtime_events.User.tag += CustomSpan | CustomInt

let count_span =
    Runtime_events.User.register "count.span" CustomSpan
        Runtime_events.Type.span

let count_value =
    Runtime_events.User.register "count.value" CustomInt
        Runtime_events.Type.int

let span_event_handler domain_id ts event value =
    (* we're only interested in our CustomSpan event *)
    match Runtime_events.User.tag event, value with
    | CustomSpan, Runtime_events.Type.Begin -> Printf.printf "> count begin\n"
    | CustomSpan, End -> Printf.printf "< count end\n"
    | _ -> ()

let int_event_handler domain_id ts event value =
    (* we're only interested in our CustomInt event *)
    match Runtime_events.User.tag event with
    | CustomInt -> Printf.printf "| count %d\n" value
    | _ -> ()

let () =
    let open Runtime_events in
    let cursor = create_cursor None in
    let callbacks =
        Callbacks.create ()
        |> Callbacks.add_user_event Type.span span_event_handler
        |> Callbacks.add_user_event Type.int int_event_handler
    in
    for _ = 0 to 100 do
        ignore(read_poll cursor callbacks None)
    done

给出以下输出

> count begin
| count 1
| count 2
| count 3
| count 4
| count 5
< count end
> count begin
| count 1
| count 2
[...]