Quanlong Huang created IMPALA-13884:
---------------------------------------
Summary: 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
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)
