RFC: JFR Recording Context

[Ludovic Henry]

The link to the draft PR: https://github.com/openjdk/jdk/pull/6368

On Fri, Nov 12, 2021 at 2:22 PM Ludovic Henry <ludovic at datadoghq.com> wrote:

> Hello,
>
> As it's been a couple of months since my last update, I wanted to share
> some of the progress I've made there. The TL;DR is that it now supports
> adding context to any event, as well as adding a global or per-event-type
> filters to control the generation of events based on the context.
>
> The changes are available at
> https://github.com/openjdk/jdk/compare/master...luhenry:jfr-context
>
> # Description of a context
>
> A context is a map of string key and string value which are attached to
> relevant JFR events. This context is installed on the current thread, and
> can be snapshotted and activated on other threads.
>
> # Building a context
>
> To build a context, you first declare the keys of the context :
>
> ```
>
> var contextKey1 = RecordingContextKey.forName("Key1");
>
> ```
>
> Then, to use that key to build a specific context, use the following:
>
> ```
>
> var context = RecordingContext.where(contextKey1, "Value1").build();
>
> ```
>
> # Installing a context
>
> Building a context will also install the context on the current thread. To
> uninstall the context, simply do `context.close()`.
>
> To capture the context and restore it on another thread, do:
>
> ```
>
> // On the thread where the context is already installed:
>
> var snapshot = RecordingContext.snapshot();
>
> // On the thread you want to restore/install the context:
>
> try (var activation = snapshot.activate()) { ... }
>
> ```
>
> You can also use helper functions for structured concurrency:
>
> ```
>
> RecordingContext.callWithSnapshot(o -> { ... }, snapshot);
>
> RecordingContext.runWithSnapshot(() -> { ... }, snapshot);
>
> ```
>
> # Lifecycle of a context
>
> Let’s take a look at an example:
>
> ```
>
> public class Program {
>
>   private static final RecordingContextKey contextKey1 =
>
>     RecordingContextKey.forName("Key1");
>
>   public static void main(String[] args) {
>
>     try (Recording recording = new Recording()) {
>
>       recording.start();
>
>       recording.enable("jdk.ThreadSleep");
>
>       try (RecordingContext context =
>
>             RecordingContext.where(contextKey1, "Value1").build()) {
>
>         ForkJoinPool pool = ForkJoinPool.commonPool();
>
>         final RecordingContext.Snapshot snapshot =
> RecordingContext.snapshot();
>
>         pool.execute(() -> {
>
>           try (var activation = snapshot.activate()) {
>
>             Thread.sleep(1);
>
>           }
>
>         });
>
>         pool.execute(() -> {
>
>           try (var activation = snapshot.activate()) {
>
>             Thread.sleep(1);
>
>           }
>
>         });
>
>         pool.shutdown();
>
>         pool.awaitTermination(Long.MAX_VALUE, TimeUnit.DAYS);
>
>       }
>
>       recording.stop();
>
>       recording.dump(Files.createTempFile("my-recording", ".jfr"));
>
>     }
>
>   }
>
> }
>
> ```
>
> The two `jdk.ThreadSleep` events generated are as follows:
> ```
>
> jdk.ThreadSleep {
>
>   startTime = 11:06:20.336 (2021-11-12)
>
>   duration = 1.05 ms
>
>   time = 1.00 ms
>
>   eventThread = "main" (javaThreadId = 1)
>
>   stackTrace = [
>
>     java.lang.Thread.sleep(long)
>
>     Program.lambda$main$0(RecordingContext$Snapshot) line: 23
>
>     java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec() line:
> 1395
>
>     java.util.concurrent.ForkJoinTask.doExec() line: 373
>
>     java.util.concurrent.ForkJoinPool.externalHelpQuiescePool(long,
> boolean) line: 2104
>
>   ]
>
>   context = [
>
>     Key1 -> Value1,
>
>   ]
>
> }
>
> jdk.ThreadSleep {
>
>   startTime = 11:06:20.336 (2021-11-12)
>
>   duration = 1.10 ms
>
>   time = 1.00 ms
>
>   eventThread = "ForkJoinPool.commonPool-worker-1" (javaThreadId = 18)
>
>   stackTrace = [
>
>     java.lang.Thread.sleep(long)
>
>     Program.lambda$main$0(RecordingContext$Snapshot) line: 23
>
>     java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec() line:
> 1395
>
>     java.util.concurrent.ForkJoinTask.doExec() line: 373
>
>     java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinTask,
> ForkJoinPool$WorkQueue) line: 1182
>
>   ]
>
>   context = [
>
>     Key1 -> Value1,
>
>   ]
>
> }
>
> ```
>
> # Filtering on the context
>
> In order to control the generation of events, this change introduces
> context filters. A filter is per-type or for all types, and is installed
> globally.
>
> To build and install a filter, you do the following:
>
> ```
>
> var filter = RecordingContextFilter.Config.createFilter()
>
>   .forType(EventType.getEventType(TestEvent.class), b -> {
>
>     b.hasEntry(contextKey1, "Value1");
>
>   })
>
>   .forAllTypes(b -> {
>
>     b.hasKey(contextKey1);
>
>   })
>
>   .build()
>
> RecordingContextFilter.Config.setContextFilter(filter);
>
> ```
>
> To uninstall a filter, set it to null:
> `RecordingContextFilter.Config.setContextFilter(null);`
>
> The currently supported operations are:
>
> - hasKey(key)
>
> - hasEntry(key, value)
>
> - hasContext()
>
> - hasNoContext()
>
> To guarantee a certain level of performance, I've made two tradeoffs:
>
>  - A filter can't have custom code and can only use the supported
> operations, and
>
>  - The filters are eagerly computed on the installation of a context to
> avoid matching the filter on the generation of every event. The per-type
> and for all types results are stored in a map (or array in native) to
> guarantee O(1) lookup time.
>
> From microbenchmarks, the current overhead is the following (all the JMH
> numbers at [1]):
>
> - Generating an event with the @Context annotation and an empty context
> adds ~25ns to the generation of the event
>
> - Each entry in the context adds ~100ns to the generation of an event
>
> - Setting a filter does not impact the performance of the generation of an
> event
>
> I'll submit a draft PR in the following hours to give an easier time for
> reviews and feedback.
>
> Thank you again very much, and looking forward to your feedback and
> questions.
>
> Ludovic
>
> [1]
>
> Benchmark                                                Mode  Cnt  Score
>   Error  Units
>
> RecordingContextBenchmark.Baseline.withContext           avgt   30  0.046
> ± 0.001  us/op
>
> RecordingContextBenchmark.Baseline.withoutContext        avgt   30  0.021
> ± 0.001  us/op
>
> RecordingContextBenchmark.One.withContext                avgt   30  0.160
> ± 0.005  us/op
>
> RecordingContextBenchmark.One.withoutContext             avgt   30  0.021
> ± 0.001  us/op
>
> RecordingContextBenchmark.Three.withContext              avgt   30  0.331
> ± 0.009  us/op
>
> RecordingContextBenchmark.Three.withoutContext           avgt   30  0.022
> ± 0.001  us/op
>
> RecordingContextBenchmark.Two.withContext                avgt   30  0.237
> ± 0.003  us/op
>
> RecordingContextBenchmark.Two.withoutContext             avgt   30  0.021
> ± 0.001  us/op
>
> RecordingContextFilterBenchmark.Baseline.withContext     avgt   30  0.048
> ± 0.001  us/op
>
> RecordingContextFilterBenchmark.Baseline.withoutContext  avgt   30  0.021
> ± 0.001  us/op
>
> RecordingContextFilterBenchmark.One.withContext          avgt   30  0.154
> ± 0.003  us/op
>
> RecordingContextFilterBenchmark.One.withoutContext       avgt   30  0.023
> ± 0.001  us/op
>
> RecordingContextFilterBenchmark.Three.withContext        avgt   30  0.346
> ± 0.007  us/op
>
> RecordingContextFilterBenchmark.Three.withoutContext     avgt   30  0.021
> ± 0.001  us/op
>
> RecordingContextFilterBenchmark.Two.withContext          avgt   30  0.239
> ± 0.004  us/op
>
> RecordingContextFilterBenchmark.Two.withoutContext       avgt   30  0.021
> ± 0.001  us/op
>