Lazy Events

[Erik Gahlin]

> On 24 Aug 2020, at 13:48, Michael Bien <mbien42 at gmail.com> wrote:
> 
> thank you for the reply,
> 
> comments inline
> 
> On 24.08.20 12:19, Erik Gahlin wrote:
>> Hello,
>> 
>> The recommended way today is to add fields. i.e.
>> 
>> class MyEvent |
>>    @Timestamp(Timestamp.MILLISECONDS_SINCE_EPOCH)
>>    long  timestamp;
>>    Thread thread;
>> }
> 
> yeah i thought about duplicating the fields, it just felt a bit redundant since it was basically already there :)
> 
>> The “eventThread” field is meant for the thread which the event was committed in.
> 
> Oh, I wrongly interpreted it as the Thread where the event happened. It would have been useful to have a standard field for this, so that tools could just grab it and know where any event occurred. (although it won't make any difference in a lot of cases)
> 
>> 
>> We are aware that JFR could be used as a storage backend where timestamps, stack trace, event thread etc. could come from a different system, but we aren’t sure the JFR consumer API and/or the JFR file format should be that system. It could be that this is better handled by third party libraries where JFR events can be pushed into those systems using event streaming. I understand that JFR may be able to store data more efficiently, but one reason for today’s efficiency (and tomorrow’s) are the limitations that JFR imposes, for example, the stack trace is taken in the commit method and users don’t have access to the clock source.
> 
> true. But what if we have something like begin() on steroids?
> 
> Lets call it writeHeader() for now (there is probably a much better name for this). Which does all the magic of commit() (stack and timestamps), but doesn't store any other event fields yet. Calling commit() stores the event fields and puts the event on the buffer using the header from before. If writeHeader() hasn't been called yet commit behaves just like today and does everything at once. Similar rules like begin/end/commit.

When a stack trace is taken, the Java implementation of JFR calls into the JVM to produce an ID which corresponds to the stack trace which is stored in a native hash table. This is to keep overhead low if the same stack trace happens again.

When a file is full and rotated the hash table is flushed. So if you are unlucky, a file may rotate between the time the ID is taken and the event is written. So we have a special mechanism to detect that in the commit method. When a chunk is rotated and the JVM is in a safepoint, it sets a notified flag. When the Java thread wakes up, it checks the flag before leaving the commit method.  If it is true, it tries to emit the event again with a new stack trace ID.

You can see this in endEvent(): src/jdk.jfr/share/classes/jdk/jfr/internal/EventWriter.java

If you would take a stack trace outside the commit method, there is a chance the stack trace in the JVM would be flushed out and a parser in the next file would not be able to parse it.

There is an enhancement called “Event Metrics” [1], which will allow users to determine what will be recorded during a call to begin() and end(). If we would add support to your use case, it would likely be using an annotation where you can specify what you want to record and when.

[1] https://bugs.openjdk.java.net/browse/JDK-8224749

Thanks
Erik

> 
> This would allow to grab the stack, time, duration etc where the event happened, but fill it with fields and commit it any time later in any other thread.
> 
> again: no strong feeling towards it, it was just a thought. Duplicating the time/Thread fields gives basically the same options + eventThread wasn't what I thought it is.
> 
>> 
>> If we would make JFR a generic backend, it would require a larger redesign.
> understood
>> Best regards,
>> Erik
> 
> thanks again & best regards,
> 
> michael
> 
> 
>>> On 24 Aug 2020, at 08:15, Michael Bien <mbien42 at gmail.com> wrote:
>>> 
>>> Hello,
>>> 
>>> I was wondering if it was ever considered to implement lazy evaluation of event attributes?
>>> 
>>> commit() must happen close to the time the event happens since it stores the time and thread id. Instead of storing all fields on commit using the client Thread, JFR could potentially append additional fields by calling event methods before its written to the repository on the JFR Thread.
>>> 
>>> class LazyEvent extends Event {
>>> 
>>>     @Label("Normal Field")
>>>    String msg1;  // taken on commit()
>>> 
>>>    @Lazy
>>>    @Label("Lazy Field")
>>>    String msg2() { return /** called by JFR thread before its written to repo **/; }
>>> 
>>> }
>>> 
>>> Another (simpler) way to allow the same functionality could be a Event::writeHeader() which would only store eventThread + startTime/duration values, while the actual Event::commit() would store the fields without altering the exiting event "header" and could be called from a different thread later.
>>> 
>>> I am mostly asking since I wrote a tiny library called JFRLog[1] which lets you log directly to JFR records using normal logging APIs. While a traditional logger impl can be usually configured to do potentially expensive stuff like message formatting or calling toString() on objects asynchronously (e.g the Thread which writes the message to a file could do this), JFRLog has to do everything in the caller Thread before event.commit(). If i would try to put that into its own thread, the eventThread IDs and startTime would be all wrong.
>>> 
>>> 
>>> its mostly just a thought i got while writing the lib - the performance is sufficient for my needs, I avoid using complex log msgs anyway which makes it just as fast as loggers which format in their own Threads. JFR does all the heavy lifting anyway.
>>> 
>>> best regards,
>>> 
>>> michael
>>> 
>>> ps: thank you for the flush-interval flag :)
>>> 
>>> 
>>> [1] https://urldefense.com/v3/__https://mbien.dev/blog/entry/jfrlog-logging-directly-to-the__;!!GqivPVa7Brio!IPh3pk4QWU733t8QHKSRIuPwggD6KFbvslW-BPNrcBgCtU3wlFL7US5hBiZqKWYE$ <https://urldefense.com/v3/__https://mbien.dev/blog/entry/jfrlog-logging-directly-to-the__;!!GqivPVa7Brio!IPh3pk4QWU733t8QHKSRIuPwggD6KFbvslW-BPNrcBgCtU3wlFL7US5hBiZqKWYE$>