Timeout during obtaining a lock (quartz-1.5.2) (ORA-01013 user requested cancel of current operation)

1.4k views Asked by At

We are using quartz-1.5.2. In our application in one scenario, the scheduler is trying to delete a job.

scheduler.deleteJob(jobName, groupName);

we are getting following exception.


org.quartz.impl.jdbcjobstore.LockException: Failure obtaining db row lock: ORA-01013: 
user requested cancel of current operation  

[See nested exception: java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation ]
    at org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.obtainLock(StdRowLockSemaphore.java:155)    
    at org.quartz.impl.jdbcjobstore.JobStoreCMT.removeJob(JobStoreCMT.java:347) 
    at org.quartz.core.QuartzScheduler.deleteJob(QuartzScheduler.java:707) 
    at org.quartz.impl.StdScheduler.deleteJob(StdScheduler.java:273)
* Nested Exception (Underlying Cause) ---------------
java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation

    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:447)
    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:396)
    at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:951)
    at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:513)
    at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:227)
    at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531)
    at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:208)
    at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:886)
    at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1175)
    at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1296)
    at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3613)
    at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3657)
    at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1495)
    at weblogic.jdbc.wrapper.PreparedStatement.executeQuery(PreparedStatement.java:135)
    at org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.obtainLock(StdRowLockSemaphore.java:137)
    at org.quartz.impl.jdbcjobstore.JobStoreCMT.removeJob(JobStoreCMT.java:347)
    at org.quartz.core.QuartzScheduler.deleteJob(QuartzScheduler.java:707)
    at org.quartz.impl.StdScheduler.deleteJob(StdScheduler.java:273)

I have debugged the StdRowLockSemaphore.java obtainLock method

ps = conn.prepareStatement(selectWithLockSQL);
ps.setString(1, lockName);
if(log.isDebugEnabled())
    log.debug( "Lock '" + lockName + "' is being obtained: " + Thread.currentThread().getName());
rs = ps.executeQuery();

time out is hapenning in ps.executeQuery();

it is trying to run a simple query

SELECT * FROM QRTZ_LOCKS WHERE LOCK_NAME = 'TRIGGER_ACCESS' FOR UPDATE;

This is not hapenning in all times, when the server is up it is running without any problem, after couple of hours we are getting this problem.

please find the properties for quartz

<prop key="org.quartz.scheduler.instanceName">CargoresScheduler_${cargores_server_type}</prop>
            <prop key="org.quartz.scheduler.instanceId">AUTO</prop>
            <prop key="org.quartz.threadPool.class">org.quartz.simpl.SimpleThreadPool</prop>
            <prop key="org.quartz.threadPool.threadCount">10</prop>
            <prop key="org.quartz.threadPool.threadPriority">5</prop>
            <prop key="org.quartz.jobStore.misfireThreshold">60000</prop>

Kindly help in figuring out the problem.

--UPDATE--

please find the thread dump.

"apps_QuartzSchedulerThread" id=60 idx=0x104 tid=21586 prio=5 alive, in native

            at jrockit/net/SocketNativeIO.readBytesPinned(Ljava/io/FileDescriptor;[BIII)I(Native Method)

            at jrockit/net/SocketNativeIO.socketRead(SocketNativeIO.java:32)

            at java/net/SocketInputStream.socketRead0(Ljava/io/FileDescriptor;[BIII)I(SocketInputStream.java)

            at java/net/SocketInputStream.read(SocketInputStream.java:129)

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

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

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

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

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

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

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

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

            at oracle/jdbc/driver/T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)[inlined]

            at oracle/jdbc/driver/T4CTTIfun.receive(T4CTTIfun.java:350)[optimized]

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

            at oracle/jdbc/driver/T4C8Oall.doOALL(T4C8Oall.java:531)[inlined]

            at oracle/jdbc/driver/T4CPreparedStatement.doOall8(T4CPreparedStatement.java:208)[optimized]

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

            at oracle/jdbc/driver/OracleStatement.executeMaybeDescribe(OracleStatement.java:1207)

            at oracle/jdbc/driver/OracleStatement.doExecuteWithTimeout(OracleStatement.java:1296)

            at oracle/jdbc/driver/OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3613)

            at oracle/jdbc/driver/OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3657)

            ^-- Holding lock: oracle/jdbc/driver/T4CConnection@0x180655aa0[thin lock]

            at oracle/jdbc/driver/OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1495)

            at weblogic/jdbc/wrapper/PreparedStatement.executeQuery(PreparedStatement.java:135)

            at org/quartz/impl/jdbcjobstore/StdRowLockSemaphore.obtainLock(StdRowLockSemaphore.java:137)

            at org/quartz/impl/jdbcjobstore/JobStoreCMT.acquireNextTrigger(JobStoreCMT.java:1173)

            at org/quartz/core/QuartzSchedulerThread.run(QuartzSchedulerThread.java:233)

            at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)

            -- end of trace

        "Timer-2" id=61 idx=0x108 tid=21587 prio=5 alive, waiting, native_blocked, daemon

            -- Waiting for notification on: java/util/TaskQueue@0x1e7db6800[fat lock]

            at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)

            at java/lang/Object.wait(J)V(Native Method)

            at java/lang/Object.wait(Object.java:485)

            at java/util/TimerThread.mainLoop(Timer.java:483)

            ^-- Lock released while waiting: java/util/TaskQueue@0x1e7db6800[fat lock]

            at java/util/TimerThread.run(Timer.java:462)

            at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)

            -- end of trace

        "apps-NON_CLUSTERED_MisfireHandler" id=62 idx=0x10c tid=21588 prio=5 alive, in native, daemon

            at jrockit/net/SocketNativeIO.readBytesPinned(Ljava/io/FileDescriptor;[BIII)I(Native Method)

            at jrockit/net/SocketNativeIO.socketRead(SocketNativeIO.java:32)

            at java/net/SocketInputStream.socketRead0(Ljava/io/FileDescriptor;[BIII)I(SocketInputStream.java)

            at java/net/SocketInputStream.read(SocketInputStream.java:129)

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

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

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

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

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

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

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

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

            at oracle/jdbc/driver/T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)[inlined]

            at oracle/jdbc/driver/T4CTTIfun.receive(T4CTTIfun.java:350)[optimized]

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

            at oracle/jdbc/driver/T4C8Oall.doOALL(T4C8Oall.java:531)[inlined]

            at oracle/jdbc/driver/T4CPreparedStatement.doOall8(T4CPreparedStatement.java:208)[optimized]

            at oracle/jdbc/driver/T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:886)

            at oracle/jdbc/driver/OracleStatement.executeMaybeDescribe(OracleStatement.java:1175)

            at oracle/jdbc/driver/OracleStatement.doExecuteWithTimeout(OracleStatement.java:1296)

            at oracle/jdbc/driver/OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3613)

            at oracle/jdbc/driver/OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3657)

            ^-- Holding lock: oracle/jdbc/driver/T4CConnection@0x1809d4df8[thin lock]

            at oracle/jdbc/driver/OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1495)

            at weblogic/jdbc/wrapper/PreparedStatement.executeQuery(PreparedStatement.java:135)

            at org/quartz/impl/jdbcjobstore/StdRowLockSemaphore.obtainLock(StdRowLockSemaphore.java:137)

            at org/quartz/impl/jdbcjobstore/JobStoreCMT.doRecoverMisfires(JobStoreCMT.java:1337)

            at org/quartz/impl/jdbcjobstore/JobStoreSupport$MisfireHandler.manage(JobStoreSupport.java:2449)

            at org/quartz/impl/jdbcjobstore/JobStoreSupport$MisfireHandler.run(JobStoreSupport.java:2468)

            at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)

            -- end of trace
0

There are 0 answers