[
https://issues.apache.org/jira/browse/IMPALA-13960?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Quanlong Huang resolved IMPALA-13960.
-------------------------------------
Fix Version/s: Impala 5.0.0
Resolution: Fixed
> 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
> Priority: Major
> Fix For: Impala 5.0.0
>
>
> 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)
