From 8dbc8b733d3712035f8615f477f74c66ec9d63ea Mon Sep 17 00:00:00 2001 From: stiga-huang Date: Mon, 5 Dec 2022 17:01:57 +0800 Subject: [PATCH] IMPALA-11756: Add error messages and debug logs in CatalogdMetaProviderTest and PartialCatalogInfoWriteIdTest We saw several test failures on collecting file metadata after minor compaction in Hive. However, I can't reproduce the failure by running the tests around 100 times. To ease our debug, this patch adds error messages to print the actual file paths. Also adds more logs to locate the time range when the test runs. Tests: - Ran CatalogdMetaProviderTest and PartialCatalogInfoWriteIdTest locally. Verified the new logs exist. - Modified the expected value to fail the tests. Verified the error messages work as expected. Change-Id: I806cc35da5a758215b8dc6cc2df86a7a968301da Reviewed-on: http://gerrit.cloudera.org:8080/19319 Reviewed-by: Impala Public Jenkins Tested-by: Impala Public Jenkins --- .../PartialCatalogInfoWriteIdTest.java | 23 ++++++++++++++++++- .../local/CatalogdMetaProviderTest.java | 20 +++++++++++++--- .../impala/testutil/HiveJdbcClientPool.java | 4 ++-- 3 files changed, 41 insertions(+), 6 deletions(-) diff --git a/fe/src/test/java/org/apache/impala/catalog/PartialCatalogInfoWriteIdTest.java b/fe/src/test/java/org/apache/impala/catalog/PartialCatalogInfoWriteIdTest.java index 059da84056..9e332052dc 100644 --- a/fe/src/test/java/org/apache/impala/catalog/PartialCatalogInfoWriteIdTest.java +++ b/fe/src/test/java/org/apache/impala/catalog/PartialCatalogInfoWriteIdTest.java @@ -20,6 +20,8 @@ import java.sql.SQLException; import java.util.List; import java.util.concurrent.TimeUnit; +import java.util.stream.Collectors; + import org.apache.hadoop.hive.common.ValidWriteIdList; import org.apache.impala.catalog.MetaStoreClientPool.MetaStoreClient; import org.apache.impala.common.InternalException; @@ -50,7 +52,9 @@ import org.junit.Assume; import org.junit.Before; import org.junit.BeforeClass; +import org.junit.Rule; import org.junit.Test; +import org.junit.rules.TestName; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -76,6 +80,9 @@ public class PartialCatalogInfoWriteIdTest { private static final String testPartitionedTbl = "insert_only_partitioned"; private static final String testAcidTblName = "test_full_acid"; + @Rule + public TestName name = new TestName(); + @BeforeClass public static void setupTestEnv() throws SQLException, ClassNotFoundException { catalog_ = CatalogServiceTestCatalog.create(); @@ -94,6 +101,7 @@ public static void shutdown() { @Before public void createTestTbls() throws Exception { + LOG.info("Creating test tables for {}", name.getMethodName()); Stopwatch st = Stopwatch.createStarted(); ImpalaJdbcClient client = ImpalaJdbcClient .createClientUsingHiveJdbcDriver(); @@ -602,7 +610,13 @@ private void testFileMetadataAfterCompaction(String tableName, String partition, int afterFileCount = afterPartitionInfo.getFile_descriptorsSize() + afterPartitionInfo.getInsert_file_descriptorsSize() + afterPartitionInfo.getDelete_file_descriptorsSize(); - Assert.assertEquals(expectedFileCount, afterFileCount); + String message = "Actual file_descriptors:\n" + + getPathsFromFileDescriptors(afterPartitionInfo.getFile_descriptors()) + + "\nActual insert_file_descriptors:\n" + + getPathsFromFileDescriptors(afterPartitionInfo.getInsert_file_descriptors()) + + "\nActual delete_file_descriptors:\n" + + getPathsFromFileDescriptors(afterPartitionInfo.getDelete_file_descriptors()); + Assert.assertEquals(message, expectedFileCount, afterFileCount); long numMissesAfterMinor = getMetricCount(testDbName, tableName, HdfsTable.FILEMETADATA_CACHE_MISS_METRIC); long numHitsAfterMinor = @@ -611,6 +625,13 @@ private void testFileMetadataAfterCompaction(String tableName, String partition, Assert.assertEquals(numMisses, numMissesAfterMinor); } + private List getPathsFromFileDescriptors(List fileDescriptors) { + return fileDescriptors.stream() + .map(HdfsPartition.FileDescriptor::fromThrift) + .map(HdfsPartition.FileDescriptor::getPath) + .collect(Collectors.toList()); + } + /** * This test make sure that the table returned is consistent with given writeId list * even if the table was dropped and recreated from outside. diff --git a/fe/src/test/java/org/apache/impala/catalog/local/CatalogdMetaProviderTest.java b/fe/src/test/java/org/apache/impala/catalog/local/CatalogdMetaProviderTest.java index 47c00f8cfd..7eb6f1fbfc 100644 --- a/fe/src/test/java/org/apache/impala/catalog/local/CatalogdMetaProviderTest.java +++ b/fe/src/test/java/org/apache/impala/catalog/local/CatalogdMetaProviderTest.java @@ -20,6 +20,7 @@ import static org.junit.Assert.*; import java.util.ArrayList; +import java.util.Collection; import java.util.List; import java.util.Map; import java.util.concurrent.ExecutorService; @@ -27,10 +28,12 @@ import java.util.concurrent.Future; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; +import java.util.stream.Collectors; import org.apache.hadoop.hive.metastore.api.ColumnStatisticsObj; import org.apache.hadoop.hive.metastore.api.Database; import org.apache.hadoop.hive.metastore.api.Table; +import org.apache.impala.catalog.HdfsPartition; import org.apache.impala.catalog.local.CatalogdMetaProvider.SizeOfWeigher; import org.apache.impala.catalog.local.MetaProvider.PartitionMetadata; import org.apache.impala.catalog.local.MetaProvider.PartitionRef; @@ -55,7 +58,9 @@ import org.apache.impala.thrift.TTable; import org.apache.impala.util.ListMap; import org.junit.Assume; +import org.junit.Rule; import org.junit.Test; +import org.junit.rules.TestName; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -75,6 +80,8 @@ public class CatalogdMetaProviderTest { private final TableMetaRef tableRef_; private CacheStats prevStats_; + @Rule + public TestName name = new TestName(); private static HiveJdbcClientPool hiveJdbcClientPool_; private static final String testDbName_ = "catalogd_meta_provider_test"; @@ -107,6 +114,8 @@ private CacheStats diffStats() { } private void createTestTbls() throws Exception { + LOG.info("Creating test tables for {}", name.getMethodName()); + Stopwatch st = Stopwatch.createStarted(); ImpalaJdbcClient client = ImpalaJdbcClient.createClientUsingHiveJdbcDriver(); client.connect(); try { @@ -122,6 +131,8 @@ private void createTestTbls() throws Exception { + " (c1 int) partitioned by (part int) stored as orc " + "tblproperties ('transactional'='true')"); } finally { + LOG.info("Time taken for createTestTbls {} msec", + st.stop().elapsed(TimeUnit.MILLISECONDS)); client.close(); } } @@ -622,9 +633,12 @@ private void testFileMetadataAfterCompaction(String dbName, String tableName, Map counters = Maps.uniqueIndex(prof.counters, TCounter::getName); assertEquals(1, counters.get("CatalogFetch.Partitions.Requests").getValue()); assertEquals(1, counters.get("CatalogFetch.Partitions.Misses").getValue()); - int afterFileCount = partMap.values().stream() - .map(PartitionMetadata::getFileDescriptors).mapToInt(List::size).sum(); - assertEquals(1, afterFileCount); + List paths = partMap.values().stream() + .map(PartitionMetadata::getFileDescriptors) + .flatMap(Collection::stream) + .map(HdfsPartition.FileDescriptor::getPath) + .collect(Collectors.toList()); + assertEquals("Actual paths: " + paths, 1, paths.size()); } } } diff --git a/fe/src/test/java/org/apache/impala/testutil/HiveJdbcClientPool.java b/fe/src/test/java/org/apache/impala/testutil/HiveJdbcClientPool.java index c83ca8b466..ff22a88875 100644 --- a/fe/src/test/java/org/apache/impala/testutil/HiveJdbcClientPool.java +++ b/fe/src/test/java/org/apache/impala/testutil/HiveJdbcClientPool.java @@ -90,7 +90,7 @@ private void validateConnection() throws SQLException { */ public ResultSet execQuery(String query) throws SQLException { validateConnection(); - LOG.debug("Executing: " + query); + LOG.info("Executing: " + query); return stmt_.executeQuery(query); } @@ -99,7 +99,7 @@ public ResultSet execQuery(String query) throws SQLException { */ public boolean executeSql(String sql) throws SQLException { validateConnection(); - LOG.debug("Executing sql : " + sql); + LOG.info("Executing sql : " + sql); return stmt_.execute(sql); } }