(impala) branch master updated: IMPALA-12529: Show logs for the time of acquiring table/db locks

[stigahuang]

This is an automated email from the ASF dual-hosted git repository.

stigahuang pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/impala.git


The following commit(s) were added to refs/heads/master by this push:
     new 543bcf42c IMPALA-12529: Show logs for the time of acquiring table/db 
locks
543bcf42c is described below

commit 543bcf42c0fa3ee8c29c59752ef4063e1870c10f
Author: stiga-huang <huangquanl...@gmail.com>
AuthorDate: Mon Oct 30 22:38:21 2023 +0800

    IMPALA-12529: Show logs for the time of acquiring table/db locks
    
    Waiting for table locks could take long when there are lots of
    concurrent catalog operations, e.g. DDL/DMLs or HMS events processing,
    on the same table. It'd be helpful to show the time of acquiring table
    locks in logs for better diagnostics.
    
    We already have TRACE level logs for acquiring the table/db locks. This
    changes them to WARN level when the duration exceeds a threshold
    (100ms).
    
    Ran a GVO without the threshold and found most of the duration are under
    100ms. The majority is 0ms. So choose 100ms to just show abnormal
    locking.
    
    Change-Id: I99d0665a5ab815a81a5341f63aff1ac2f9a447d5
    Reviewed-on: http://gerrit.cloudera.org:8080/20643
    Reviewed-by: Impala Public Jenkins <impala-public-jenk...@cloudera.com>
    Tested-by: Impala Public Jenkins <impala-public-jenk...@cloudera.com>
---
 .../apache/impala/catalog/CatalogServiceCatalog.java   | 18 ++++++++++--------
 1 file changed, 10 insertions(+), 8 deletions(-)

diff --git 
a/fe/src/main/java/org/apache/impala/catalog/CatalogServiceCatalog.java 
b/fe/src/main/java/org/apache/impala/catalog/CatalogServiceCatalog.java
index fad2f5035..12cbd7b87 100644
--- a/fe/src/main/java/org/apache/impala/catalog/CatalogServiceCatalog.java
+++ b/fe/src/main/java/org/apache/impala/catalog/CatalogServiceCatalog.java
@@ -237,6 +237,8 @@ public class CatalogServiceCatalog extends Catalog {
   public static final long LOCK_RETRY_TIMEOUT_MS = 7200000;
   // Time to sleep before retrying to acquire a table lock
   private static final int LOCK_RETRY_DELAY_MS = 10;
+  // Threshold to add warning logs for slow lock acquiring.
+  private static final long LOCK_ACQUIRING_DURATION_WARN_MS = 100;
   // default value of table id in the GetPartialCatalogObjectRequest
   public static final long TABLE_ID_UNAVAILABLE = -1;
 
@@ -525,10 +527,10 @@ public class CatalogServiceCatalog extends Catalog {
           //cannot be acquired. Holding version lock can potentially blocks 
other
           //unrelated DDL operations.
           if (lock.tryLock(0, TimeUnit.SECONDS)) {
-            if (LOG.isTraceEnabled()) {
-              end = System.currentTimeMillis();
-              LOG.trace(String.format("Lock for table %s was acquired in %d 
msec",
-                  tbl.getFullName(), end - begin));
+            long duration = System.currentTimeMillis() - begin;
+            if (duration > LOCK_ACQUIRING_DURATION_WARN_MS) {
+              LOG.warn("{} lock for table {} was acquired in {} msec",
+                  useWriteLock ? "Write" : "Read", tbl.getFullName(), 
duration);
             }
             return true;
           }
@@ -557,10 +559,10 @@ public class CatalogServiceCatalog extends Catalog {
       do {
         versionLock_.writeLock().lock();
         if (db.getLock().tryLock()) {
-          if (LOG.isTraceEnabled()) {
-            end = System.currentTimeMillis();
-            LOG.trace(String.format("Lock for db %s was acquired in %d msec",
-                db.getName(), end - begin));
+          long duration = System.currentTimeMillis() - begin;
+          if (duration > LOCK_ACQUIRING_DURATION_WARN_MS) {
+            LOG.warn("Lock for db {} was acquired in {} msec",
+                db.getName(), duration);
           }
           return true;
         }