Increasing heap usage with recording stream

[Gunnar Morling]

Am Di., 8. Dez. 2020 um 16:04 Uhr schrieb Erik Gahlin <
erik.gahlin at oracle.com>:

> I have filed a bug:
>
> https://bugs.openjdk.java.net/browse/JDK-8257906
>

Thanks, Erik!

>
> Erik
>
> On 8 Dec 2020, at 15:40, Gunnar Morling <gunnar at hibernate.org> wrote:
>
> Hi Denghui, Erik,
>
> Thanks for your replies. I can confirm heap size remains constant if I
> call stream.setOrdered(false);
>
> > What happens if you run the program for a longer period of time? It
> should stabilise after 10-15 seconds
>
> That's not what I observe, unfortunately. I've adjusted the program to run
> 5 * that 100M allocation loop which takes about 110 sec for me. Heap size
> is linearly growing and the GC info in the JFR recording file shows the
> increasing heap size post GCs. Below is the updated program. The heap size
> also doesn't shrink after that last GC after closing the stream.
>
> --Gunnar
>
>
> import jdk.jfr.consumer.RecordingStream;
>
> public class RecordingStreamTest {
>
> public static byte[] bytes;
>
> public static void main(String[] args) throws Exception {
> RecordingStream stream = new RecordingStream();
> stream.enable("jdk.ObjectAllocationInNewTLAB");
> stream.enable("jdk.ObjectAllocationOutsideTLAB");
> stream.onEvent(re -> {});
> stream.startAsync();
>
> for (int j = 1; j <= 5; j++) {
> for (int i = 1; i <= 100_000_000; i++) {
> bytes = new byte[1024];
> }
>
> System.gc();
> }
>
> stream.close();
> stream.awaitTermination();
>
> System.gc();
>
> Thread.sleep(5000);
> }
> }
>
> Am Di., 8. Dez. 2020 um 14:59 Uhr schrieb Erik Gahlin <
> erik.gahlin at oracle.com>:
>
>> Hi Gunnar,
>>
>> By default, a recording stream sort events and reuse event objects. This
>> means there needs to be some caching. For example, if you emit 500 000
>> events within one second, all those event must be kept in memory before the
>> sorting algorithm can be invoked.  When the next second happens, the cache
>> will remember those events object. Since events have different field layout
>> the caching happens per event type.
>>
>> I think this is what you are seeing.
>>
>> If sorting is not important, you can set
>> RecordingStream::setOrdered(false) and only one RecordedEvent will cached
>> per event type. If you set RecordingStream::setReuse(false), no caching
>> will occur. Without caching, the observer effect will increase and you are
>> more likely to  trigger a GC due to the events you stream.
>>
>> I can’t rule out a memory-leak, but the code you have seems to generate a
>> huge number of events in a very short period of time, so I think it is the
>> cache at work you are seeing.
>>
>> What happens if you run the program for a longer period of time? It
>> should stabilise after 10-15 seconds, when it reaches the highest number of
>> events per second
>>
>> Thanks
>> Erik
>>
>> > On 8 Dec 2020, at 10:16, Gunnar Morling <gunnar at hibernate.org> wrote:
>> >
>> > Hi,
>> >
>> > Here's a basic reproducer for the behaviour I observe:
>> >
>> > cat > RecordingStreamTest.java <<EOF
>> > import jdk.jfr.consumer.RecordingStream;
>> >
>> > public class RecordingStreamTest {
>> >
>> > public static byte[] bytes;
>> >
>> > public static void main(String[] args) throws Exception {
>> > RecordingStream stream = new RecordingStream();
>> > stream.enable("jdk.ObjectAllocationInNewTLAB");
>> > stream.enable("jdk.ObjectAllocationOutsideTLAB");
>> > stream.onEvent(re -> {});
>> > stream.startAsync();
>> >
>> > for (int i = 1; i <= 100_000_000; i++) {
>> > bytes = new byte[1024];
>> > }
>> >
>> > System.gc();
>> >
>> > for (int i = 1; i <= 100_000_000; i++) {
>> > bytes = new byte[1024];
>> > }
>> >
>> > stream.close();
>> > stream.awaitTermination();
>> >
>> > System.gc();
>> > }
>> > }
>> > EOF
>> >
>> > javac RecordingStreamTest.java
>> >
>> > java -XX:+HeapDumpAfterFullGC
>> >
>> -XX:StartFlightRecording=duration=2m,name=MyRecording,filename=myrecording.jfr,settings=default
>> > RecordingStreamTest
>> >
>> > The heap dump after the second full GC contains 500K RecordedEvent
>> > instances, and the flight recording shows that the heap size after GC is
>> > constantly increasing. Is this a usage error on my side (if so, what
>> should
>> > I do to prevent this?), or is it actually a memory leak somewhere in the
>> > recording stream code?
>> >
>> > Many thanks for any help,
>> >
>> > --Gunnar
>> >
>> >
>> > Am Mo., 7. Dez. 2020 um 10:20 Uhr schrieb Gunnar Morling <
>> > gunnar at hibernate.org>:
>> >>
>> >> Hi,
>> >>
>> >> I'm using a JDK 14 RecordingStream, and I observe an ever-increasing
>> heap
>> > usage as my application keeps running. The reference chain is
>> >>
>> >>    JFR Event Stream Thread -> jdk.jfr.internal.consumer.ChunkParser ->
>> > parsers jdk.jfr.internal.LongMap -> objects java.lang.Object[512]  ->
>> > jdk.jfr.internal.consumer.EventParser -> cached
>> > jdk.jfr.consumer.RecordedEvent[131072]
>> >>
>> >> I.e. that array "RecordedEvent[] cached" is continuously growing. Is
>> this
>> > a usage error on my end? I was looking for some sort of flush() or
>> similar
>> > API on RecordingStream, but can't find such a method.
>> >>
>> >> Any help would be appreciated.
>> >>
>> >> Thanks a lot,
>> >>
>> >> --Gunnar
>>
>>
>