<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1">
<style type="text/css" style="display:none;"> P {margin-top:0;margin-bottom:0;} </style>
</head>
<body dir="ltr">
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
Hi Steven,</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
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?</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
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:</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
$ java -XX:StartFlightRecording:jdk.SocketRead#threshold=0ms,filename=rec.jfr ...</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
This might provide you with greater insight.</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
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.</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<a href="https://github.com/openjdk/jdk/tree/master/test/jdk/jdk/jfr/event/io">https://github.com/openjdk/jdk/tree/master/test/jdk/jdk/jfr/event/io</a></div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
Thanks</div>
<div class="elementToProof" style="font-family: Aptos, Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica, sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
Erik</div>
<hr style="display: inline-block; width: 98%;">
<div id="divRplyFwdMsg" dir="ltr"><span style="font-family: Calibri, sans-serif; font-size: 11pt; color: rgb(0, 0, 0);"><b>From:</b> hotspot-jfr-dev <hotspot-jfr-dev-retn@openjdk.org> on behalf of Steven Schlansker <stevenschlansker@gmail.com><br>
<b>Sent:</b> Tuesday, December 17, 2024 8:08 PM<br>
<b>To:</b> hotspot-jfr-dev@openjdk.org <hotspot-jfr-dev@openjdk.org><br>
<b>Subject:</b> Socket Read event always reads 5B on jdk 23.0.1+11</span>
<div> </div>
</div>
<div style="font-size: 11pt;">Hi hotspot-jfr-dev,<br>
<br>
I am trying to track down a problem with long db queries - Java<br>
reports 10s, but the database server says the query only took 100ms.<br>
<br>
In the flight recording, I look up the Socket Read events and indeed<br>
find my suspiciously long read event. However, the event reports that<br>
only 5B are read, which is hard to believe. In fact, *every* socket<br>
read event reports exactly 5B read. This seems impossible - the server<br>
builds a 45MB response body, and all the data comes from the database.<br>
<br>
Should I expect that the socket read event reliably reports Bytes<br>
Read? I don't believe this socket stream uses asynchronous IO, which<br>
doesn't seem to be recorded at all (bummer!)<br>
I tried to read the Socket$SocketInputStream Java code but the<br>
instrumentation seems to happen due to much deeper magic.<br>
<br>
We run openjdk 23.0.1+11 on rockylinux 9.5<br>
<br>
Example event log, subset:<br>
Start Time Duration End Time Event Thread Remote Address<br>
Bytes Read End of Stream Remote Host Remote Port Timeout<br>
Value Event Type Id<br>
1734454183069711840 epochns 24210111038 ticks<br>
3815799226963477504 epochticks company-server-56 10.28.224.20<br>
5 B false wsdb 5432 0 ms jdk.SocketRead<br>
1734454183748414110 epochns 20222774822 ticks<br>
3815799224469286400 epochticks company-server-39 10.28.224.20<br>
5 B false wsdb 5432 0 ms jdk.SocketRead<br>
1734454590578194253 epochns 4759793838 ticks 3815800104031821312<br>
epochticks company-server-59 10.28.224.20 5 B false<br>
wsdb 5432 0 ms jdk.SocketRead<br>
1734454441187707733 epochns 4751996960 ticks 3815799775364954112<br>
epochticks company-server-42 10.28.224.20 5 B false<br>
wsdb 5432 0 ms jdk.SocketRead<br>
1734454425227497984 epochns 4120098692 ticks 3815799739620594688<br>
epochticks company-server-39 10.28.224.20 5 B false<br>
wsdb 5432 0 ms jdk.SocketRead<br>
1734454241790648566 epochns 1079527886 ticks 3815799333018955264<br>
epochticks company-server-55 10.28.224.20 5 B false<br>
wsdb 5432 0 ms jdk.SocketRead<br>
1734454590289810962 epochns 884150534 ticks 3815800099521735168<br>
epochticks company-server-47 10.28.224.20 5 B false<br>
wsdb 5432 0 ms jdk.SocketRead<br>
1734454649681226560 epochns 757929740 ticks 3815800230056628736<br>
epochticks company-server-47 10.28.224.20 5 B false<br>
wsdb 5432 0 ms jdk.SocketRead<br>
<br>
<br>
An example stack trace for one of the events:<br>
void jdk.internal.event.SocketReadEvent.emit(long, long, long,<br>
SocketAddress, long)<br>
int java.net.Socket$SocketInputStream.read(byte[], int, int)<br>
int sun.security.ssl.SSLSocketInputRecord.read(InputStream, byte[], int, int)<br>
int sun.security.ssl.SSLSocketInputRecord.readHeader()<br>
int sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket()<br>
ByteBuffer sun.security.ssl.SSLSocketImpl.readApplicationRecord(ByteBuffer)<br>
int sun.security.ssl.SSLSocketImpl$AppInputStream.read(byte[], int, int)<br>
boolean org.postgresql.core.VisibleBufferedInputStream.readMore(int, boolean)<br>
boolean org.postgresql.core.VisibleBufferedInputStream.ensureBytes(int, boolean)<br>
boolean org.postgresql.core.VisibleBufferedInputStream.ensureBytes(int)<br>
int org.postgresql.core.VisibleBufferedInputStream.read()<br>
int org.postgresql.core.PGStream.receiveChar()<br>
void org.postgresql.core.v3.QueryExecutorImpl.processResults(ResultHandler,<br>
int, boolean)<br>
void org.postgresql.core.v3.QueryExecutorImpl.execute(Query,<br>
ParameterList, ResultHandler, int, int, int, boolean)<br>
void org.postgresql.jdbc.PgStatement.executeInternal(CachedQuery,<br>
ParameterList, int)<br>
void org.postgresql.jdbc.PgStatement.execute(CachedQuery, ParameterList, int)<br>
boolean org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(int)<br>
boolean org.postgresql.jdbc.PgPreparedStatement.execute()<br>
boolean com.zaxxer.hikari.pool.ProxyPreparedStatement.execute()<br>
boolean com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute()<br>
<br>
Thank you for any insight - happy to provide more information if possible.</div>
</body>
</html>