Quanlong Huang created IMPALA-13960:
---------------------------------------
Summary: Add catalog timeline item for prepareInsertEventData()
Key: IMPALA-13960
URL: https://issues.apache.org/jira/browse/IMPALA-13960
Project: IMPALA
Issue Type: Bug
Components: Catalog
Reporter: Quanlong Huang
Assignee: Quanlong Huang
After IMPALA-12443, we have catalog timeline in profiles for all DDL/DMLs. Here
is a timeline for a slow INSERT:
{noformat}
Catalog Server Operation
Got catalog version read lock: 2.35us (2352)
Got catalog version write lock and table write lock: 36.03us (36031)
Got Metastore client: 1ms (1671234)
Unset partition stats in Metastore: 148ms (148485023)
Got Metastore client: 19.9m (1193611314630) <---------- 1st
slowest, 19.9m. Actually in prepareInsertEventData()
Fired Metastore events: 19.9m (1193987278467)
Got Metastore client: 19.9m (1193987411141)
Fetched table from Metastore: 19.9m (1193992369196)
Start refreshing file metadata: 19.9m (1193998823165)
Loaded file metadata for 24 partitions: 23.2m (1390520901790) <--------
2nd slowest, 3.3m
Reloaded table metadata: 23.2m (1390522004615)
Finished updateCatalog request: 23.2m (1390522048075){noformat}
The first slowest point is "Got Metastore client: 19.9m". It seems getting a
HMS client took 19.9 minutes. However, it's just the duration between two
timeline items. So it means after "Unset partition stats in Metastore", we
spent 19.9m before we start firing the HMS INSERT events.
The catalogd logs show what happens during that time:
{noformat}
I0403 12:56:11.310474 1162572 JniUtil.java:166]
a2426d05d038f8f3:b9785d2100000000] updateCatalog request: Update catalog for
masked_tbl
I0403 12:56:11.459260 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202403/part=P
I0403 12:56:34.131578 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202408/part=P
I0403 12:57:01.882170 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202412/part=I
I0403 12:58:15.632098 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202408/part=I
I0403 12:59:42.968737 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202409/part=I
I0403 12:59:59.686712 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202404/part=I
I0403 13:00:11.229885 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202411/part=I
I0403 13:00:27.176134 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202407/part=P
I0403 13:00:33.649430 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202411/part=P
I0403 13:01:20.446049 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202409/part=P
I0403 13:05:25.102756 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202404/part=P
I0403 13:08:11.804157 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202407/part=I
I0403 13:09:59.541743 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202403/part=I
I0403 13:11:41.731952 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202412/part=P
I0403 13:14:08.321990 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202406/part=I
I0403 13:14:39.233712 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202401/part=P
I0403 13:14:53.318434 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202405/part=P
I0403 13:14:58.458074 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202402/part=I
I0403 13:15:05.593832 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202410/part=P
I0403 13:15:12.048745 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202405/part=I
I0403 13:15:23.656896 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202402/part=P
I0403 13:15:46.168848 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202410/part=I
I0403 13:15:54.583890 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202406/part=P
I0403 13:16:02.863479 1162572 CatalogOpExecutor.java:7222]
a2426d05d038f8f3:b9785d2100000000] 208 new files detected for table masked_tbl
partition month_id=202401/part=I
I0403 13:16:04.922019 1162572 MetastoreShim.java:470]
a2426d05d038f8f3:b9785d2100000000] Firing 24 insert event(s) for masked_tbl
I0403 13:16:05.297775 1162572 MetastoreShim.java:408]
a2426d05d038f8f3:b9785d2100000000] Time taken to fire insert events on table
masked_tbl: 375 msec
I0403 13:16:05.303035 1162572 HdfsTable.java:1271]
a2426d05d038f8f3:b9785d2100000000] Reloading metadata for 24 partition(s) of
masked_tbl (INSERT)
I0403 13:16:05.303103 1162572 HdfsTable.java:3085]
a2426d05d038f8f3:b9785d2100000000] Load Valid Write Id List Done. Time taken:
1.597us
I0403 13:16:05.312436 1162572 ParallelFileMetadataLoader.java:225]
a2426d05d038f8f3:b9785d2100000000] Refreshing file and block metadata for 24
paths for table masked_tbl using a thread pool of size 5
I0403 13:19:21.831636 1162572 HdfsTable.java:835]
a2426d05d038f8f3:b9785d2100000000] Loaded file and block metadata for
masked_tbl partitions: month_id=202403/part=P, month_id=202408/part=P,
month_id=202412/part=I, and 21 others. Time taken: 3m16s
I0403 13:19:21.831907 1162572 HdfsTable.java:1311]
a2426d05d038f8f3:b9785d2100000000] Incrementally loaded table metadata for:
masked_tbl
W0403 13:19:21.832484 1162572 HdfsTable.java:1340]
a2426d05d038f8f3:b9785d2100000000] Time taken on loading table masked_tbl
exceeded warning threshold. Time: 3m16s
W0403 13:19:21.832736 1162572 JniUtil.java:203]
a2426d05d038f8f3:b9785d2100000000] Response too slow: size=766 (766B),
duration=1390522ms (23m10s), method: updateCatalog
I0403 13:19:21.832770 1162572 JniUtil.java:177]
a2426d05d038f8f3:b9785d2100000000] Finished updateCatalog request: Update
catalog for masked_tbl. Time spent: 23m10s{noformat}
The log "N new files detected for table tbl partition part_name" comes from
prepareInsertEventData():
https://github.com/apache/impala/blob/047cf9ff4d3c68c32be0965fbc3cb0c245d3b3b1/fe/src/main/java/org/apache/impala/service/CatalogOpExecutor.java#L7757-L7759
It takes time to create the HMS INSERT events maybe due to fetching the
checksum of each new files from the storage here:
https://github.com/apache/impala/blob/047cf9ff4d3c68c32be0965fbc3cb0c245d3b3b1/fe/src/main/java/org/apache/impala/service/CatalogOpExecutor.java#L7823
Optimization for this will be done in another JIRA. This JIRA aims to add the
missing timeline item to show how long it takes to prepare data of the HMS
INSERT events.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
