diff --git a/fe/fe-core/src/main/java/org/apache/doris/catalog/Table.java b/fe/fe-core/src/main/java/org/apache/doris/catalog/Table.java index 6b5de7e581f8a90..1dc9b70fe1811cc 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/catalog/Table.java +++ b/fe/fe-core/src/main/java/org/apache/doris/catalog/Table.java @@ -19,6 +19,7 @@ import org.apache.doris.alter.AlterCancelException; import org.apache.doris.analysis.CreateTableStmt; +import org.apache.doris.common.Config; import org.apache.doris.common.DdlException; import org.apache.doris.common.MetaNotFoundException; import org.apache.doris.common.io.Text; @@ -73,6 +74,8 @@ public abstract class Table extends MetaObject implements Writable, TableIf { protected TableType type; protected long createTime; protected QueryableReentrantReadWriteLock rwLock; + private final ThreadLocal lockReadStart = new ThreadLocal<>(); + private long lockWriteStart; /* * fullSchema and nameToColumn should contains all columns, both visible and shadow. @@ -146,6 +149,7 @@ public void unmarkDropped() { public void readLock() { this.rwLock.readLock().lock(); + lockReadStart.set(System.currentTimeMillis()); } public boolean tryReadLock(long timeout, TimeUnit unit) { @@ -155,6 +159,9 @@ public boolean tryReadLock(long timeout, TimeUnit unit) { LOG.warn("Failed to try table {}'s read lock. timeout {} {}. Current owner: {}", name, timeout, unit.name(), rwLock.getOwner()); } + if (res) { + lockReadStart.set(System.currentTimeMillis()); + } return res; } catch (InterruptedException e) { LOG.warn("failed to try read lock at table[" + name + "]", e); @@ -163,11 +170,16 @@ public boolean tryReadLock(long timeout, TimeUnit unit) { } public void readUnlock() { + if (lockReadStart.get() != null) { + checkAndLogLockDuration("read", lockReadStart.get(), System.currentTimeMillis()); + lockReadStart.remove(); + } this.rwLock.readLock().unlock(); } public void writeLock() { this.rwLock.writeLock().lock(); + lockWriteStart = System.currentTimeMillis(); } public boolean writeLockIfExist() { @@ -176,9 +188,39 @@ public boolean writeLockIfExist() { this.rwLock.writeLock().unlock(); return false; } + lockWriteStart = System.currentTimeMillis(); return true; } + private void checkAndLogLockDuration(String type, long lockStart, long lockEnd) { + long duration = lockEnd - lockStart; + if (duration > Config.lock_reporting_threshold_ms) { + StringBuilder msgBuilder = new StringBuilder(); + msgBuilder.append(getId()) + .append(" ") + .append(getName()) + .append(" ") + .append(type) + .append(" lock is held at ") + .append(lockStart) + .append(".And release after ") + .append(duration) + .append(" ms.") + .append("Call stack is :\n") + .append(getStackTrace(Thread.currentThread())); + LOG.info(msgBuilder.toString()); + } + } + + private static String getStackTrace(Thread t) { + final StackTraceElement[] stackTrace = t.getStackTrace(); + StringBuilder msgBuilder = new StringBuilder(); + for (StackTraceElement e : stackTrace) { + msgBuilder.append(e.toString()).append("\n"); + } + return msgBuilder.toString(); + } + public boolean tryWriteLock(long timeout, TimeUnit unit) { try { boolean res = this.rwLock.writeLock().tryLock(timeout, unit); @@ -186,6 +228,9 @@ public boolean tryWriteLock(long timeout, TimeUnit unit) { LOG.warn("Failed to try table {}'s write lock. timeout {} {}. Current owner: {}", name, timeout, unit.name(), rwLock.getOwner()); } + if (res) { + lockWriteStart = System.currentTimeMillis(); + } return res; } catch (InterruptedException e) { LOG.warn("failed to try write lock at table[" + name + "]", e); @@ -194,6 +239,7 @@ public boolean tryWriteLock(long timeout, TimeUnit unit) { } public void writeUnlock() { + checkAndLogLockDuration("write", lockWriteStart, System.currentTimeMillis()); this.rwLock.writeLock().unlock(); } diff --git a/fe/fe-core/src/main/java/org/apache/doris/transaction/DatabaseTransactionMgr.java b/fe/fe-core/src/main/java/org/apache/doris/transaction/DatabaseTransactionMgr.java index cf4bed28e5bddd4..3bc676a1b422d86 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/transaction/DatabaseTransactionMgr.java +++ b/fe/fe-core/src/main/java/org/apache/doris/transaction/DatabaseTransactionMgr.java @@ -165,14 +165,20 @@ private enum PublishResult { private volatile long usedQuotaDataBytes = -1; private long lockWriteStart; + private final ThreadLocal lockReadStart = new ThreadLocal<>(); - private long lockReportingThresholdMs = Config.lock_reporting_threshold_ms; + private final long lockReportingThresholdMs = Config.lock_reporting_threshold_ms; protected void readLock() { this.transactionLock.readLock().lock(); + lockReadStart.set(System.currentTimeMillis()); } protected void readUnlock() { + if (lockReadStart.get() != null) { + checkAndLogLockDuration("read", lockReadStart.get(), System.currentTimeMillis()); + lockReadStart.remove(); + } this.transactionLock.readLock().unlock(); } @@ -182,7 +188,7 @@ protected void writeLock() { } protected void writeUnlock() { - checkAndLogWriteLockDuration(lockWriteStart, System.currentTimeMillis()); + checkAndLogLockDuration("write", lockWriteStart, System.currentTimeMillis()); this.transactionLock.writeLock().unlock(); } @@ -2211,11 +2217,12 @@ public long getTxnNumByStatus(TransactionStatus status) { * @param lockStart holing lock start time. * @param lockEnd release lock time. */ - private void checkAndLogWriteLockDuration(long lockStart, long lockEnd) { + private void checkAndLogLockDuration(String type, long lockStart, long lockEnd) { long duration = lockEnd - lockStart; if (duration > lockReportingThresholdMs) { StringBuilder msgBuilder = new StringBuilder(); - msgBuilder.append("lock is held at ") + msgBuilder.append(type) + .append(" lock is held at ") .append(lockStart) .append(".And release after ") .append(duration)