[impala] 02/02: IMPALA-11540: Add logs for ALTER_TABLE events that trigger slow metadata reload

[st...@apache.org]

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

commit 5aff120c40475de35bf45703b3cb953b9ab970f1
Author: stiga-huang <hu...@gmail.com>
AuthorDate: Mon Aug 29 08:14:37 2022 +0800

    IMPALA-11540: Add logs for ALTER_TABLE events that trigger slow metadata reload
    
    ALTER_TABLE event could trigger full refresh on the table, which is
    time consuming and can lead to event-processor lagging behind. We need
    logs to show the difference between the before and after hmsTables so we
    can further distinguish the cases that actully don't need a full table
    refresh, e.g. changing the owner, changing tblproperties, etc.
    
    Tests:
     - Attach the process using IntelliJ to pause the metadata loading for a
       while. So the metadata reloading of ALTER_TABLE event can exceed the
       threshold. Manually verified the logs.
    
    Change-Id: Ibf344e6b423f88c9635ca8d61d53385b88ba4dce
    Reviewed-on: http://gerrit.cloudera.org:8080/18926
    Reviewed-by: Impala Public Jenkins <im...@cloudera.com>
    Tested-by: Quanlong Huang <hu...@gmail.com>
---
 .../impala/catalog/events/MetastoreEvents.java       | 20 ++++++++++++++++++++
 1 file changed, 20 insertions(+)

diff --git a/fe/src/main/java/org/apache/impala/catalog/events/MetastoreEvents.java b/fe/src/main/java/org/apache/impala/catalog/events/MetastoreEvents.java
index 2c8e6c98d..4bfb2c8a4 100644
--- a/fe/src/main/java/org/apache/impala/catalog/events/MetastoreEvents.java
+++ b/fe/src/main/java/org/apache/impala/catalog/events/MetastoreEvents.java
@@ -64,6 +64,7 @@ import org.apache.impala.catalog.TableNotFoundException;
 import org.apache.impala.catalog.TableNotLoadedException;
 import org.apache.impala.catalog.TableWriteId;
 import org.apache.impala.common.Metrics;
+import org.apache.impala.common.PrintUtils;
 import org.apache.impala.common.Reference;
 import org.apache.impala.compat.MetastoreShim;
 import org.apache.impala.hive.common.MutableValidWriteIdList;
@@ -641,6 +642,17 @@ public class MetastoreEvents {
       LOG.trace(formatString, formatArgs);
     }
 
+    /**
+     * Similar to infoLog excepts logs at warn level
+     */
+    protected void warnLog(String logFormattedStr, Object... args) {
+      if (!LOG.isWarnEnabled()) return;
+      String formatString =
+          new StringBuilder(LOG_FORMAT_EVENT_ID_TYPE).append(logFormattedStr).toString();
+      Object[] formatArgs = getLogFormatArgs(args);
+      LOG.warn(formatString, formatArgs);
+    }
+
     /**
      * Search for a inverse event (for example drop_table is a inverse event for
      * create_table) for this event from a given list of notificationEvents starting for
@@ -1432,6 +1444,7 @@ public class MetastoreEvents {
       // refresh  eg. this could be due to as simple as adding a new parameter or a
       // full blown adding or changing column type
       // rename is already handled above
+      long startNs = System.nanoTime();
       if (!reloadTableFromCatalog("ALTER_TABLE", false)) {
         if (wasEventSyncTurnedOn()) {
           // we received this alter table event on a non-existing table. We also
@@ -1448,6 +1461,13 @@ public class MetastoreEvents {
                   + "the event processing state", getFullyQualifiedTblName()));
         }
       }
+      long durationNs = System.nanoTime() - startNs;
+      // Log event details for those triggered slow reload.
+      if (durationNs > HdfsTable.LOADING_WARNING_TIME_NS) {
+        warnLog("Slow event processing. Duration: {}. TableBefore: {}. " +
+            "TableAfter: {}", PrintUtils.printTimeNs(durationNs),
+            tableBefore_.toString(), tableAfter_.toString());
+      }
     }
 
     /**