[IMPALA-12870] Tag TableLoader logs with query ids

• Type: Improvement
• Status: Open
• Priority: Critical
• Resolution: Unresolved
• Component/s: Catalog
• Epic Link: Catalog Observability
• Epic Color: ghx-label-14
• Assignee: Quanlong Huang
• Reporter: Quanlong Huang
• Created: 05/Mar/24 01:14
• Updated: 06/Mar/24 13:24

Description

In local-catalog mode, the reason of table metadata loading is logged as "needed by coordinator". It'd be helpful to tag the logs with the query ids. So we can confirm which query actually triggers metadata loading on the table.

Here are the catalogd logs for a REFRESH statement in local-catalog mode. The first part is loading the metadata of the table triggered by the planning phase in the coordinator. No query ids are tagged in this part. The second part starts with the resetMetadata request. Logs are tagged with query ids. That's what we want.

I0305 09:05:32.802394 11245 TableLoadingMgr.java:72] Loading metadata for table: functional.alltypestiny
I0305 09:05:32.802747 11336 TableLoader.java:76] Loading metadata for: functional.alltypestiny (needed by coordinator)
I0305 09:05:32.803429 11245 TableLoadingMgr.java:74] Remaining items in queue: 0. Loads in progress: 1
I0305 09:05:32.831334 11336 Table.java:244] createEventId_ for table: functional.alltypestiny set to: -1
I0305 09:05:32.831614 11336 HdfsTable.java:1251] Loading metadata for table definition and all partition(s) of functional.alltypestiny (needed by coordinator)
I0305 09:05:32.846228 11336 HdfsTable.java:1886] Loaded 13 columns from HMS. Actual columns: 13
I0305 09:05:32.867285 11336 HdfsTable.java:3065] Load Valid Write Id List Done. Time taken: 8.479us
I0305 09:05:32.867355 11336 HdfsTable.java:1291] Fetching partition metadata from the Metastore: functional.alltypestiny
I0305 09:05:32.870157 11336 MetaStoreUtil.java:190] Fetching 4 partitions for: functional.alltypestiny using partition batch size: 1000 
I0305 09:05:32.887723 11336 MetaStoreUtil.java:208] Fetched 4/4 partitions for table functional.alltypestiny
I0305 09:05:32.887784 11336 HdfsTable.java:1298] Fetched partition metadata from the Metastore: functional.alltypestiny
I0305 09:05:32.893668 11336 ParallelFileMetadataLoader.java:224] Loading file and block metadata for 4 paths for table functional.alltypestiny using a thread pool of size 4
I0305 09:05:32.898553 11336 HdfsTable.java:821] Loaded file and block metadata for functional.alltypestiny partitions: year=2009/month=1, year=2009/month=2, year=2009/month=3, and 1 others. Time taken: 5.429ms
I0305 09:05:32.899248 11336 Table.java:1104] last refreshed event id for table: functional.alltypestiny set to: -1
I0305 09:05:32.899305 11336 TableLoader.java:176] Loaded metadata for: functional.alltypestiny (96ms)
I0305 09:05:32.930579 11245 JniUtil.java:166] c740fb0d001885d9:6a12143000000000] resetMetadata request: REFRESH TABLE functional.alltypestiny issued by quanlong
I0305 09:05:32.955250 11245 CatalogServiceCatalog.java:2642] c740fb0d001885d9:6a12143000000000] Refreshing table metadata: functional.alltypestiny
I0305 09:05:32.963577 11245 HdfsTable.java:1251] c740fb0d001885d9:6a12143000000000] Reloading metadata for table definition and all partition(s) of functional.alltypestiny (REFRESH TABLE functional.alltypestiny issued by quanlong)
I0305 09:05:32.966183 11245 HdfsTable.java:1886] c740fb0d001885d9:6a12143000000000] Loaded 13 columns from HMS. Actual columns: 13
I0305 09:05:32.975786 11245 HdfsTable.java:3065] c740fb0d001885d9:6a12143000000000] Load Valid Write Id List Done. Time taken: 7.288us
I0305 09:05:32.981313 11245 ParallelFileMetadataLoader.java:224] c740fb0d001885d9:6a12143000000000] Refreshing file and block metadata for 4 paths for table functional.alltypestiny using a thread pool of size 4
I0305 09:05:32.985464 11245 HdfsTable.java:821] c740fb0d001885d9:6a12143000000000] Loaded file and block metadata for functional.alltypestiny partitions: year=2009/month=1, year=2009/month=2, year=2009/month=3, and 1 others. Time taken: 5.839ms
I0305 09:05:32.985622 11245 HdfsTable.java:1289] c740fb0d001885d9:6a12143000000000] Incrementally loaded table metadata for: functional.alltypestiny
I0305 09:05:32.985924 11245 CatalogServiceCatalog.java:2703] c740fb0d001885d9:6a12143000000000] Refreshed table metadata: functional.alltypestiny
I0305 09:05:32.985971 11245 Table.java:1104] c740fb0d001885d9:6a12143000000000] last refreshed event id for table: functional.alltypestiny set to: -1
I0305 09:05:32.988221 11245 JniUtil.java:177] c740fb0d001885d9:6a12143000000000] Finished resetMetadata request: REFRESH TABLE functional.alltypestiny issued by quanlong. Time spent: 58ms

CC fangyurao 

Issue Links

• relates to: IMPALA-6665 Tag CatalogOp logs with query IDs