Transaction Serialization errors

[johnaohara]

When recalulating a large dataset, the following exception is thrown;

2023-09-18 14:20:16,800 WARN  [io.agr.pool] (vert.x-worker-thread-3) Datasource '<default>': JDBC resources leaked: 1 ResultSet(s) and 1 Statement(s)
2023-09-18 14:20:16,842 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) SQL Error: 0, SQLState: 40001
2023-09-18 14:20:16,843 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.
2023-09-18 14:20:16,844 WARN  [io.agr.pool] (vert.x-worker-thread-3) Datasource '<default>': JDBC resources leaked: 1 ResultSet(s) and 1 Statement(s)
2023-09-18 14:20:17,308 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) SQL Error: 0, SQLState: 40001
2023-09-18 14:20:17,308 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.
2023-09-18 14:20:17,309 WARN  [io.agr.pool] (vert.x-worker-thread-3) Datasource '<default>': JDBC resources leaked: 1 ResultSet(s) and 1 Statement(s)
2023-09-18 14:20:17,753 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) SQL Error: 0, SQLState: 40001
2023-09-18 14:20:17,754 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.
2023-09-18 14:20:17,754 WARN  [io.agr.pool] (vert.x-worker-thread-3) Datasource '<default>': JDBC resources leaked: 1 ResultSet(s) and 1 Statement(s)
2023-09-18 14:20:18,298 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) SQL Error: 0, SQLState: 40001
2023-09-18 14:20:18,298 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.
2023-09-18 14:20:18,299 WARN  [io.agr.pool] (vert.x-worker-thread-3) Datasource '<default>': JDBC resources leaked: 1 ResultSet(s) and 1 Statement(s)
2023-09-18 14:20:18,300 ERROR [io.hyp.too.hor.ser.BaseTransactionRetryInterceptor] (vert.x-worker-thread-3) Exceeded maximum number of retries.
2023-09-18 14:20:18,300 ERROR [io.hyp.too.hor.ser.ErrorReporter] (vert.x-worker-thread-3) Exception in handler for message bus channel DATAPOINT_NEW, message DataPoint.Event{dataPoint=28277|11955@2021-08-11T00:49:08Z: 17146.53, notify=false}

: jakarta.persistence.OptimisticLockException: org.hibernate.exception.LockAcquisitionException: JDBC exception executing SQL [DELETE FROM change cc WHERE cc.id IN (SELECT id FROM change c LEFT JOIN fingerprint fp ON c.dataset_id = fp.dataset_id WHERE NOT c.confirmed AND c.variable_id = ? AND (c.timestamp > ? OR (c.timestamp = ? AND ?)) AND json_equals(fp.fingerprint, ?))] [ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.] [n/a]
	at org.hibernate.internal.ExceptionConverterImpl.wrapLockException(ExceptionConverterImpl.java:249)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:98)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:162)
	at org.hibernate.query.spi.AbstractQuery.executeUpdate(AbstractQuery.java:648)
	at io.hyperfoil.tools.horreum.svc.AlertingServiceImpl.runChangeDetection(AlertingServiceImpl.java:599)
	at io.hyperfoil.tools.horreum.svc.AlertingServiceImpl.onNewDataPoint(AlertingServiceImpl.java:555)
	at io.hyperfoil.tools.horreum.svc.AlertingServiceImpl_Subclass.onNewDataPoint$$superforward(Unknown Source)
	at io.hyperfoil.tools.horreum.svc.AlertingServiceImpl_Subclass$$function$$19.apply(Unknown Source)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:73)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext$NextAroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:97)
	at io.hyperfoil.tools.horreum.server.RolesInterceptor.intercept(RolesInterceptor.java:70)
	at io.hyperfoil.tools.horreum.server.RolesInterceptor_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:70)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext$NextAroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:97)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:136)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:107)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:61)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
	at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:70)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:62)
	at io.hyperfoil.tools.horreum.server.BaseTransactionRetryInterceptor.intercept(BaseTransactionRetryInterceptor.java:29)
	at io.hyperfoil.tools.horreum.server.BaseTransactionRetryInterceptor_RequiredTransactionRetryInterceptor_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:30)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:27)
	at io.hyperfoil.tools.horreum.svc.AlertingServiceImpl_Subclass.onNewDataPoint(Unknown Source)
	at io.hyperfoil.tools.horreum.bus.MessageBus.lambda$subscribe$3(MessageBus.java:157)
	at io.smallrye.context.impl.wrappers.SlowContextualRunnable.run(SlowContextualRunnable.java:19)
	at io.hyperfoil.tools.horreum.svc.Util.lambda$wrapForBlockingExecution$3(Util.java:496)
	at io.hyperfoil.tools.horreum.bus.TaskQueue.executeOrAdd(TaskQueue.java:27)
	at io.hyperfoil.tools.horreum.bus.MessageBus.lambda$executeForTest$9(MessageBus.java:295)
	at io.vertx.core.impl.ContextBase.lambda$executeBlocking$1(ContextBase.java:180)
	at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:277)
	at io.vertx.core.impl.ContextBase.lambda$internalExecuteBlocking$2(ContextBase.java:199)
	at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: org.hibernate.exception.LockAcquisitionException: JDBC exception executing SQL [DELETE FROM change cc WHERE cc.id IN (SELECT id FROM change c LEFT JOIN fingerprint fp ON c.dataset_id = fp.dataset_id WHERE NOT c.confirmed AND c.variable_id = ? AND (c.timestamp > ? OR (c.timestamp = ? AND ?)) AND json_equals(fp.fingerprint, ?))] [ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.] [n/a]
	at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:106)
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:56)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:108)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:94)
	at org.hibernate.sql.exec.internal.StandardJdbcMutationExecutor.execute(StandardJdbcMutationExecutor.java:96)
	at org.hibernate.query.sql.internal.NativeNonSelectQueryPlanImpl.executeUpdate(NativeNonSelectQueryPlanImpl.java:76)
	at org.hibernate.query.sql.internal.NativeQueryImpl.doExecuteUpdate(NativeQueryImpl.java:834)
	at org.hibernate.query.spi.AbstractQuery.executeUpdate(AbstractQuery.java:637)
	... 42 more
Caused by: org.postgresql.util.PSQLException: ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2713)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2401)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:368)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:498)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:415)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:190)
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:152)
	at io.agroal.pool.wrapper.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:88)
	at org.hibernate.sql.exec.internal.StandardJdbcMutationExecutor.execute(StandardJdbcMutationExecutor.java:83)
	... 45 more

[johnaohara]

Another query that fails due to serialization errors;

2023-09-18 14:23:46,018 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) SQL Error: 0, SQLState: 40001
2023-09-18 14:23:46,018 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-3) ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during conflict out checking.
  Hint: The transaction might succeed if retried.
  Where: SQL statement "SELECT labels ? (SELECT name FROM label WHERE id = NEW.label_id)"
PL/pgSQL function fp_after_lv_insert_func() line 6 at IF

[johnaohara]

Another query that keeps hitting this error;

2023-09-18 14:36:40,686 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (vert.x-worker-thread-2) ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during conflict out checking.
  Hint: The transaction might succeed if retried.
  Where: SQL statement "SELECT passphrase                   FROM dbsecret"
PL/pgSQL function has_role(text) line 12 at SQL statement

[jesperpedersen]

I think we need to consider if we want an async architecture right now...

[stalep]

I can not reproduce this from master against a prod db recalculating over 2k datasets