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 <[email protected]> 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 <[email protected]> Tested-by: Quanlong Huang <[email protected]> --- .../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()); + } } /**
