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