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?
>>
>
>
