I am not sure using geomean is a good ground for performance impact argument. Looking at the chart some test cases became faster with eventring added, how come? And redux has 10% impact, is that right?

Love to see more work in the tracing space!

I wonder if this has any relation to the tracing library we released recently: https://github.com/janestreet/tracing

Or to our work on leveraging Intel's processor trace: https://blog.janestreet.com/magic-trace/

Or to the work we've done adding probes to OCaml. Not sure if this is the best link for that: https://github.com/gretay-js/probes

I am not sure using geomean is a good ground for performance impact argument. Looking at the chart some test cases became faster with eventring added, how come? And redux has 10% impact, is that right?

I should have been more specific above the table. The numbers are the average of the normalised times against trunk (i.e normalised before averaging rather than after). Geometric mean is the right thing to do in this case: http://www.cse.unsw.edu.au/~cs9242/11/papers/Fleming_Wallace_86.pdf

Yes, some of the benchmarks show a speedup. This PR only adds instructions so you would think it would always make things slower but there's a couple of sources of noise.

First is just the machine itself. While the benchmarking machine has steps to reduce variability (https://github.com/ocaml-bench/ocaml_bench_scripts/#notes-on-hardware-and-os-settings-for-linux-benchmarking) there is still some. I have a batch run of a number of iterations of the macro benchmarking suite going to quantify what the run-to-run variability is.

Second source is actually just small changes can have knock-on effects. e.g adding a probe could change the alignment of a later loop an lead to a significant slowdown. http://eecs.northwestern.edu/~robby/courses/322-2013-spring/mytkowicz-wrong-data.pdf has some depressing examples. Also @ctk21 has good notes on his investigations https://github.com/ocaml-bench/notes/blob/master/apr19.md#what-we-learnt .

After this large batch run finishes I'll also kick off a run that only uses instruction counts.

There's also benchmarks on parallel programs that need to be done. I'm waiting on this in-case we need to revisit the design or implementation significantly.

Love to see more work in the tracing space!

Thanks for taking a look.

The aim for this PR is to only provide a facility for consuming events generated by the runtime's subsystems (mostly the GC but also some lifecycle events). This is intentional, I'm aware there's already some good observability tooling. Tracing, probes and memprof/memtrace being able to make use of eventring would be really powerful and I've already had a couple of discussions with JS folk on what some of that might look like. Eio also has an eye on replacing their tracing implementation with something atop of eventring.

It would be good to identify if there's anything in this design that precludes this from happening. Interfaces for plugging in a tracing or a probe library would be follow-up work requiring some community coordination.

Alternatively we might find we can't cover enough common usecases and eventring only functions as a way of transporting runtime events somewhere else. That's still better than the situation at the moment but it would feel like a missed opportunity.

Yeah, maybe there's something to share here. I think @gretay-js is probably the right person to connect to here.

I've updated the PR description with a sandmark run for retired instructions.

With the exception of native_multilayer, this PR adds less than a quarter of a percent to retired instructions when eventring is compiled in but not enabled.

naive_multilayer sees nearly a 1% increase in instructions retired when eventring is disabled and 22% when it is enabled. It's allocating a fair amount (~5.5GB/s and 2.9k minor gcs/s) but I think there might be something else going on. Will investigate.

Results for run-to-run variation in timings are just waiting on me to figure out how to graph them.

I found the issue with naive_multilayer. It very frequently calls caml_make_vect which ultimately triggers a handle_gc_interrupt on each invocation and this causes an EV_INTERRUPT_GC to be emitted - even if there's nothing to do. Usually we only end up on this code path when there is something non-trivial to do (and so the relative cost of checking whether eventring is enabled and emitting the event is very low).

I was considering moving this event to the instrumented runtime but I'm actually not convinced it's that useful even there so will remove it and kick off another benchmarking run.

I've rerun and updated the benchmarking results after removing EV_INTERRUPT_GC.

I looked at the benchmarks and I'm a bit confused (as often).

The "retired instructions" measures look like we expect: at most there is 0.4% increase in instruction count when eventring is enabled, nothing to worry about, and when it is disabled it's mostly lost in the noise except for a couple outliers. (What's going on with these outliers? I wonder, but given that the difference is so small it's okay anyway.)

The "time" benchmarks exhibit wide noise, possibly due to code-placement issues: there are 10% changes in performance, either up or down, with no clear pattern or obvious relation to the change itself. This is not unexpected, and we shouldn't be surprised anymore. What I do find surprising is that there are a handful of outliers (one microbenchmark and two-four macrobenchmarks; really most cases where something "interesting" seems to happen) where the eventring-disabled version is noticeably slower than the eventring-enabled version. This is weird! In particular, both versions use the same code layout (right?), so the weird difference comes from something else. (And there are essentially no programs where the difference goes in the other direction, where eventring-enabled program is noticeably slower than the eventring-disabled program.)

Am I reading the graphs wrong (I expect that score >1 means "slower than the baseline", and <1 means "faster than the baseline".)? Could you have switched the two labels by mistake?

I looked at the benchmarks and I'm a bit confused (as often).

Thanks for taking a look @gasche . Your comment did get me thinking and I realised that the eventring-pr and eventring-enabled branches could result in different runtimes. To better fit sandmark's workflow the eventring-enabled branch is eventring-pr with a one-liner commit atop that always starts eventring, regardless of whether the environment variable is passed.

So instead I kicked off another benchmarking run, this time with the same runtime but only using environment variables to turn eventring on. There's still benchmarks where eventring enabled takes less time.

I picked knucleotide3 and ran the binary (taskset on an isolated core) and averaged over 6 runs of each there's still a ~3.7% performance advantage to having eventring enabled.

I wondered whether just having an extra environment variable the same size as OCAML_EVENTRING_START was enough but no dice, it performs the same as not enabled.

@shakthimaan is currently running benchmarks of this PR on the sandmark benchmarking infrastructure (thanks Shakthi!).

The sequential macro benchmarks are done and look remarkably similar to the ones that we did on our benchmarking setup:

There are indeed still benchmarks where eventring enabled performs better than disabled.

Parallel benchmarks are still running. I'll update this when they're done.

Personally I'm not so worried about the benchmarks: there is nothing in them that suggests that the changes does add noticeable overhead (we are discussing strange noise effects, which suggests that there is nothing else to discuss). And if we were to find noticeable performance impact later, we have the easy option of moving more probes from the normal runtime to the instrumented runtime. I would consider this point settled.

But if we want to make a decision on the PR, we need:

1. decisions on whether we like the new design better than the previous Eventlog design
2. and a review of the implementation

So far we haven't had those. Point (1) sounds like an easy sell ("it comes from the same group, we said yes last time, they say it's even better this time, so what's not to like?"), and we have a caml-devel meeting shortly where you can always poll to force a decision. Point (2) is the bottleneck, as always.

This is a really cool feature @sadiqj !

I've been looking into using this with ocaml-multicore/eio#138 where I'm connecting to an existing eventring rather than creating them programatically hence testing the Some (dir, pid) logic.

Thanks @patricoferris . It looks like that code was broken after a refactoring. I really need to add a test for reading an external process' events but I may need some help from an ocamltest expert to figure out how we'd do it.

The latest changes move eventring to otherlibs and rename it to Runtime_events. The headers are split in to those functions required by the runtime (for producing) and those required by consumers.

The only quirk that I still haven't ironed out (because I'm not entirely sure it needs to be changed) is that now the Runtime_events module is in otherlibs and not the stdlib, you can't start/stop it from OCaml without linking that. You can however turn it on using the environment variable even if the program doesn't link Runtime_events.

Thanks to @dra27 for all kinds of help in getting this moved.

(rebased to trunk just now)

I want to check where we are with the PR at the moment, as it would be great to get things merged and follow up with good documentation and tooling in time for 5.0. There's also some follow up work on the set of events we currently have, there may be some we want to remove (there are some no longer present in 5.0 that are there from 4.x) and add others. I've purposefully left that out to minimise the diff for this PR.

@gasche are you still planning to take a look at the ring buffer implementation itself?

Looks like all the things I spotted in review (which focused mainly on the C code side) have been addressed.

As I said during the last development meeting, I have looked at the part of the PR that is not the C code itself. (Maybe not with the level of scrutiny of our usual full reviews, but I'm afraid we have to live with that in the absence of other volunteers.) Now that @ctk21 reviewed carefully the runtime_event_{consumer,producer}, we may have, in combination, enough assurance for an approval. @ctk21, do you agree with this assessment, or are there other things you would like to look at?

@gasche I agree with your assessment. I don't have further things that need addressing.

Thanks for squashing the commits. The PR is a great addition for observability of OCaml programs. Looking forward to using it.

As a next step, I hope you will contribute the documentation necessary for using eventring.

Great. Thanks everyone for their time in providing feedback and reviewing.

Off to documentation and supporting tooling!

This PR breaks the build on OmniOS:

gcc -m64 -c -O2 -fno-strict-aliasing -fwrapv -D_POSIX_PTHREAD_SEMANTICS -pthread -g -Wall -Werror -fno-common -fexcess-precision=standard -fno-tree-vrp -ffunction-sections  -I./runtime  -D_FILE_OFFSET_BITS=64  -DCAMLDLLIMPORT=  -o runtime/runtime_events.b.o runtime/runtime_events.c
runtime/runtime_events.c: In function 'runtime_events_teardown_raw':
runtime/runtime_events.c:138:12: error: passing argument 1 of 'munmap' from incompatible pointer type [-Werror=incompatible-pointer-types]
     munmap(current_metadata, current_ring_total_size);
            ^~~~~~~~~~~~~~~~
In file included from runtime/runtime_events.c:39:
/usr/include/sys/mman.h:245:19: note: expected 'caddr_t' {aka 'char *'} but argument is of type 'struct runtime_events_metadata_header *'
 extern int munmap(caddr_t, size_t);
                   ^~~~~~~
runtime/runtime_events.c: In function 'runtime_events_create_raw':
runtime/runtime_events.c:295:22: error: assignment to 'struct runtime_events_metadata_header *' from incompatible pointer type 'caddr_t' {aka 'char *'} [-Werror=incompatible-pointer-types]
     current_metadata = mmap(NULL, current_ring_total_size,
                      ^
cc1: all warnings being treated as errors

OmniOS is probably wrong w.r.t. the types of mmap and munmap. Possible fixes include

• add casts: munmap((void *) current_metadata, ...) and current_metadata = (struct ... *) mmap(...)
• figure out which defines to add to get POSIX-conformant header files from OmniOS
• give up on OmniOS support entirely.

Your call.

Having a look at the headers in Illumos it seems the minimum we need is _POSIX_C_SOURCE=199309L to get the conformant header. I'll get a branch together and test.

Something else is wrong on ARM 32 bits and PowerPC 32 bits:

/usr/bin/ld: /home/touraine/ci/builds/workspace/precheck/flambda/false/label/ocaml-arm-32/runtime/runtime_events.c:418: undefined reference to `__atomic_load_8'
/usr/bin/ld: /home/touraine/ci/builds/workspace/precheck/flambda/false/label/ocaml-arm-32/runtime/runtime_events.c:456: undefined reference to `__atomic_store_8'
/usr/bin/ld: /home/touraine/ci/builds/workspace/precheck/flambda/false/label/ocaml-arm-32/runtime/runtime_events.c:490: undefined reference to `__atomic_store_8'
/usr/bin/ld: /home/touraine/ci/builds/workspace/precheck/flambda/false/label/ocaml-arm-32/runtime/runtime_events.c:469: undefined reference to `__atomic_store_8'

These platforms implement 64-bit atomic operations using locks and library functions. For Clang the functions are linked automatically, but for GCC we need to link -latomic explicitly.

Do we really need 64-bit indices in the ring buffer on a 32-bit platform? Could you please use atomic_uintnat instead of atomic_uint_fast64_t ?

Note that a 64-bit atomic int implemented with locks occupies more than 8 bytes, so you're not getting the same memory layout on ARM-32 than on, say, x86-64, at any rate.

We don't need to keep 64-bit indices on 32-bit platforms. I can't imagine anyone would really want to monitor 32-bit from 64-bit or vice-versa (or across archs).

I'll test a combined fix on precheck to see if there's anything else that's fallen out.

Thinking about it... if ring_head and ring_tail are 32-bit integers, they will overflow eventually, and this doesn't seem to be handled in the current code... That's a strong reason to keep using 64-bit integers.

Oh yes, this is a good point. I'll get -latomic included for 32-bit GCC.

I'm on it, it's undergoing CI.

I pushed the -latomic fix directly to trunk: 2d8a0cf . CI seems happy.

Thank you, I'll get the omnios fix in soon.