Author: szehon
Date: Fri Jul 25 23:03:49 2014
New Revision: 1613530
URL: http://svn.apache.org/r1613530
Log:
HIVE-7445 : Improve LOGS for Hive when a query is not able to acquire locks
(Chaoyu Tang via Szehon)
Modified:
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/HiveLockObject.java
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/zookeeper/ZooKeeperHiveLockManager.java
hive/trunk/ql/src/test/results/clientnegative/insert_into1.q.out
hive/trunk/ql/src/test/results/clientnegative/insert_into2.q.out
hive/trunk/ql/src/test/results/clientnegative/insert_into3.q.out
hive/trunk/ql/src/test/results/clientnegative/insert_into4.q.out
hive/trunk/ql/src/test/results/clientnegative/lockneg1.q.out
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_db_lock_conflict.q.out
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_drop_locked_db.q.out
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_lock_db_in_use.q.out
Modified:
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/HiveLockObject.java
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/HiveLockObject.java?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
---
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/HiveLockObject.java
(original)
+++
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/HiveLockObject.java
Fri Jul 25 23:03:49 2014
@@ -70,6 +70,9 @@ public class HiveLockObject {
lockTime = elem[1];
lockMode = elem[2];
queryStr = elem[3];
+ if (elem.length >= 5) {
+ clientIp = elem[4];
+ }
}
public String getQueryId() {
Modified:
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/zookeeper/ZooKeeperHiveLockManager.java
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/zookeeper/ZooKeeperHiveLockManager.java?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
---
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/zookeeper/ZooKeeperHiveLockManager.java
(original)
+++
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/lockmgr/zookeeper/ZooKeeperHiveLockManager.java
Fri Jul 25 23:03:49 2014
@@ -28,6 +28,7 @@ import org.apache.hadoop.hive.ql.lockmgr
import org.apache.hadoop.hive.ql.metadata.*;
import org.apache.hadoop.hive.ql.session.SessionState.LogHelper;
import org.apache.zookeeper.CreateMode;
+import org.apache.zookeeper.data.Stat;
import org.apache.zookeeper.KeeperException;
import org.apache.zookeeper.Watcher;
import org.apache.zookeeper.ZooDefs.Ids;
@@ -296,45 +297,77 @@ public class ZooKeeperHiveLockManager im
private ZooKeeperHiveLock lock (HiveLockObject key, HiveLockMode mode,
boolean keepAlive, boolean parentCreated) throws LockException {
- int tryNum = 1;
+ int tryNum = 0;
ZooKeeperHiveLock ret = null;
+ Set<String> conflictingLocks = new HashSet<String>();
do {
+ tryNum++;
try {
if (tryNum > 1) {
Thread.sleep(sleepTime);
prepareRetry();
}
- ret = lockPrimitive(key, mode, keepAlive, parentCreated);
+ ret = lockPrimitive(key, mode, keepAlive, parentCreated,
conflictingLocks);
if (ret != null) {
break;
}
- tryNum++;
} catch (Exception e1) {
- tryNum++;
if (e1 instanceof KeeperException) {
KeeperException e = (KeeperException) e1;
switch (e.code()) {
case CONNECTIONLOSS:
case OPERATIONTIMEOUT:
- LOG.warn("Possibly transient ZooKeeper exception: ", e);
- break;
+ LOG.debug("Possibly transient ZooKeeper exception: ", e);
+ continue;
default:
LOG.error("Serious Zookeeper exception: ", e);
break;
}
}
if (tryNum >= numRetriesForLock) {
+ console.printError("Unable to acquire " + key.getData().getLockMode()
+ + ", " + mode + " lock " + key.getDisplayName() + " after "
+ + tryNum + " attempts.");
+ LOG.error("Exceeds maximum retries with errors: ", e1);
+ printConflictingLocks(key,mode,conflictingLocks);
+ conflictingLocks.clear();
throw new LockException(e1);
}
}
} while (tryNum < numRetriesForLock);
+ if (ret == null) {
+ console.printError("Unable to acquire " + key.getData().getLockMode()
+ + ", " + mode + " lock " + key.getDisplayName() + " after "
+ + tryNum + " attempts.");
+ printConflictingLocks(key,mode,conflictingLocks);
+ }
+ conflictingLocks.clear();
return ret;
}
+ private void printConflictingLocks(HiveLockObject key, HiveLockMode mode,
+ Set<String> conflictingLocks) {
+ if (!conflictingLocks.isEmpty()) {
+ HiveLockObjectData requestedLock = new
HiveLockObjectData(key.getData().toString());
+ LOG.debug("Requested lock " + key.getDisplayName()
+ + ":: mode:" + requestedLock.getLockMode() + "," + mode
+ + "; query:" + requestedLock.getQueryStr());
+ for (String conflictingLock : conflictingLocks) {
+ HiveLockObjectData conflictingLockData = new
HiveLockObjectData(conflictingLock);
+ LOG.debug("Conflicting lock to " + key.getDisplayName()
+ + ":: mode:" + conflictingLockData.getLockMode()
+ + ";query:" + conflictingLockData.getQueryStr()
+ + ";queryId:" + conflictingLockData.getQueryId()
+ + ";clientIp:" + conflictingLockData.getClientIp());
+ }
+ }
+ }
+
private ZooKeeperHiveLock lockPrimitive(HiveLockObject key,
- HiveLockMode mode, boolean keepAlive, boolean parentCreated)
+ HiveLockMode mode, boolean keepAlive, boolean parentCreated,
+ Set<String> conflictingLocks)
throws KeeperException, InterruptedException {
String res;
@@ -394,9 +427,19 @@ public class ZooKeeperHiveLockManager im
}
if ((childSeq >= 0) && (childSeq < seqNo)) {
- zooKeeper.delete(res, -1);
- console.printError("conflicting lock present for "
- + key.getDisplayName() + " mode " + mode);
+ try {
+ zooKeeper.delete(res, -1);
+ } finally {
+ if (LOG.isDebugEnabled()) {
+ Stat stat = new Stat();
+ try {
+ String data = new String(zooKeeper.getData(child, false, stat));
+ conflictingLocks.add(data);
+ } catch (Exception e) {
+ //ignored
+ }
+ }
+ }
return null;
}
}
Modified: hive/trunk/ql/src/test/results/clientnegative/insert_into1.q.out
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/test/results/clientnegative/insert_into1.q.out?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
--- hive/trunk/ql/src/test/results/clientnegative/insert_into1.q.out (original)
+++ hive/trunk/ql/src/test/results/clientnegative/insert_into1.q.out Fri Jul 25
23:03:49 2014
@@ -13,8 +13,5 @@ PREHOOK: query: LOCK TABLE insert_into1_
PREHOOK: type: LOCKTABLE
POSTHOOK: query: LOCK TABLE insert_into1_neg SHARED
POSTHOOK: type: LOCKTABLE
-conflicting lock present for default@insert_into1_neg mode EXCLUSIVE
-conflicting lock present for default@insert_into1_neg mode EXCLUSIVE
-conflicting lock present for default@insert_into1_neg mode EXCLUSIVE
-conflicting lock present for default@insert_into1_neg mode EXCLUSIVE
+Unable to acquire IMPLICIT, EXCLUSIVE lock default@insert_into1_neg after 5
attempts.
FAILED: Error in acquiring locks: Locks on the underlying objects cannot be
acquired. retry after some time
Modified: hive/trunk/ql/src/test/results/clientnegative/insert_into2.q.out
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/test/results/clientnegative/insert_into2.q.out?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
--- hive/trunk/ql/src/test/results/clientnegative/insert_into2.q.out (original)
+++ hive/trunk/ql/src/test/results/clientnegative/insert_into2.q.out Fri Jul 25
23:03:49 2014
@@ -13,8 +13,5 @@ PREHOOK: query: LOCK TABLE insert_into1_
PREHOOK: type: LOCKTABLE
POSTHOOK: query: LOCK TABLE insert_into1_neg EXCLUSIVE
POSTHOOK: type: LOCKTABLE
-conflicting lock present for default@insert_into1_neg mode EXCLUSIVE
-conflicting lock present for default@insert_into1_neg mode EXCLUSIVE
-conflicting lock present for default@insert_into1_neg mode EXCLUSIVE
-conflicting lock present for default@insert_into1_neg mode EXCLUSIVE
+Unable to acquire IMPLICIT, EXCLUSIVE lock default@insert_into1_neg after 5
attempts.
FAILED: Error in acquiring locks: Locks on the underlying objects cannot be
acquired. retry after some time
Modified: hive/trunk/ql/src/test/results/clientnegative/insert_into3.q.out
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/test/results/clientnegative/insert_into3.q.out?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
--- hive/trunk/ql/src/test/results/clientnegative/insert_into3.q.out (original)
+++ hive/trunk/ql/src/test/results/clientnegative/insert_into3.q.out Fri Jul 25
23:03:49 2014
@@ -27,8 +27,5 @@ PREHOOK: query: LOCK TABLE insert_into3_
PREHOOK: type: LOCKTABLE
POSTHOOK: query: LOCK TABLE insert_into3_neg PARTITION (ds='1') SHARED
POSTHOOK: type: LOCKTABLE
-conflicting lock present for default@insert_into3_neg@ds=1 mode EXCLUSIVE
-conflicting lock present for default@insert_into3_neg@ds=1 mode EXCLUSIVE
-conflicting lock present for default@insert_into3_neg@ds=1 mode EXCLUSIVE
-conflicting lock present for default@insert_into3_neg@ds=1 mode EXCLUSIVE
+Unable to acquire IMPLICIT, EXCLUSIVE lock default@insert_into3_neg@ds=1 after
5 attempts.
FAILED: Error in acquiring locks: Locks on the underlying objects cannot be
acquired. retry after some time
Modified: hive/trunk/ql/src/test/results/clientnegative/insert_into4.q.out
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/test/results/clientnegative/insert_into4.q.out?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
--- hive/trunk/ql/src/test/results/clientnegative/insert_into4.q.out (original)
+++ hive/trunk/ql/src/test/results/clientnegative/insert_into4.q.out Fri Jul 25
23:03:49 2014
@@ -27,8 +27,5 @@ PREHOOK: query: LOCK TABLE insert_into3_
PREHOOK: type: LOCKTABLE
POSTHOOK: query: LOCK TABLE insert_into3_neg PARTITION (ds='1') EXCLUSIVE
POSTHOOK: type: LOCKTABLE
-conflicting lock present for default@insert_into3_neg@ds=1 mode EXCLUSIVE
-conflicting lock present for default@insert_into3_neg@ds=1 mode EXCLUSIVE
-conflicting lock present for default@insert_into3_neg@ds=1 mode EXCLUSIVE
-conflicting lock present for default@insert_into3_neg@ds=1 mode EXCLUSIVE
+Unable to acquire IMPLICIT, EXCLUSIVE lock default@insert_into3_neg@ds=1 after
5 attempts.
FAILED: Error in acquiring locks: Locks on the underlying objects cannot be
acquired. retry after some time
Modified: hive/trunk/ql/src/test/results/clientnegative/lockneg1.q.out
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/test/results/clientnegative/lockneg1.q.out?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
--- hive/trunk/ql/src/test/results/clientnegative/lockneg1.q.out (original)
+++ hive/trunk/ql/src/test/results/clientnegative/lockneg1.q.out Fri Jul 25
23:03:49 2014
@@ -29,5 +29,5 @@ POSTHOOK: query: LOCK TABLE tstsrc SHARE
POSTHOOK: type: LOCKTABLE
PREHOOK: query: LOCK TABLE tstsrc EXCLUSIVE
PREHOOK: type: LOCKTABLE
-conflicting lock present for default@tstsrc mode EXCLUSIVE
+Unable to acquire EXPLICIT, EXCLUSIVE lock default@tstsrc after 1 attempts.
FAILED: Execution Error, return code 1 from
org.apache.hadoop.hive.ql.exec.DDLTask
Modified:
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_db_lock_conflict.q.out
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/test/results/clientnegative/lockneg_try_db_lock_conflict.q.out?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
---
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_db_lock_conflict.q.out
(original)
+++
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_db_lock_conflict.q.out
Fri Jul 25 23:03:49 2014
@@ -8,5 +8,5 @@ POSTHOOK: query: lock database lockneg4
POSTHOOK: type: LOCKDATABASE
PREHOOK: query: lock database lockneg4 shared
PREHOOK: type: LOCKDATABASE
-conflicting lock present for lockneg4 mode SHARED
+Unable to acquire EXPLICIT, SHARED lock lockneg4 after 1 attempts.
FAILED: Execution Error, return code 1 from
org.apache.hadoop.hive.ql.exec.DDLTask
Modified:
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_drop_locked_db.q.out
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/test/results/clientnegative/lockneg_try_drop_locked_db.q.out?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
---
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_drop_locked_db.q.out
(original)
+++
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_drop_locked_db.q.out
Fri Jul 25 23:03:49 2014
@@ -10,5 +10,5 @@ PREHOOK: query: show locks database lock
PREHOOK: type: SHOWLOCKS
POSTHOOK: query: show locks database lockneg9
POSTHOOK: type: SHOWLOCKS
-conflicting lock present for lockneg9 mode EXCLUSIVE
+Unable to acquire IMPLICIT, EXCLUSIVE lock lockneg9 after 1 attempts.
FAILED: Error in acquiring locks: Locks on the underlying objects cannot be
acquired. retry after some time
Modified:
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_lock_db_in_use.q.out
URL:
http://svn.apache.org/viewvc/hive/trunk/ql/src/test/results/clientnegative/lockneg_try_lock_db_in_use.q.out?rev=1613530&r1=1613529&r2=1613530&view=diff
==============================================================================
---
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_lock_db_in_use.q.out
(original)
+++
hive/trunk/ql/src/test/results/clientnegative/lockneg_try_lock_db_in_use.q.out
Fri Jul 25 23:03:49 2014
@@ -38,5 +38,5 @@ POSTHOOK: type: SHOWLOCKS
lockneg2@tstsrcpart SHARED
PREHOOK: query: lock database lockneg2 exclusive
PREHOOK: type: LOCKDATABASE
-conflicting lock present for lockneg2 mode EXCLUSIVE
+Unable to acquire EXPLICIT, EXCLUSIVE lock lockneg2 after 1 attempts.
FAILED: Execution Error, return code 1 from
org.apache.hadoop.hive.ql.exec.DDLTask
