You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues-all@impala.apache.org by "Michael Smith (Jira)" <ji...@apache.org> on 2025/04/24 18:08:00 UTC
[jira] [Commented] (IMPALA-13884) Improves logging of slow event processing
[ https://issues.apache.org/jira/browse/IMPALA-13884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17947120#comment-17947120 ]
Michael Smith commented on IMPALA-13884:
----------------------------------------
This also incidentally fixed a NullPointerException that can happen when table updates and invalidate metadata race.
> 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)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-all-unsubscribe@impala.apache.org
For additional commands, e-mail: issues-all-help@impala.apache.org