5 Replies Latest reply on Feb 23, 2017 1:36 PM by cfang

    JdbcItemReader and Transactions

    joao.santana

      Hi all.


      I'm using jdbcitemreader with a datasource (jta = false).


      The query is taking too long to run (the database server is in an unstable environment).


      So, in 3 minutes the transaction timed out...


      10:57:46,606 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffac1e0f32:-1c34c4e0:57b70cd0:36 in state  RUN

      10:57:46,609 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffac1e0f32:-1c34c4e0:57b70cd0:36 invoked while multiple threads active within it.

      10:57:46,612 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffffac1e0f32:-1c34c4e0:57b70cd0:36 completed with multiple threads - thread Batch Thread - 2 was in progress with java.net.SocketInputStream.socketRead0(Native Method)

       

      how to set the timeout if the datasource is not using jta?


      Default transactions configuration:


      <subsystem xmlns="urn:jboss:domain:transactions:3.0">
           <core-environment>
                <process-id>
                     <uuid/>
                </process-id>
           </core-environment>
           <recovery-environment socket-binding="txn-recovery-environment" status-socket-binding="txn-status-manager"/>
           <coordinator-environment default-timeout="300"/>
      </subsystem>
      
        • 1. Re: JdbcItemReader and Transactions
          cfang

          You can try WildFly forum WildFly , if you're looking for a way to tune the WildFly transaction subsystem.  Or WildFly User chat HipChat

          • 2. Re: JdbcItemReader and Transactions
            joao.santana

            the stak is:

             

             

            21:56:07,887 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a83801:-66797c34:58a38e4e:7641 in state  RUN

            21:56:07,891 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a83801:-66797c34:58a38e4e:7641 invoked while multiple threads active within it.

            21:56:07,894 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffffc0a83801:-66797c34:58a38e4e:7641 completed with multiple threads - thread Batch Thread - 1 was in progress with java.net.SocketInputStream.socketRead0(Native Method)

            java.net.SocketInputStream.socketRead(SocketInputStream.java:116)

            java.net.SocketInputStream.read(SocketInputStream.java:170)

            java.net.SocketInputStream.read(SocketInputStream.java:141)

            oracle.net.ns.Packet.receive(Packet.java:308)

            oracle.net.ns.DataPacket.receive(DataPacket.java:106)

            oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:324)

            oracle.net.ns.NetInputStream.read(NetInputStream.java:268)

            oracle.net.ns.NetInputStream.read(NetInputStream.java:190)

            oracle.net.ns.NetInputStream.read(NetInputStream.java:107)

            oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)

            oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)

            oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)

            oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:350)

            oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:227)

            oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531)

            oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:208)

            oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:1046)

            oracle.jdbc.driver.OraclePreparedStatement.executeForRowsWithTimeout(OraclePreparedStatement.java:10298)

            oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:10404)

            oracle.jdbc.driver.OracleStatementWrapper.executeBatch(OracleStatementWrapper.java:230)

            org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1190)

            org.jberet.support.io.JdbcItemWriter.writeItems(JdbcItemWriter.java:108)

            org.jberet.runtime.runner.ChunkRunner.doCheckpoint(ChunkRunner.java:528)

            org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:317)

            org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:201)

            org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:226)

            org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:147)

            org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164)

            org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88)

            org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:60)

            org.wildfly.extension.batch.jberet.impl.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:243)

            org.wildfly.extension.requestcontroller.RequestController$QueuedTask$1.run(RequestController.java:497)

            org.jberet.spi.JobExecutor$3.run(JobExecutor.java:161)

            org.jberet.spi.JobExecutor$1.run(JobExecutor.java:99)

            java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

            java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

            java.lang.Thread.run(Thread.java:745)

            org.jboss.threads.JBossThread.run(JBossThread.java:320)

             

            21:56:07,965 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a83801:-66797c34:58a38e4e:7641 aborting with 1 threads active!

            21:56:08,138 WARN  [com.arjuna.ats.arjuna] (Batch Thread - 1) ARJUNA012077: Abort called on already aborted atomic action 0:ffffc0a83801:-66797c34:58a38e4e:7641

            21:56:08,139 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffffc0a83801:-66797c34:58a38e4e:7641

            21:56:08,142 ERROR [org.jberet] (Batch Thread - 1) ProcessingInfo{count=0, timerExpired=false, itemState=RUNNING, chunkState=RUNNING, checkpointPosition=-1, readPosition=15979, failurePoint=null}

            21:56:08,158 ERROR [org.jberet] (Batch Thread - 1) item-count=10, time-limit=0, skip-limit=-1, skipCount=1743, retry-limit=5, retryCount=5

            21:56:08,160 ERROR [org.jberet] (Batch Thread - 1) JBERET000007: Failed to run job data-loader, carregarDados, org.jberet.job.model.Chunk@71d7a7cd: javax.transaction.NotSupportedException: BaseTransaction.checkTransactionState - ARJUNA016051: thread is already associated with a transaction!

                    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.begin(BaseTransaction.java:73)

                    at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.begin(BaseTransactionManagerDelegate.java:78)

                    at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:296)

                    at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:201)

                    at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:226)

                    at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:147)

                    at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164)

                    at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88)

                    at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:60)

                    at org.wildfly.extension.batch.jberet.impl.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:243)

                    at org.wildfly.extension.requestcontroller.RequestController$QueuedTask$1.run(RequestController.java:497)

                    at org.jberet.spi.JobExecutor$3.run(JobExecutor.java:161)

                    at org.jberet.spi.JobExecutor$1.run(JobExecutor.java:99)

                    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

                    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

                    at java.lang.Thread.run(Thread.java:745)

                    at org.jboss.threads.JBossThread.run(JBossThread.java:320)

            Caused by: java.lang.IllegalStateException: BaseTransaction.checkTransactionState - ARJUNA016051: thread is already associated with a transaction!

                    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.checkTransactionState(BaseTransaction.java:264)

                    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.begin(BaseTransaction.java:68)

                    ... 16 more

             

            its not a batch thread configuration problem? the query fetch so many data...

            • 3. Re: JdbcItemReader and Transactions
              cfang

              the batch spec (JSR 352) defines a step property to control global transaction timeout:

               

              javax.transaction.global.timeout

               

              , which takes the number of seconds, and the defautl is 180 seconds.

               

              <step id="step1">

                      <properties>

                          <property name="javax.transaction.global.timeout" value="360"></property>

                      </properties>

               

              Did you try that, and did it make any difference?

              • 4. Re: JdbcItemReader and Transactions
                joao.santana

                yes... it did. about transactions yet...

                 

                what does it means?

                 

                after a:

                 

                "WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffffc0a83801:72254a9b:58addeac:f51f"

                 

                all scheduled jobs are stopped ... wating i guess...

                 

                In my wildfly runtime console:

                Thread Pool

                Active Count10
                Completed Task Count333
                Current Thread Count10
                Largest Thread Count10
                Queue Size85
                Rejected Count0
                Task Count428
                • 5. Re: JdbcItemReader and Transactions
                  cfang

                  I think the ultimate fix is to refactor the application transaction logic to perform less work in a transaction scope, and to tune the database query/index, etc.

                   

                  If the above is not possible, then you can try changing the WildFly transaction default timeout. You can do it either in CLI or admin console.

                   

                  [standalone@localhost:9990 /] /subsystem=transactions:write-attribute(name=default-timeout, value=1200)

                  {

                      "outcome" => "success",

                      "response-headers" => {

                          "operation-requires-reload" => true,

                          "process-state" => "reload-required"

                      }

                  }

                   

                  For more info, check docs/schema/wildfly-txn_3_0.xsd in your WildFly installation:

                   

                  <xs:complexType name="coordinator-environment">

                          <xs:annotation>

                              <xs:documentation>

                              <![CDATA[

                                  The coordinator environment configuration.

                                  statistics-enabled - if recording of transaction statistics is enabled, false otherwise.

                                  enable-tsm-status - if the transaction status manager (TSM) service, needed for out of process recovery, should be provided or not.

                                  default-timeout - the default transaction lifetime, in seconds.

                              ]]>

                              </xs:documentation>

                          </xs:annotation>

                          <xs:attribute name="statistics-enabled" type="xs:boolean" default="false"/>

                          <xs:attribute name="enable-statistics" type="xs:boolean" default="false">

                              <xs:annotation>

                                  <xs:documentation>

                                      <![CDATA[ Deprecated. Use statistics-enabled. ]]>

                                  </xs:documentation>

                              </xs:annotation>

                          </xs:attribute>

                          <xs:attribute name="enable-tsm-status" type="xs:boolean" default="false"/>

                          <xs:attribute name="default-timeout" type="xs:int" default="300" />

                      </xs:complexType>