|
| 1 | +# Extending the timeline tool |
| 2 | + |
| 3 | +This document is mainly for VM binding developers who want to extend this timeline tool to trace and |
| 4 | +visualize VM-specific events on the timeline. |
| 5 | + |
| 6 | +## Custom work packets in VM bindings |
| 7 | + |
| 8 | +mmtk-core contains trace points that captures the beginning and end of *all* work packets. If a VM |
| 9 | +bindings defines its own work packets and execute them, they will automatically appear on the |
| 10 | +timeline, without needing to modify or extend any scripts. |
| 11 | + |
| 12 | +But if you wish to add additional attributes to work packets or events and browse them in Perfetto |
| 13 | +UI, please read on. |
| 14 | + |
| 15 | +## The output format of `capture.bt` |
| 16 | + |
| 17 | +The capturing script `capture.bt` prints events in a text format. Each line contains |
| 18 | +comma-separated values: |
| 19 | + |
| 20 | +``` |
| 21 | +name,ph,tid,timestamp,arg0,arg1,arg2,... |
| 22 | +``` |
| 23 | + |
| 24 | +The `visualize.py` script will transform those lines into the [Trace Event Format], a JSON-based |
| 25 | +format suitable for Perfetto UI, like this: `{"name": name, "ph": ph, "tid": tid, "ts": ts}`. |
| 26 | +Possible values of the event type (or "phase", "ph") are defined by the [Trace Event Format]. For |
| 27 | +example, "B" and "E" represent the beginning and the end of a duration event, while "i" represents |
| 28 | +an instant event. Additional arguments (arg0, arg1, ...) are processed by `visualize.py` in ways |
| 29 | +specific to each event. Some arguments are added to the resulting JSON object, for example |
| 30 | +`{"name": name, ..., "args": {"is_roots": 1, "num_slots": 2}}` The data in "args" are |
| 31 | +human-readable, and can be displayed on Perfetto UI. |
| 32 | + |
| 33 | +[Trace Event Format]: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU |
| 34 | + |
| 35 | +## Extending the capturing script |
| 36 | + |
| 37 | +VM binding developers may insert custom USDT trace points into the VM binding. They need to be |
| 38 | +captured by bpftrace to be displayed on the timeline. |
| 39 | + |
| 40 | +The `capture.py` can use the `-x` command line option to append a script after `capture.bt` which is |
| 41 | +the base bpftrace script used by `capture.py`. Because the extended script is simply appended to |
| 42 | +`capture.bt`, it has access to all "map" variables (`@`) defined in `capture.bt`, such as |
| 43 | +`@harness`, `@enable_print`, etc. The Python script `capture.py` also uses [template strings] to |
| 44 | +replace things starting with `$`. Specifically, `$MMTK` will be replaced with the path to the MMTk |
| 45 | +binary. It will affect the extended script, too. |
| 46 | + |
| 47 | +[template strings]: https://docs.python.org/3/library/string.html#template-strings |
| 48 | + |
| 49 | +For example, you can hack the [mmtk-openjdk](https://github.com/mmtk/mmtk-openjdk) binding and add a |
| 50 | +dependency to the `probe` crate in `Cargo.toml` if it doesn't already have one. |
| 51 | + |
| 52 | +```toml |
| 53 | +probe = "0.5" |
| 54 | +``` |
| 55 | + |
| 56 | +Then add the following `probe!` macro in `stop_all_mutators` in `collection.rs`: |
| 57 | + |
| 58 | +```rust |
| 59 | + probe!(mmtk_openjdk, hello); |
| 60 | +``` |
| 61 | + |
| 62 | +and create a bpftrace script `capture_openjdk_example.bt`: |
| 63 | + |
| 64 | +```c |
| 65 | +usdt:$MMTK:mmtk_openjdk:hello { |
| 66 | + if (@enable_print) { |
| 67 | + printf("hello,i,%d,%lu\n", tid, nsecs); |
| 68 | + } |
| 69 | +} |
| 70 | +``` |
| 71 | + |
| 72 | +and use the `-x` command line option while invoking `capture.py`: |
| 73 | + |
| 74 | +```shell |
| 75 | +./capture.py -x capture_openjdk_example.bt -m /path/to/libmmtk_openjdk.so ... > output.log |
| 76 | +``` |
| 77 | + |
| 78 | +and run a benchmark with OpenJDK (such as `lusearch`). Use the unmodified `visualize.py` to process |
| 79 | +the log, and you will see many arrows representing the "hello" events on the timeline. They should |
| 80 | +be quite obvious because each one will be a lone instant event right below a `StopMutators` work |
| 81 | +packet. |
| 82 | + |
| 83 | +## Extending the visualization script |
| 84 | + |
| 85 | +The `visualize.py` script also allows extension using the `-x` command line option. The `-x` option |
| 86 | +points to a Python script that implements two functions: `enrich_event_extra` and |
| 87 | +`enrich_meta_extra` (you may omit either one if you don't need). `enrich_event_extra` is used to |
| 88 | +process events that the `visualize.py` script doesn't recognize. We'll cover `enrich_meta_extra` |
| 89 | +later. |
| 90 | + |
| 91 | +For example, modify the `probe!` macro and add an argument: |
| 92 | + |
| 93 | +```rust |
| 94 | + probe!(mmtk_openjdk, hello, 42); |
| 95 | +``` |
| 96 | + |
| 97 | +and modify `capture_openjdk_example.bt` to print `arg0` in the CSV: |
| 98 | + |
| 99 | +```c |
| 100 | + printf("hello,i,%d,%lu,%lu\n", tid, nsecs, arg0); |
| 101 | +``` |
| 102 | +
|
| 103 | +and create a Python script `visualize_openjdk_example.py`: |
| 104 | +
|
| 105 | +```python |
| 106 | +def enrich_event_extra(log_processor, name, ph, tid, ts, result, rest): |
| 107 | + match name: |
| 108 | + case "hello": |
| 109 | + result["args"] |= { |
| 110 | + "the_number": int(rest[0]), |
| 111 | + } |
| 112 | +``` |
| 113 | + |
| 114 | +Process the log with `visualize.py`, adding a `-x` option: |
| 115 | + |
| 116 | +```shell |
| 117 | +./visualize.py -x visualize_openjdk_example.py output.log |
| 118 | +``` |
| 119 | + |
| 120 | +Load the output into Perfetto UI and select the hello event, and you shall see the "the_number" |
| 121 | +argument in the "Arguments" block on the right side of the "Current Selection" panel. |
| 122 | + |
| 123 | +## Meta events |
| 124 | + |
| 125 | +The `capture.bt` script and its extensions can print events with type "meta" instead of the usual |
| 126 | +"B", "E", "i", etc. "meta" is not a valid event type defined by the [Trace Event Format]. While |
| 127 | +going through the log, the `visualize.py` script remembers the current GC and the current work |
| 128 | +packet each thread is executing. When `visualize.py` sees a "meta" event, it will find the |
| 129 | +previously created JSON objects for the beginning of the current GC and the beginning of the current |
| 130 | +work packet of the current thread, and modify them, usually by adding more arguments to the event |
| 131 | +using information (arguments) provided by the "meta" event. For example, the `gen_full_heap` "meta" |
| 132 | +event adds an argument to the "GC" bar (on the timeline of "Thread 0") to display whether the |
| 133 | +current GC is a full-heap GC (as opposed to nursery GC), and the `process_slots` "meta" event |
| 134 | +patches the work packet event with additional arguments to display the number of slots processed and |
| 135 | +whether the slots are roots. |
| 136 | + |
| 137 | +Users can extend `visualize.py` and define the `enrich_meta_extra` function to handle "meta" events |
| 138 | +the `visualize.py` script doesn't recognize. |
| 139 | + |
| 140 | +For example, hack the mmtk-openjdk binding again, and add the following `probe!` macro into |
| 141 | +`scan_vm_specific_roots` in `scanning.rs`: |
| 142 | + |
| 143 | +```rust |
| 144 | + probe!(mmtk_openjdk, hello2, 43); |
| 145 | +``` |
| 146 | + |
| 147 | +and add the following `probe!` macro into `scan_roots_in_mutator_thread` in `scanning.rs`: |
| 148 | + |
| 149 | +```rust |
| 150 | + probe!(mmtk_openjdk, hello3, 44); |
| 151 | +``` |
| 152 | + |
| 153 | +Capture the event in `capture_openjdk_example.bt`: |
| 154 | + |
| 155 | +```c |
| 156 | +usdt:$MMTK:mmtk_openjdk:hello2 { |
| 157 | + printf("hello2,meta,%d,%lu,%lu\n", tid, nsecs, arg0); |
| 158 | +} |
| 159 | + |
| 160 | +usdt:$MMTK:mmtk_openjdk:hello3 { |
| 161 | + if (@enable_print) { |
| 162 | + printf("hello3,meta,%d,%lu,%lu\n", tid, nsecs, arg0); |
| 163 | + } |
| 164 | +} |
| 165 | +``` |
| 166 | + |
| 167 | +Process the meta event in `visualize_openjdk_example.py`: |
| 168 | + |
| 169 | +```python |
| 170 | +def enrich_meta_extra(log_processor, name, tid, ts, gc, wp, rest): |
| 171 | + if gc is not None: |
| 172 | + match name: |
| 173 | + case "hello2": |
| 174 | + gc["args"] |= { |
| 175 | + "the_number": int(rest[0]), |
| 176 | + } |
| 177 | + |
| 178 | + if wp is not None: |
| 179 | + match name: |
| 180 | + case "hello3": |
| 181 | + wp["args"] |= { |
| 182 | + "the_number": int(rest[0]), |
| 183 | + } |
| 184 | +``` |
| 185 | + |
| 186 | +Run a benchmark, capture a log (with `-x capture_openjdk_example.bt`) and visualize it (with `-x |
| 187 | +visualize_openjdk_example.py`). Load it into Perfetto UI. Select a `GC` bar and you should see the |
| 188 | +`the_number` argument being 43; select a `ScanMutatorRoots` work packet, and you will see the |
| 189 | +`the_number` argument being 44. If you use `-e` to capture logs for every few GCs, you will find |
| 190 | +that the `the_number` argument also exists on GCs that don't record work packets. That's because we |
| 191 | +don't have `if (@enable_print)` for "hello2" in `capture_openjdk_example.bt`. |
| 192 | + |
| 193 | +## Notes on dropped events |
| 194 | + |
| 195 | +bpftrace may drop events, so it may fail to record the beginning of some work packets. This affects |
| 196 | +work packets defined in both mmtk-core and the VM binding. If this happens, `visualize.py` may see |
| 197 | +some "meta" events on threads which are apparently not executing any work packets. Such "meta" |
| 198 | +events are silently ignored. |
| 199 | + |
| 200 | +## Advanced usage |
| 201 | + |
| 202 | +The `enrich_event_extra` and `enrich_meta_extra` have the `LogProcessor` instance as their first |
| 203 | +parameters. This allows the functions to use the `LogProcessor` instance to store states that |
| 204 | +persist across multiple invocations of `enrich_event_extra` and `enrich_meta_extra`. For example, |
| 205 | +the VM binding can define its own duration events (those with "B" and "E" events and shown as a bar |
| 206 | +on the timeline). The extension script can exploit the dynamic nature of Python, and use instance |
| 207 | +variables of the `LogProcessor` instance to record the "current" event, and let subsequent "meta" |
| 208 | +events patch those "current" events. |
| 209 | + |
| 210 | +The `LogProcessor` parameter also allows the extension script to hack into the internals of the log |
| 211 | +processor, just in case the extension mechanism is not flexible enough. This is not elegant in |
| 212 | +terms of encapsulation and API design, but the tools are designed to be practical and not getting in |
| 213 | +the user's ways. Since MMTk is a free open-source software, feel free to hack those tools to suit |
| 214 | +your specific needs, and discuss with MMTk developers in our official [Zulip channel]. |
| 215 | + |
| 216 | +[Zulip channel]: https://mmtk.zulipchat.com/ |
| 217 | + |
| 218 | +<!-- |
| 219 | +vim: ts=4 sw=4 sts=4 et tw=100 |
| 220 | +--> |
0 commit comments