commit d7b5819f906c19281fdf9594ecf4616f6c9f92a0
author stiga-huang <huangquanlong@gmail.com> Wed Aug 30 18:47:55 2023 +0800
committer Impala Public Jenkins <impala-public-jenkins@cloudera.com> Thu Mar 21 16:04:14 2024 +0000
tree a650bb1cbc56d734730e7d0047fe8e1ac05055ad
parent 1e67480ba6cd4a6f01b369eb11cc2b7330554bde

IMPALA-12443: Add catalog timeline for all DDL profiles

This is a follow-up work of IMPALA-12024 where we add the catalog
timeline for CreateTable statements. Using the same mechanism, this
patch adds catalog timeline for all DDL/DML profiles, including
REFRESH and INSERT.

The goal is to add timeline markers after each step that could be
blocked, e.g. acquiring locks, external RPCs. So we can better debug
slow DDLs with the catalog timeline in profiles.

Tried to add some constant strings for widely used events, e.g. "Fetched
table from Metastore". Didn't do so for events that only occurs once.

Most of the catalog methods now have a new argument for tracking the
execution timeline. To avoid adding null checks everywhere, for code
paths that don't need a catalog profile, e.g. EventProcessor, uses a
static noop EventSequence as the argument. We can replace it in future
works, e.g. expose execution timeline of a slow processing on an HMS
event.

This patch also removes some unused overloads of HdfsTable#load() and
HdfsTable#reloadPartitionsFromNames().

Example timeline for a REFRESH statement on an unloaded table
(IncompleteTable):
Catalog Server Operation: 2s300ms
   - Got catalog version read lock: 26.407us (26.407us)
   - Start loading table: 314.663us (288.256us)
   - Got Metastore client: 629.599us (314.936us)
   - Fetched table from Metastore: 7.248ms (6.618ms)
   - Loaded table schema: 27.947ms (20.699ms)
   - Preloaded permissions cache for 1824 partitions: 1s514ms (1s486ms)
   - Got access level: 1s514ms (588.314us)
   - Created partition builders: 2s103ms (588.270ms)
   - Start loading file metadata: 2s103ms (49.760us)
   - Loaded file metadata for 1824 partitions: 2s282ms (179.839ms)
   - Async loaded table: 2s289ms (6.931ms)
   - Loaded table from scratch: 2s289ms (72.038us)
   - Got table read lock: 2s289ms (2.289us)
   - Finished resetMetadata request: 2s300ms (10.188ms)

Example timeline for an INSERT statement:
Catalog Server Operation: 178.120ms
   - Got catalog version read lock: 4.238us (4.238us)
   - Got catalog version write lock and table write lock: 52.768us (48.530us)
   - Got Metastore client: 15.768ms (15.715ms)
   - Fired Metastore events: 156.650ms (140.882ms)
   - Got Metastore client: 163.317ms (6.666ms)
   - Fetched table from Metastore: 166.561ms (3.244ms)
   - Start refreshing file metadata: 167.961ms (1.399ms)
   - Loaded file metadata for 24 partitions: 177.679ms (9.717ms)
   - Reloaded table metadata: 178.021ms (342.261us)
   - Finished updateCatalog request: 178.120ms (98.929us)

Example timeline for a "COMPUTE STATS tpcds_parquet.store_sales":
Catalog Server Operation: 6s737ms
   - Got catalog version read lock: 19.971us (19.971us)
   - Got catalog version write lock and table write lock: 50.255us (30.284us)
   - Got Metastore client: 171.819us (121.564us)
   - Updated column stats: 25.560ms (25.388ms)
   - Got Metastore client: 69.298ms (43.738ms)
   - Altered 500 partitions in Metastore: 1s894ms (1s825ms)
   - Altered 1000 partitions in Metastore: 3s558ms (1s664ms)
   - Altered 1500 partitions in Metastore: 5s144ms (1s586ms)
   - Altered 1824 partitions in Metastore: 6s205ms (1s060ms)
   - Got Metastore client: 6s205ms (329.481us)
   - Altered table in Metastore: 6s216ms (11.073ms)
   - Got Metastore client: 6s216ms (13.377us)
   - Fetched table from Metastore: 6s219ms (2.419ms)
   - Loaded table schema: 6s223ms (4.130ms)
   - Got current Metastore event id 19017: 6s639ms (415.690ms)
   - Start loading file metadata: 6s639ms (9.591us)
   - Loaded file metadata for 1824 partitions: 6s729ms (90.196ms)
   - Reloaded table metadata: 6s735ms (5.865ms)
   - DDL finished: 6s737ms (2.255ms)

Example timeline for a global INVALIDATE METADATA:
Catalog Server Operation: 301.618ms
   - Got catalog version write lock: 9.908ms (9.908ms)
   - Got Metastore client: 9.922ms (14.013us)
   - Got database list: 11.396ms (1.473ms)
   - Loaded functions of default: 44.919ms (33.523ms)
   - Loaded TableMeta of 82 tables in database default: 47.524ms (2.604ms)
   - Loaded functions of functional: 50.846ms (3.321ms)
   - Loaded TableMeta of 101 tables in database functional: 52.580ms (1.734ms)
   - Loaded functions of functional_avro: 54.861ms (2.281ms)
   - Loaded TableMeta of 35 tables in database functional_avro: 55.789ms (928.120us)
   ...
   - Loaded functions of tpch_text_gzip: 299.503ms (1.710ms)
   - Loaded TableMeta of 8 tables in database tpch_text_gzip: 300.288ms (784.725us)
   - Updated catalog cache: 300.366ms (78.045us)
   - Finished resetMetadata request: 301.618ms (1.251ms)

Tests:
 - Add e2e test to verify the catalog timeline in some DDLs.
 - Ran CORE tests

Change-Id: Ifbceefaeb24c66eb1a064c449d6f56077ea347c5
Reviewed-on: http://gerrit.cloudera.org:8080/20491
Reviewed-by: Impala Public Jenkins <impala-public-jenkins@cloudera.com>
Tested-by: Impala Public Jenkins <impala-public-jenkins@cloudera.com>