IMPALA-4768: Improve logging of table loading. - Improves the logging for several important events, in particular, during table loading. - Uses LOG.info() for such messages to clarify their intent.
The goal is to improve supportability without having to turn on trace debugging which can generate a significant log volume. Change-Id: I8de96d0cb6d09b2272b1925d42cb059367fe7196 Reviewed-on: http://gerrit.cloudera.org:8080/5709 Reviewed-by: Alex Behm <[email protected]> Tested-by: Impala Public Jenkins Project: http://git-wip-us.apache.org/repos/asf/incubator-impala/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-impala/commit/3b7a1791 Tree: http://git-wip-us.apache.org/repos/asf/incubator-impala/tree/3b7a1791 Diff: http://git-wip-us.apache.org/repos/asf/incubator-impala/diff/3b7a1791 Branch: refs/heads/master Commit: 3b7a179197bccdebf9c8492477f0cf88c6df0e18 Parents: fa4a054 Author: Alex Behm <[email protected]> Authored: Thu Jan 12 16:54:31 2017 -0800 Committer: Impala Public Jenkins <[email protected]> Committed: Tue Jan 17 02:25:11 2017 +0000 ---------------------------------------------------------------------- .../impala/catalog/CatalogServiceCatalog.java | 37 +++++++++----------- .../org/apache/impala/catalog/HdfsTable.java | 27 +++++++------- .../org/apache/impala/catalog/TableLoader.java | 5 +-- .../impala/service/CatalogOpExecutor.java | 2 +- .../org/apache/impala/service/Frontend.java | 7 ++-- 5 files changed, 39 insertions(+), 39 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3b7a1791/fe/src/main/java/org/apache/impala/catalog/CatalogServiceCatalog.java ---------------------------------------------------------------------- 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 b51c9aa..31001a2 100644 --- a/fe/src/main/java/org/apache/impala/catalog/CatalogServiceCatalog.java +++ b/fe/src/main/java/org/apache/impala/catalog/CatalogServiceCatalog.java @@ -194,9 +194,8 @@ public class CatalogServiceCatalog extends Catalog { } public void run() { - if (LOG.isTraceEnabled()) { - LOG.trace("Reloading cache pool names from HDFS"); - } + if (LOG.isTraceEnabled()) LOG.trace("Reloading cache pool names from HDFS"); + // Map of cache pool name to CachePoolInfo. Stored in a map to allow Set operations // to be performed on the keys. Map<String, CachePoolInfo> currentCachePools = Maps.newHashMap(); @@ -523,9 +522,7 @@ public class CatalogServiceCatalog extends Catalog { private void loadFunctionsFromDbParams(Db db, org.apache.hadoop.hive.metastore.api.Database msDb) { if (msDb == null || msDb.getParameters() == null) return; - if (LOG.isTraceEnabled()) { - LOG.trace("Loading native functions for database: " + db.getName()); - } + LOG.info("Loading native functions for database: " + db.getName()); TCompactProtocol.Factory protocolFactory = new TCompactProtocol.Factory(); for (String key: msDb.getParameters().keySet()) { if (!key.startsWith(Db.FUNCTION_INDEX_PREFIX)) continue; @@ -541,6 +538,7 @@ public class CatalogServiceCatalog extends Catalog { + ",continuing", e); } } + LOG.info("Loaded native functions for database: " + db.getName()); } /** @@ -551,9 +549,7 @@ public class CatalogServiceCatalog extends Catalog { private void loadJavaFunctions(Db db, List<org.apache.hadoop.hive.metastore.api.Function> functions) { Preconditions.checkNotNull(functions); - if (LOG.isTraceEnabled()) { - LOG.trace("Loading Java functions for database: " + db.getName()); - } + LOG.info("Loading Java functions for database: " + db.getName()); for (org.apache.hadoop.hive.metastore.api.Function function: functions) { try { for (Function fn: extractFunctions(db.getName(), function)) { @@ -564,6 +560,7 @@ public class CatalogServiceCatalog extends Catalog { LOG.error("Skipping function load: " + function.getFunctionName(), e); } } + LOG.info("Loaded Java functions for database: " + db.getName()); } /** @@ -622,6 +619,8 @@ public class CatalogServiceCatalog extends Catalog { * Resets this catalog instance by clearing all cached table and database metadata. */ public void reset() throws CatalogException { + LOG.info("Invalidating all metadata."); + // First update the policy metadata. if (sentryProxy_ != null) { // Sentry Service is enabled. @@ -665,6 +664,7 @@ public class CatalogServiceCatalog extends Catalog { } finally { catalogLock_.writeLock().unlock(); } + LOG.info("Invalidated all metadata."); } /** @@ -893,9 +893,7 @@ public class CatalogServiceCatalog extends Catalog { * Throws a CatalogException if there is an error loading table metadata. */ public Table reloadTable(Table tbl) throws CatalogException { - if (LOG.isTraceEnabled()) { - LOG.trace(String.format("Refreshing table metadata: %s", tbl.getFullName())); - } + LOG.info(String.format("Refreshing table metadata: %s", tbl.getFullName())); TTableName tblName = new TTableName(tbl.getDb().getName().toLowerCase(), tbl.getName().toLowerCase()); Db db = tbl.getDb(); @@ -917,6 +915,7 @@ public class CatalogServiceCatalog extends Catalog { return replaceTableIfUnchanged(loadReq.get(), previousCatalogVersion); } finally { loadReq.close(); + LOG.info(String.format("Refreshed table metadata: %s", tbl.getFullName())); } } @@ -936,6 +935,7 @@ public class CatalogServiceCatalog extends Catalog { tbl.load(false, msClient.getHiveClient(), msTbl); } tbl.setCatalogVersion(newCatalogVersion); + LOG.info(String.format("Refreshed table metadata: %s", tbl.getFullName())); return tbl; } } @@ -1024,12 +1024,9 @@ public class CatalogServiceCatalog extends Catalog { Preconditions.checkNotNull(updatedObjects); updatedObjects.first = null; updatedObjects.second = null; - if (LOG.isTraceEnabled()) { - LOG.trace(String.format("Invalidating table metadata: %s.%s", - tableName.getDb_name(), tableName.getTable_name())); - } String dbName = tableName.getDb_name(); String tblName = tableName.getTable_name(); + LOG.info(String.format("Invalidating table metadata: %s.%s", dbName, tblName)); // Stores whether the table exists in the metastore. Can have three states: // 1) true - Table exists in metastore. @@ -1266,10 +1263,8 @@ public class CatalogServiceCatalog extends Catalog { String partitionName = hdfsPartition == null ? HdfsTable.constructPartitionName(partitionSpec) : hdfsPartition.getPartitionName(); - if (LOG.isTraceEnabled()) { - LOG.trace(String.format("Refreshing Partition metadata: %s %s", - hdfsTable.getFullName(), partitionName)); - } + LOG.info(String.format("Refreshing partition metadata: %s %s", + hdfsTable.getFullName(), partitionName)); try (MetaStoreClient msClient = getMetaStoreClient()) { org.apache.hadoop.hive.metastore.api.Partition hmsPartition = null; try { @@ -1290,6 +1285,8 @@ public class CatalogServiceCatalog extends Catalog { hdfsTable.reloadPartition(hdfsPartition, hmsPartition); } hdfsTable.setCatalogVersion(newCatalogVersion); + LOG.info(String.format("Refreshed partition metadata: %s %s", + hdfsTable.getFullName(), partitionName)); return hdfsTable; } } http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3b7a1791/fe/src/main/java/org/apache/impala/catalog/HdfsTable.java ---------------------------------------------------------------------- diff --git a/fe/src/main/java/org/apache/impala/catalog/HdfsTable.java b/fe/src/main/java/org/apache/impala/catalog/HdfsTable.java index 8fa4f21..857216f 100644 --- a/fe/src/main/java/org/apache/impala/catalog/HdfsTable.java +++ b/fe/src/main/java/org/apache/impala/catalog/HdfsTable.java @@ -272,6 +272,7 @@ public class HdfsTable extends Table { synthesizeBlockMetadata(fs, dirPath, partsByPath); return; } + int unknownDiskIdCount = 0; RemoteIterator<LocatedFileStatus> fileStatusIter = fs.listFiles(dirPath, true); while (fileStatusIter.hasNext()) { @@ -728,7 +729,7 @@ public class HdfsTable extends Table { } } } - if (LOG.isTraceEnabled()) LOG.trace("partsByPath size: " + partsByPath.size()); + loadMetadataAndDiskIds(dirsToLoad, partsByPath); } @@ -746,8 +747,13 @@ public class HdfsTable extends Table { */ private void loadMetadataAndDiskIds(List<Path> locations, HashMap<Path, List<HdfsPartition>> partsByPath) { + LOG.info(String.format("Loading file and block metadata for %s partitions: %s", + partsByPath.size(), getFullName())); for (Path location: locations) { loadBlockMetadata(location, partsByPath); } + LOG.info(String.format("Loaded file and block metadata for %s partitions: %s", + partsByPath.size(), getFullName())); } + /** * Gets the AccessLevel that is available for Impala for this table based on the * permissions Impala has on the given path. If the path does not exist, recurses up @@ -1029,9 +1035,7 @@ public class HdfsTable extends Table { // Load partition and file metadata if (reuseMetadata) { // Incrementally update this table's partitions and file metadata - if (LOG.isTraceEnabled()) { - LOG.trace("incremental update for table: " + db_.getName() + "." + name_); - } + LOG.info("Incrementally loading table metadata for: " + getFullName()); Preconditions.checkState(partitionsToUpdate == null || loadFileMetadata); updateMdFromHmsTable(msTbl); if (msTbl.getPartitionKeysSize() == 0) { @@ -1039,15 +1043,14 @@ public class HdfsTable extends Table { } else { updatePartitionsFromHms(client, partitionsToUpdate, loadFileMetadata); } + LOG.info("Incrementally loaded table metadata for: " + getFullName()); } else { // Load all partitions from Hive Metastore, including file metadata. - if (LOG.isTraceEnabled()) { - LOG.trace("load table from Hive Metastore: " + db_.getName() + "." + name_); - } + LOG.info("Fetching partition metadata from the Metastore: " + getFullName()); List<org.apache.hadoop.hive.metastore.api.Partition> msPartitions = - Lists.newArrayList(); - msPartitions.addAll(MetaStoreUtil.fetchAllPartitions( - client, db_.getName(), name_, NUM_PARTITION_FETCH_RETRIES)); + MetaStoreUtil.fetchAllPartitions( + client, db_.getName(), name_, NUM_PARTITION_FETCH_RETRIES); + LOG.info("Fetched partition metadata from the Metastore: " + getFullName()); loadAllPartitions(msPartitions, msTbl); } if (loadTableSchema) setAvroSchema(client, msTbl); @@ -1107,9 +1110,7 @@ public class HdfsTable extends Table { */ private void updatePartitionsFromHms(IMetaStoreClient client, Set<String> partitionsToUpdate, boolean loadFileMetadata) throws Exception { - if (LOG.isTraceEnabled()) { - LOG.trace("sync table partitions: " + name_); - } + if (LOG.isTraceEnabled()) LOG.trace("Sync table partitions: " + name_); org.apache.hadoop.hive.metastore.api.Table msTbl = getMetaStoreTable(); Preconditions.checkNotNull(msTbl); Preconditions.checkState(msTbl.getPartitionKeysSize() != 0); http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3b7a1791/fe/src/main/java/org/apache/impala/catalog/TableLoader.java ---------------------------------------------------------------------- diff --git a/fe/src/main/java/org/apache/impala/catalog/TableLoader.java b/fe/src/main/java/org/apache/impala/catalog/TableLoader.java index 7f17a5c..2a1ee15 100644 --- a/fe/src/main/java/org/apache/impala/catalog/TableLoader.java +++ b/fe/src/main/java/org/apache/impala/catalog/TableLoader.java @@ -55,7 +55,7 @@ public class TableLoader { */ public Table load(Db db, String tblName) { String fullTblName = db.getName() + "." + tblName; - if (LOG.isTraceEnabled()) LOG.trace("Loading metadata for: " + fullTblName); + LOG.info("Loading metadata for: " + fullTblName); Table table; // turn all exceptions into TableLoadingException try (MetaStoreClient msClient = catalog_.getMetaStoreClient()) { @@ -88,12 +88,13 @@ public class TableLoader { "catalog."); table = IncompleteTable.createFailedMetadataLoadTable( db, tblName, tableDoesNotExist); - } catch (Exception e) { + } catch (Throwable e) { table = IncompleteTable.createFailedMetadataLoadTable( db, tblName, new TableLoadingException( "Failed to load metadata for table: " + fullTblName + ". Running " + "'invalidate metadata " + fullTblName + "' may resolve this problem.", e)); } + LOG.info("Loaded metadata for: " + fullTblName); return table; } } http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3b7a1791/fe/src/main/java/org/apache/impala/service/CatalogOpExecutor.java ---------------------------------------------------------------------- diff --git a/fe/src/main/java/org/apache/impala/service/CatalogOpExecutor.java b/fe/src/main/java/org/apache/impala/service/CatalogOpExecutor.java index d9448b3..208ff2b 100644 --- a/fe/src/main/java/org/apache/impala/service/CatalogOpExecutor.java +++ b/fe/src/main/java/org/apache/impala/service/CatalogOpExecutor.java @@ -559,7 +559,7 @@ public class CatalogOpExecutor { /** * Loads the metadata of a table 'tbl' and assigns a new catalog version. - * reloadFileMetadata', 'reloadTableSchema', and 'partitionsToUpdate' + * 'reloadFileMetadata', 'reloadTableSchema', and 'partitionsToUpdate' * are used only for HdfsTables and control which metadata to reload. * Throws a CatalogException if there is an error loading table metadata. */ http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3b7a1791/fe/src/main/java/org/apache/impala/service/Frontend.java ---------------------------------------------------------------------- diff --git a/fe/src/main/java/org/apache/impala/service/Frontend.java b/fe/src/main/java/org/apache/impala/service/Frontend.java index eca8d65..1030111 100644 --- a/fe/src/main/java/org/apache/impala/service/Frontend.java +++ b/fe/src/main/java/org/apache/impala/service/Frontend.java @@ -887,7 +887,7 @@ public class Frontend { AnalysisContext analysisCtx = new AnalysisContext(impaladCatalog_, queryCtx, authzConfig_); - if (LOG.isTraceEnabled()) LOG.trace("analyze query " + queryCtx.client_request.stmt); + LOG.info("Compiling query: " + queryCtx.client_request.stmt); // Run analysis in a loop until it any of the following events occur: // 1) Analysis completes successfully. @@ -909,8 +909,8 @@ public class Frontend { // Some tables/views were missing, request and wait for them to load. if (!requestTblLoadAndWait(missingTbls, MISSING_TBL_LOAD_WAIT_TIMEOUT_MS)) { - if (LOG.isTraceEnabled()) { - LOG.trace(String.format("Missing tables were not received in %dms. Load " + + if (LOG.isWarnEnabled()) { + LOG.warn(String.format("Missing tables were not received in %dms. Load " + "request will be retried.", MISSING_TBL_LOAD_WAIT_TIMEOUT_MS)); } analysisCtx.getTimeline().markEvent("Metadata load timeout"); @@ -924,6 +924,7 @@ public class Frontend { // AuthorizationExceptions must take precedence over any AnalysisException // that has been thrown, so perform the authorization first. analysisCtx.authorize(getAuthzChecker()); + LOG.info("Compiled query."); } }
