[
https://issues.apache.org/jira/browse/IMPALA-13960?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17944794#comment-17944794
]
ASF subversion and git services commented on IMPALA-13960:
----------------------------------------------------------
Commit c0174bb4383c0d284bd3e8a6312bae49a55dc8ec in impala's branch
refs/heads/master from stiga-huang
[ https://gitbox.apache.org/repos/asf?p=impala.git;h=c0174bb43 ]
IMPALA-13960: Add catalog timeline item for prepareInsertEventData
When enable_insert_events is set to true (default), Impala will fire HMS
INSERT events for each INSERT statement. Preparing data of the
InsertEvents actually takes time since it fetches checksums of all the
new files. This patch adds a catalog timeline item to reveal this step.
Before this patch, the duration of "Got Metastore client" before "Fired
Metastore events" could be long:
Catalog Server Operation: 65.762ms
- Got catalog version read lock: 12.724us (12.724us)
- Got catalog version write lock and table write lock: 224.572us
(211.848us)
- Got Metastore client: 418.346us (193.774us)
- Got Metastore client: 29.001ms (28.583ms) <---- Unexpected long
- Fired Metastore events: 52.665ms (23.663ms)
After this patch, we shows what actually takes the time is "Prepared
InsertEvent data":
Catalog Server Operation: 61.597ms
- Got catalog version read lock: 7.129us (7.129us)
- Got catalog version write lock and table write lock: 114.476us
(107.347us)
- Got Metastore client: 200.040us (85.564us)
- Prepared InsertEvent data: 25.335ms (25.135ms)
- Got Metastore client: 25.342ms (7.009us)
- Fired Metastore events: 46.625ms (21.283ms)
Tests:
- Added e2e test
Change-Id: Iaef1cae7e8ca1c350faae8666ab1369717736978
Reviewed-on: http://gerrit.cloudera.org:8080/22778
Reviewed-by: Impala Public Jenkins <[email protected]>
Tested-by: Impala Public Jenkins <[email protected]>
> 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
>
> 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)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
