Sv: Lazy Events

Tue Aug 25 18:02:53 UTC 2020

+1 on @Instant and +1 on being able to annotate away thread information. :)

I think it would be lovely with a commit(Thread) method, which captures the thread and stacktrace (async) from the thread provided as a parameter. That way you could, for example, easily build your own dynamic wall clock profiler in Java. 

Kind regards,
Marcus

-----Ursprungligt meddelande-----
Från: hotspot-jfr-dev <hotspot-jfr-dev-retn at openjdk.java.net> För Erik Gahlin
Skickat: den 25 augusti 2020 15:56
Till: Michael Bien <mbien42 at gmail.com>
Kopia: hotspot-jfr-dev <hotspot-jfr-dev at openjdk.java.net>
Ämne: Re: Lazy Events

> On 25 Aug 2020, at 12:03, Michael Bien <mbien42 at gmail.com> wrote:
> 
> 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 <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. . 
> 
>From a design point of view, it is important that any added API makes sense from an Event Metrics perspective. Time will not be the only metric that an event can measure.

>From an implementation point of view, they are dealing with the same thing (bytecode generation). You may not know this, but the methods of jdk.jfr.Event are just empty stubs. See:

http://hg.openjdk.java.net/jdk/jdk/file/tip/src/jdk.jfr/share/classes/jdk/jfr/Event.java
> 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.
> 
I hear you.

The current thinking is to add an annotation, for example @Instantaneous, to signal that an event is point-in-time. It will allow JFR to remove the duration field to reduce the event size and make it possible for tools to see that an event lacks duration from its metadata. We can see if it makes sense for end() to take the timestamp (or any other metric) if @Instantaneous is set and throw “begin must be called before end” if it is not. 

We will also investigate if the eventThread field can be removed using an annotation, similar to removing the duration field. Native events already have this capability. This could open up the possibility for users to create their own eventThread field and assign it as they see fit, or maybe some other mechanism will be invented.

Erik
> 
>> 
>> 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$ <https://urldefense.com/v3/__https://mbien.dev/blog/entry/jfrlog-logging-directly-to-the__;!!GqivPVa7Brio!IPh3pk4QWU733t8QHKSRIuPwggD6KFbvslW-BPNrcBgCtU3wlFL7US5hBiZqKWYE$>
> 