Socket Read event always reads 5B on jdk 23.0.1+11

[Erik Gahlin]

Hi Steven,

There were changes to the Socket Read event in JDK 22 and JDK 23. I have looked at the implementation again, but it seems fine. Can you reproduce on JDK 21?

Only events that take more than 20 ms are written, which might explain why some events are missing? You can enable all Socket Read events with the following command:

  $ java -XX:StartFlightRecording:jdk.SocketRead#threshold=0ms,filename=rec.jfr ...

This might provide you with greater insight.

Without a standalone reproducer, it's hard to say much more. Our tests of the Socket Read event work, but they do not test the duration because it's hard to do in a quick and reliable way.

https://github.com/openjdk/jdk/tree/master/test/jdk/jdk/jfr/event/io

Thanks
Erik
________________________________
From: hotspot-jfr-dev <hotspot-jfr-dev-retn at openjdk.org> on behalf of Steven Schlansker <stevenschlansker at gmail.com>
Sent: Tuesday, December 17, 2024 8:08 PM
To: hotspot-jfr-dev at openjdk.org <hotspot-jfr-dev at openjdk.org>
Subject: Socket Read event always reads 5B on jdk 23.0.1+11

Hi hotspot-jfr-dev,

I am trying to track down a problem with long db queries - Java
reports 10s, but the database server says the query only took 100ms.

In the flight recording, I look up the Socket Read events and indeed
find my suspiciously long read event. However, the event reports that
only 5B are read, which is hard to believe. In fact, *every* socket
read event reports exactly 5B read. This seems impossible - the server
builds a 45MB response body, and all the data comes from the database.

Should I expect that the socket read event reliably reports Bytes
Read? I don't believe this socket stream uses asynchronous IO, which
doesn't seem to be recorded at all (bummer!)
I tried to read the Socket$SocketInputStream Java code but the
instrumentation seems to happen due to much deeper magic.

We run openjdk 23.0.1+11 on rockylinux 9.5

Example event log, subset:
Start Time    Duration    End Time    Event Thread    Remote Address
 Bytes Read    End of Stream    Remote Host    Remote Port    Timeout
Value    Event Type Id
1734454183069711840 epochns    24210111038 ticks
3815799226963477504 epochticks    company-server-56    10.28.224.20
5 B    false    wsdb    5432    0 ms    jdk.SocketRead
1734454183748414110 epochns    20222774822 ticks
3815799224469286400 epochticks    company-server-39    10.28.224.20
5 B    false    wsdb    5432    0 ms    jdk.SocketRead
1734454590578194253 epochns    4759793838 ticks    3815800104031821312
epochticks    company-server-59    10.28.224.20    5 B    false
wsdb    5432    0 ms    jdk.SocketRead
1734454441187707733 epochns    4751996960 ticks    3815799775364954112
epochticks    company-server-42    10.28.224.20    5 B    false
wsdb    5432    0 ms    jdk.SocketRead
1734454425227497984 epochns    4120098692 ticks    3815799739620594688
epochticks    company-server-39    10.28.224.20    5 B    false
wsdb    5432    0 ms    jdk.SocketRead
1734454241790648566 epochns    1079527886 ticks    3815799333018955264
epochticks    company-server-55    10.28.224.20    5 B    false
wsdb    5432    0 ms    jdk.SocketRead
1734454590289810962 epochns    884150534 ticks    3815800099521735168
epochticks    company-server-47    10.28.224.20    5 B    false
wsdb    5432    0 ms    jdk.SocketRead
1734454649681226560 epochns    757929740 ticks    3815800230056628736
epochticks    company-server-47    10.28.224.20    5 B    false
wsdb    5432    0 ms    jdk.SocketRead


An example stack trace for one of the events:
void jdk.internal.event.SocketReadEvent.emit(long, long, long,
SocketAddress, long)
int java.net.Socket$SocketInputStream.read(byte[], int, int)
int sun.security.ssl.SSLSocketInputRecord.read(InputStream, byte[], int, int)
int sun.security.ssl.SSLSocketInputRecord.readHeader()
int sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket()
ByteBuffer sun.security.ssl.SSLSocketImpl.readApplicationRecord(ByteBuffer)
int sun.security.ssl.SSLSocketImpl$AppInputStream.read(byte[], int, int)
boolean org.postgresql.core.VisibleBufferedInputStream.readMore(int, boolean)
boolean org.postgresql.core.VisibleBufferedInputStream.ensureBytes(int, boolean)
boolean org.postgresql.core.VisibleBufferedInputStream.ensureBytes(int)
int org.postgresql.core.VisibleBufferedInputStream.read()
int org.postgresql.core.PGStream.receiveChar()
void org.postgresql.core.v3.QueryExecutorImpl.processResults(ResultHandler,
int, boolean)
void org.postgresql.core.v3.QueryExecutorImpl.execute(Query,
ParameterList, ResultHandler, int, int, int, boolean)
void org.postgresql.jdbc.PgStatement.executeInternal(CachedQuery,
ParameterList, int)
void org.postgresql.jdbc.PgStatement.execute(CachedQuery, ParameterList, int)
boolean org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(int)
boolean org.postgresql.jdbc.PgPreparedStatement.execute()
boolean com.zaxxer.hikari.pool.ProxyPreparedStatement.execute()
boolean com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute()

Thank you for any insight - happy to provide more information if possible.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-jfr-dev/attachments/20250109/61cd14a6/attachment-0001.htm>