[
https://issues.apache.org/jira/browse/IMPALA-13884?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Quanlong Huang resolved IMPALA-13884.
-------------------------------------
Fix Version/s: Impala 5.0.0
Resolution: Fixed
Resolving this. Thank [~rizaon] and [~jasonmfehr] for the review!
> Improves logging of slow event processing
> -----------------------------------------
>
> Key: IMPALA-13884
> URL: https://issues.apache.org/jira/browse/IMPALA-13884
> Project: IMPALA
> Issue Type: Improvement
> Reporter: Quanlong Huang
> Assignee: Quanlong Huang
> Priority: Major
> Fix For: Impala 5.0.0
>
>
> I saw a slow event processing log like this:
> {code:java}
> W0306 20:54:02.202912 279 MetastoreEventsProcessor.java:1417] Top 10
> expensive events: (type=INSERT, id=4485886,
> target=highpartition_small_impala.stocks_highpartition_small_file,
> duration_ms=40529)...{code}
> However, I can't find any logs of this event directly. Instead, I have to
> find logs of the previous event 4485885
> {code:java}
> I0306 20:52:29.213896 279 MetastoreEvents.java:838] EventId: 4485885
> EventType: ADD_PARTITION Incremented skipped metric to 1101327 since no
> partitions were added.{code}
> and the next event 4485887
> {code:java}
> I0306 20:53:09.742729 279 MetastoreEvents.java:827] EventId: 4485887
> EventType: ALTER_PARTITION Not processing this event as it only modifies some
> partition parameters which can be ignored.{code}
> Then all the logs of thread id 279 between these two are the logs of event
> 4485886. Note that currently event processing is executed in a dedicated
> thread (single thread).
> {noformat}
> W0306 20:53:03.690521 279 CatalogServiceCatalog.java:631] Write lock for
> table highpartition_small_impala.stocks_highpartition_small_file was acquired
> in 34477 msec
> W0306 20:53:09.326007 279 CatalogServiceCatalog.java:631] Write lock for
> table highpartition_small_impala.stocks_highpartition_small_file was acquired
> in 5635 msec
> I0306 20:53:09.326260 279 HdfsTable.java:2914] Reloading partition
> metadata: highpartition_small_impala.stocks_highpartition_small_file
> year=2022/month=Feb/day=10 (INSERT event)
> I0306 20:53:09.326365 279 MetaStoreUtil.java:191] Fetching 1 partitions
> for: highpartition_small_impala.stocks_highpartition_small_file using
> partition batch size: 1000
> I0306 20:53:09.339805 279 MetaStoreUtil.java:223] Fetched 1/1 partitions
> for table highpartition_small_impala.stocks_highpartition_small_file
> I0306 20:53:09.342584 279 HdfsTable.java:3072] Setting the latest refresh
> event id to 5016235 for the reloaded 1 partitions
> I0306 20:53:09.342660 279 HdfsTable.java:3075] for table
> highpartition_small_impala.stocks_highpartition_small_file, file metadataOps:
> FORCE_LOAD, refreshing file metadata for 1 out of 1 partitions to reload in
> reloadPartitions()
> I0306 20:53:09.742367 279 HdfsTable.java:847] Loaded file and block
> metadata for highpartition_small_impala.stocks_highpartition_small_file
> partitions: year=2022/month=Feb/day=10. Time taken: 399.520ms{noformat}
> We might not be always lucky to have logs of the previous and next events.
> It'd be helpful to show the event id somewhere, e.g. in the reason of
> reloading "(INSERT event)".
> For the warning logs of waiting for write locks too long, we should log the
> stacktrace so we know what's waiting for it.
> For the skipped events, it'd be helpful to log the table name and partition
> name.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
