Lazy Events

[Michael Bien]

On 24.08.20 17:03, Erik Gahlin wrote:
>
>> On 24 Aug 2020, at 13:48, Michael Bien <mbien42 at gmail.com 
>> <mailto: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.

Thank you for the detailed explanation. Although i don't even have stack 
traces enabled for log message events, it makes more sense now why some 
tasks can't be easily moved ahead of commit() method.

I still wished it would be legal to call end() without begin() to record 
startTime and eventThread ahead of commit() at least, but this would 
make it really confusing for events which also have stack trace enabled 
and commit() isn't called immediately after it. This would record the 
stack and eventThread at a different place and time on commit(). 
(reading the ER link below, event-metrics events would have the same 
problem)


>
> 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

interesting! The enhancement request does far more than I would need for 
simple point-in-time events though, since it is dealing with snapshots 
over a time span.  I think there might be still a need for a new method 
to make it work for simple events. fireEvent() or reuse end() and allow 
it without begin() so that point-in-time events don't automatically 
become a duration event.


>
> Thanks
> Erik
>
thank you for your time,

michael


>>
>> 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 
>>>> <mailto: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$
>