On 5/27/21 3:08 PM, Sam Gendler wrote:
The same JDBC connection that is resulting in lost data? Sounds to me
like you aren't connecting to the DB you think you are connecting to.
I almost wish that were true.
However, looking at AWS "Performance Insights" is see the sql statements
generate by my app begin executed on the server. Not coincidentally
this is from the "Top SQL (10)/Load by waits" view. Now that view does
NOT, in point of fact, name the database in which the sql is running,
but the rest of my environment pretty much rules out silently switching
tracks on myself. I have to read from the correct database, using a
UUID, to get data to analyze, then save the results of the analysis
back. I'm using my wonderful webapp to run this and I've successfully
analyzed and stored result for small starting data sets.
I just notice the "Top database" tab on that screen: there is only one
and it's the correct one.
I've reproduced the behaviour. I'm pretty convinced it a size thing,
but which part of the system is being max'd out is not clear. Not CPU,
but that's the only resource the "Performance Insight" mentions
(suggesting this UI wasn't designed by a database person).
The loss of the staging table is most spectacular. It filled from a
file which has 7.5M records. It's clear in the tomcat logs that is was
created and written to, one record read. Then the "top sql" happens:
insert into segment select * from
bulk."rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6" as s where
s.probandset_id >= ? and s.probandset_id < ?
the "bulk" table is the staging table. The params are filled in with a
quasi-uuid which grab roughly 1/16th of the data. In the stack trace on
my tomcat server I get
Caused by: org.jooq.exception.DataAccessException: SQL [insert into
segment select * from
bulk."rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6" as s where
s.probandset_id >= '30000000-0000-0000-0000-00000000\
0000' and s.probandset_id < '40000000-0000-0000-0000-000000000000'
]; An I/O error occurred while sending to the backend.
So this would have been the fourth such insert statement read from that
staging table.
That table is not deleted by my code. It is renamed after the last
insert into segment, by appending "_done" to the name. But that table,
by either name, is nowhere to be seen on the server.
For those scoring at home, the trouble in the tomcat log start with
0:02:11.452 [https-jsse-nio-10.0.2.28-15002-exec-7] INFO
edu.utah.camplab.jx.PayloadFromMux -
bulk."rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6": Begin
transfer from bulk to segment
27-May-2021 20:02:50.338 FINE [Catalina-utility-2]
org.apache.catalina.session.ManagerBase.processExpires Start expire
sessions StandardManager at 1622145770338 sessioncount 0
27-May-2021 20:02:50.338 FINE [Catalina-utility-2]
org.apache.catalina.session.ManagerBase.processExpires End expire
sessions StandardManager processingTime 0 expired sessions: 0
27-May-2021 20:02:50.476 FINE [Catalina-utility-2]
org.apache.catalina.session.ManagerBase.processExpires Start expire
sessions StandardManager at 1622145770476 sessioncount 1
27-May-2021 20:02:50.476 FINE [Catalina-utility-2]
org.apache.catalina.session.ManagerBase.processExpires End expire
sessions StandardManager processingTime 0 expired sessions: 0
27-May-2021 20:02:51.847 WARNING [Tomcat JDBC Pool
Cleaner[1731185718:1622133381802]]
org.apache.tomcat.jdbc.pool.ConnectionPool.abandon Connection has
been abandoned PooledConnection[org.postgresql.jdbc.PgCo\
nnection@1622ead9]:java.lang.Exception
at
org.apache.tomcat.jdbc.pool.ConnectionPool.getThreadDump(ConnectionPool.java:1163)
at
org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:816)
at
org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:660)
at
org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:198)
at
org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:132)
at
org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:90)
at
edu.utah.camplab.servlet.AbstractSGSServlet.getDbConn(AbstractSGSServlet.java:123)
at
edu.utah.camplab.servlet.AbstractSGSServlet.getDbConn(AbstractSGSServlet.java:105)
at
edu.utah.camplab.servlet.PayloadSaveServlet.doPost(PayloadSaveServlet.java:50)
....
20:02:51.854 [https-jsse-nio-10.0.2.28-15002-exec-7] DEBUG
org.jooq.impl.DefaultConnectionProvider - rollback to savepoint
20:02:51.855 [https-jsse-nio-10.0.2.28-15002-exec-7] DEBUG
org.jooq.impl.DefaultConnectionProvider - rollback
20:02:51.855 [https-jsse-nio-10.0.2.28-15002-exec-7] DEBUG
org.jooq.impl.DefaultConnectionProvider - setting auto commit : true
20:02:51.855 [https-jsse-nio-10.0.2.28-15002-exec-7] ERROR
edu.utah.camplab.jx.AbstractPayload - run
c9e224ca-85d2-40b4-ad46-327cfb9f0ac6: Exception from db write: SQL
[insert into segment select * from bulk.\
"rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6" as s where
s.probandset_id >= '30000000-0000-0000-0000-000000000000' and
s.probandset_id < '40000000-0000-0000-0000-000000000000' ]; An I/O
error occurred \
while sending to the backend.: {}
org.jooq.exception.DataAccessException: SQL [insert into segment
select * from
bulk."rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6" as s where
s.probandset_id >= '30000000-0000-0000-0000-000000000000' an\
d s.probandset_id < '40000000-0000-0000-0000-000000000000' ]; An I/O
error occurred while sending to the backend.
at org.jooq_3.14.7.POSTGRES.debug(Unknown Source)
at org.jooq.impl.Tools.translate(Tools.java:2880)
at
org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:757)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:389)
at
edu.utah.camplab.jx.PayloadFromMux.insertAllSegments(PayloadFromMux.java:177)
at
edu.utah.camplab.jx.PayloadFromMux.lambda$completeSegmentSave$3(PayloadFromMux.java:165)
at
org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:615)
at
org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:612)
at
org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:543)
at org.jooq.impl.Tools$35$1.block(Tools.java:5203)
at
java.base/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3137)
at org.jooq.impl.Tools$35.get(Tools.java:5200)
at
org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:595)
at
org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:512)
at
org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:612)
at
edu.utah.camplab.jx.PayloadFromMux.completeSegmentSave(PayloadFromMux.java:164)
at
edu.utah.camplab.jx.PayloadFromMux.writedb(PayloadFromMux.java:45)
at
edu.utah.camplab.jx.AbstractPayload.lambda$write$0(AbstractPayload.java:77)
at
org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:615)
...
Suppressed: org.jooq.exception.DataAccessException: Cannot
rollback transaction
at
org.jooq.impl.DefaultConnectionProvider.rollback(DefaultConnectionProvider.java:142)
at
org.jooq.impl.DefaultTransactionProvider.rollback(DefaultTransactionProvider.java:223)
at
org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:567)
... 45 common frames omitted
Caused by: java.sql.SQLException: Connection has already
been closed.
at
org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at
org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at
org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy4.rollback(Unknown Source)
at
org.jooq.impl.DefaultConnectionProvider.rollback(DefaultConnectionProvider.java:139)
... 47 common frames omitted
Suppressed: org.jooq.exception.DataAccessException: Cannot
set autoCommit
at
org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:222)
at
org.jooq.impl.DefaultTransactionProvider.brace(DefaultTransactionProvider.java:246)
at
org.jooq.impl.DefaultTransactionProvider.rollback(DefaultTransactionProvider.java:229)
at
org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:567)
... 33 common frames omitted
Caused by: java.sql.SQLException: Connection has already
been closed.
at
org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at
org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at
org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy4.setAutoCommit(Unknown Source)
at
org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:219)
... 36 common frames omitted
Caused by: org.postgresql.util.PSQLException: An I/O error occurred
while sending to the backend.
at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:350)
at
org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481)
at
org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401)
at
org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
at
org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:153)
at
jdk.internal.reflect.GeneratedMethodAccessor25.invoke(Unknown Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at
org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
at com.sun.proxy.$Proxy14.execute(Unknown Source)
at
org.jooq.tools.jdbc.DefaultPreparedStatement.execute(DefaultPreparedStatement.java:214)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:458)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:375)
... 50 common frames omitted
Caused by: javax.net.ssl.SSLException: Socket closed
at
java.base/sun.security.ssl.Alert.createSSLException(Alert.java:127)
at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:369)
at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:312)
at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:307)
at
java.base/sun.security.ssl.SSLSocketImpl.handleException(SSLSocketImpl.java:1680)
at
java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1054)
at
org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:161)
at
org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:128)
