Done, HIVE-11934 Sent from my iPad
> On Sep 23, 2015, at 12:03 PM, Eugene Koifman <[email protected]> wrote: > > could you file a Jira for this please? > > From: Eugene Koifman <[email protected]> > Reply-To: "[email protected]" <[email protected]> > Date: Wednesday, September 23, 2015 at 8:15 AM > To: "[email protected]" <[email protected]> > Subject: Re: Transaction deadlocks > > that’s indeed a problem. > > From: Steve Howard <[email protected]> > Reply-To: "[email protected]" <[email protected]> > Date: Tuesday, September 22, 2015 at 6:48 PM > To: "[email protected]" <[email protected]> > Subject: Re: Transaction deadlocks > > Am I missing it, or do you reset the deadlock count to 0 every time the lock > method is taken, so the ten count is never reached in checkRetryable()? > > public LockResponse lock(LockRequest rqst) > throws NoSuchTxnException, TxnAbortedException, MetaException > { > >>> this.deadlockCnt = 0; <<< > try > { > Connection dbConn = null; > try > { > dbConn = getDbConn(8); > return lock(dbConn, rqst, true); > } > catch (SQLException e) > { > LOG.debug("Going to rollback"); > rollbackDBConn(dbConn); > checkRetryable(dbConn, e, "lock(" + rqst + ")"); > throw new MetaException("Unable to update transaction database " + > StringUtils.stringifyException(e)); > } > finally > { > closeDbConn(dbConn); > } > return lock(rqst); > } > catch (RetryException e) {} > } > > >> On Tue, Sep 22, 2015 at 9:24 PM, Steve Howard <[email protected]> wrote: >> Hi Eugene, >> >> This is HDP 2.3, 1.2.1.2.3.0.0-2557. >> >> I see the deadlock count is 10, and we haven't overriden >> ConfVars.HMSHANDLERATTEMPTS, which also defaults to 10. I am at a loss why >> the call stack would be that large (I think it is 1,000), as that indicates >> to me it keeps failing to get the lock and keeps calling itself. >> >> protected void checkRetryable(Connection conn, SQLException e, String >> caller) >> throws TxnHandler.RetryException, MetaException >> { >> if ((this.dbProduct == null) && (conn != null)) { >> determineDatabaseProduct(conn); >> } >> if (((e instanceof SQLTransactionRollbackException)) || >> (((this.dbProduct != DatabaseProduct.MYSQL) && (this.dbProduct != >> DatabaseProduct.POSTGRES) && (this.dbProduct != DatabaseProduct.SQLSERVER)) >> || ((e.getSQLState().equals("40001")) || ((this.dbProduct == >> DatabaseProduct.POSTGRES) && (e.getSQLState().equals("40P01"))) || >> ((this.dbProduct == DatabaseProduct.ORACLE) && >> ((e.getMessage().contains("deadlock detected")) || >> (e.getMessage().contains("can't serialize access for this transaction"))))))) >> { >> if (this.deadlockCnt++ < 10) >> { >> long waitInterval = this.deadlockRetryInterval * this.deadlockCnt; >> LOG.warn("Deadlock detected in " + caller + ". Will wait " + >> waitInterval + "ms try again up to " + (10 - this.deadlockCnt + 1) + " >> times."); >> try >> { >> Thread.sleep(waitInterval); >> } >> catch (InterruptedException ie) {} >> throw new RetryException(); >> } >> LOG.error("Too many repeated deadlocks in " + caller + ", giving up."); >> this.deadlockCnt = 0; >> } >> else if (isRetryable(e)) >> { >> if (this.retryNum++ < this.retryLimit) >> { >> LOG.warn("Retryable error detected in " + caller + ". Will wait " + >> this.retryInterval + "ms and retry up to " + (this.retryLimit - >> this.retryNum + 1) + " times. Error: " + getMessage(e)); >> try >> { >> Thread.sleep(this.retryInterval); >> } >> catch (InterruptedException ex) {} >> throw new RetryException(); >> } >> LOG.error("Fatal error. Retry limit (" + this.retryLimit + ") reached. >> Last error: " + getMessage(e)); >> this.retryNum = 0; >> } >> else >> { >> this.deadlockCnt = 0; >> this.retryNum = 0; >> } >> } >> >> Thanks, >> >> Steve >> >>> On Tue, Sep 22, 2015 at 6:22 PM, Eugene Koifman <[email protected]> >>> wrote: >>> What version of Hive are you running? In the current codebase at least, >>> TxnHandler.checkRetryable() keeps track of how many retries it allowed – it >>> will not retry forever. >>> >>> >>> From: Steve Howard <[email protected]> >>> Reply-To: "[email protected]" <[email protected]> >>> Date: Tuesday, September 22, 2015 at 1:32 PM >>> To: "[email protected]" <[email protected]> >>> Subject: Transaction deadlocks >>> >>> >>> >>> Thread A… >>> >>> >>> >>> >>> >>> "HiveServer2-Background-Pool: Thread-35" #35 prio=5 os_prio=0 >>> tid=0x00007fd150e40000 nid=0x2c97 runnable [0x00007fd146e0a000] >>> >>> java.lang.Thread.State: RUNNABLE >>> >>> at java.net.SocketInputStream.socketRead0(Native Method) >>> >>> at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) >>> >>> at java.net.SocketInputStream.read(SocketInputStream.java:170) >>> >>> at java.net.SocketInputStream.read(SocketInputStream.java:141) >>> >>> at oracle.net.ns.Packet.receive(Packet.java:300) >>> >>> at oracle.net.ns.DataPacket.receive(DataPacket.java:106) >>> >>> at >>> oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315) >>> >>> at oracle.net.ns.NetInputStream.read(NetInputStream.java:260) >>> >>> at oracle.net.ns.NetInputStream.read(NetInputStream.java:185) >>> >>> at oracle.net.ns.NetInputStream.read(NetInputStream.java:102) >>> >>> 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) >>> >>> at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290) >>> >>> at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192) >>> >>> at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531) >>> >>> at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:193) >>> >>> at >>> oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:1033) >>> >>> at >>> oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1329) >>> >>> at >>> oracle.jdbc.driver.OracleStatement.executeUpdateInternal(OracleStatement.java:1838) >>> >>> at >>> oracle.jdbc.driver.OracleStatement.executeUpdate(OracleStatement.java:1803) >>> >>> - locked <0x00000000c09fcda0> (a oracle.jdbc.driver.T4CConnection) >>> >>> at >>> oracle.jdbc.driver.OracleStatementWrapper.executeUpdate(OracleStatementWrapper.java:294) >>> >>> at >>> org.apache.commons.dbcp.DelegatingStatement.executeUpdate(DelegatingStatement.java:228) >>> >>> at >>> org.apache.commons.dbcp.DelegatingStatement.executeUpdate(DelegatingStatement.java:228) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:1432) >>> >>> - locked <0x00000000c09fcc28> (a java.lang.Object) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:422) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> >>> >>> >>> >>> …blocks Thread B, resulting in a deadlock message being written to the logs >>> over and over again… >>> >>> >>> >>> >>> >>> >>> >>> >>> >>> "HiveServer2-Background-Pool: Thread-51" #51 prio=5 os_prio=0 >>> tid=0x000000000279f000 nid=0x7227 waiting for monitor entry >>> [0x00007fd146a47000] >>> >>> java.lang.Thread.State: BLOCKED (on object monitor) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:1361) >>> >>> - waiting to lock <0x00000000c09fcc28> (a java.lang.Object) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:422) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> at >>> org.apache.hadoop.hive.metastore.txn.TxnHandler.lock(TxnHandler.java:433) >>> >>> >>> >>> >>> >>> …but my guess is the bigger issue is that eventually the stack will be >>> exhausted, as the method below recursively calls itself (notice the stack >>> above)… >>> >>> >>> >>> >>> >>> public LockResponse lock(LockRequest rqst) >>> >>> throws NoSuchTxnException, TxnAbortedException, MetaException >>> >>> { >>> >>> this.deadlockCnt = 0; >>> >>> try >>> >>> { >>> >>> Connection dbConn = null; >>> >>> try >>> >>> { >>> >>> dbConn = getDbConn(8); >>> >>> return lock(dbConn, rqst, true); >>> >>> } >>> >>> catch (SQLException e) >>> >>> { >>> >>> LOG.debug("Going to rollback"); >>> >>> rollbackDBConn(dbConn); >>> >>> checkRetryable(dbConn, e, "lock(" + rqst + ")"); >>> >>> throw new MetaException("Unable to update transaction database " + >>> StringUtils.stringifyException(e)); >>> >>> } >>> >>> finally >>> >>> { >>> >>> closeDbConn(dbConn); >>> >>> } >>> >>> return lock(rqst); >>> >>> } >>> >>> catch (RetryException e) {} >>> >>> } >>> >>> >>> >>> >>> This effectively freezes all access to a table. >>> >>> Any ideas? >> >
