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

[Steven Schlansker]

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.