[IMPALA-5152] Frontend requests metadata for one table at a time in the query

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: Impala 2.8.0, Impala 2.9.0, Impala 2.10.0, Impala 2.11.0
• Fix Version/s: Impala 2.12.0
• Component/s: Catalog, Frontend
• Labels: Performance frontend
• Target Version: Impala 2.12.0
• Epic Color: ghx-label-9
• Assignee: Alexander Behm
• Reporter: Mostafa Mokhtar
• Created: 03/Apr/17 21:30
• Updated: 24/Feb/18 19:13
• Resolved: 22/Feb/18 07:44

Description

It appears that the Frontend serializes loading metadata for missing tables in a query, Catalog log shows that the queue size is alway 0.

Query below references 9 tables and metadata is loaded for one table at a time.

explain select i_item_id ,i_item_desc ,s_state ,count(ss_quantity) as store_sales_quantitycount ,avg(ss_quantity) as store_sales_quantityave ,stddev_samp(ss_quantity) as store_sales_quantitystdev ,stddev_samp(ss_quantity)/avg(ss_quantity) as store_sales_quantitycov ,count(sr_return_quantity) as store_returns_quantitycount ,avg(sr_return_quantity) as store_returns_quantityave ,stddev_samp(sr_return_quantity) as store_returns_quantitystdev ,stddev_samp(sr_return_quantity)/avg(sr_return_quantity) as store_returns_quantitycov ,count(cs_quantity) as catalog_sales_quantitycount ,avg(cs_quantity) as catalog_sales_quantityave ,stddev_samp(cs_quantity) as catalog_sales_quantitystdev ,stddev_samp(cs_quantity)/avg(cs_quantity) as catalog_sales_quantitycov from store_sales ,store_returns ,catalog_sales ,date_dim d1 ,date_dim d2 ,date_dim d3 ,store ,item where d1.d_quarter_name = '2000Q1' and d1.d_date_sk = ss_sold_date_sk and i_item_sk = ss_item_sk and s_store_sk = ss_store_sk and ss_customer_sk = sr_customer_sk and ss_item_sk = sr_item_sk and ss_ticket_number = sr_ticket_number and sr_returned_date_sk = d2.d_date_sk and d2.d_quarter_name in ('2000Q1','2000Q2','2000Q3') and sr_customer_sk = cs_bill_customer_sk and sr_item_sk = cs_item_sk and cs_sold_date_sk = d3.d_date_sk and d3.d_quarter_name in ('2000Q1','2000Q2','2000Q3') group by i_item_id ,i_item_desc ,s_state order by i_item_id ,i_item_desc ,s_state limit 100

Catalog log

I0403 14:17:32.471273 57286 TableLoadingMgr.java:285] Loading next table from queue: tpcds_1000_parquet.store_sales
I0403 14:17:32.471375 57286 TableLoadingMgr.java:287] Remaining items in queue: 0. Loads in progress: 0
I0403 14:17:32.471560 34156 TableLoader.java:58] Loading metadata for: tpcds_1000_parquet.store_sales
I0403 14:17:32.485390 34156 HdfsTable.java:1145] Fetching partition metadata from the Metastore: tpcds_1000_parquet.store_sales
I0403 14:17:32.760711 34156 HdfsTable.java:1149] Fetched partition metadata from the Metastore: tpcds_1000_parquet.store_sales
I0403 14:17:33.958519 34156 HdfsTable.java:844] Loading file and block metadata for 1824 partitions from 1 paths: tpcds_1000_parquet.store_sales
I0403 14:17:34.392324 34156 HdfsTable.java:848] Loaded file and block metadata for 1824 partitions from 1 paths: tpcds_1000_parquet.store_sales
I0403 14:17:34.392421 34156 TableLoader.java:97] Loaded metadata for: tpcds_1000_parquet.store_sales
I0403 14:17:36.058523 57304 catalog-server.cc:320] Publishing update: TABLE:tpcds_1000_parquet.store_sales@3840
I0403 14:17:36.065404 57304 catalog-server.cc:320] Publishing update: CATALOG:44dafc1672d34719:bf64b7285d2a5912@3840
I0403 14:17:38.279191 57271 TableLoadingMgr.java:285] Loading next table from queue: tpcds_1000_parquet.store_returns
I0403 14:17:38.279278 57271 TableLoadingMgr.java:287] Remaining items in queue: 0. Loads in progress: 0
I0403 14:17:38.279422 34244 TableLoader.java:58] Loading metadata for: tpcds_1000_parquet.store_returns
I0403 14:17:38.308568 34244 HdfsTable.java:1145] Fetching partition metadata from the Metastore: tpcds_1000_parquet.store_returns
I0403 14:17:38.579197 34244 HdfsTable.java:1149] Fetched partition metadata from the Metastore: tpcds_1000_parquet.store_returns
I0403 14:17:39.897581 34244 HdfsTable.java:844] Loading file and block metadata for 2004 partitions from 1 paths: tpcds_1000_parquet.store_returns
I0403 14:17:40.371350 34244 HdfsTable.java:848] Loaded file and block metadata for 2004 partitions from 1 paths: tpcds_1000_parquet.store_returns
I0403 14:17:40.371443 34244 TableLoader.java:97] Loaded metadata for: tpcds_1000_parquet.store_returns
I0403 14:17:42.088232 57304 catalog-server.cc:320] Publishing update: TABLE:tpcds_1000_parquet.store_returns@3841
I0403 14:17:42.092733 57304 catalog-server.cc:320] Publishing update: CATALOG:44dafc1672d34719:bf64b7285d2a5912@3841
I0403 14:17:44.361759 57273 TableLoadingMgr.java:285] Loading next table from queue: tpcds_1000_parquet.catalog_sales
I0403 14:17:44.361835 57273 TableLoadingMgr.java:287] Remaining items in queue: 0. Loads in progress: 0
I0403 14:17:44.362061 34289 TableLoader.java:58] Loading metadata for: tpcds_1000_parquet.catalog_sales
I0403 14:17:44.377027 34289 HdfsTable.java:1145] Fetching partition metadata from the Metastore: tpcds_1000_parquet.catalog_sales
I0403 14:17:44.650100 34289 HdfsTable.java:1149] Fetched partition metadata from the Metastore: tpcds_1000_parquet.catalog_sales
I0403 14:17:45.819257 34289 HdfsTable.java:844] Loading file and block metadata for 1837 partitions from 1 paths: tpcds_1000_parquet.catalog_sales
I0403 14:17:46.264878 34289 HdfsTable.java:848] Loaded file and block metadata for 1837 partitions from 1 paths: tpcds_1000_parquet.catalog_sales
I0403 14:17:46.264987 34289 TableLoader.java:97] Loaded metadata for: tpcds_1000_parquet.catalog_sales
I0403 14:17:48.093703 57304 catalog-server.cc:320] Publishing update: TABLE:tpcds_1000_parquet.catalog_sales@3842
I0403 14:17:48.098681 57304 catalog-server.cc:320] Publishing update: CATALOG:44dafc1672d34719:bf64b7285d2a5912@3842
I0403 14:17:50.438555 57272 TableLoadingMgr.java:285] Loading next table from queue: tpcds_1000_parquet.date_dim
I0403 14:17:50.438663 57272 TableLoadingMgr.java:287] Remaining items in queue: 0. Loads in progress: 0
I0403 14:17:50.438886 34319 TableLoader.java:58] Loading metadata for: tpcds_1000_parquet.date_dim
I0403 14:17:50.454288 34319 HdfsTable.java:1145] Fetching partition metadata from the Metastore: tpcds_1000_parquet.date_dim
I0403 14:17:50.455581 34319 HdfsTable.java:1149] Fetched partition metadata from the Metastore: tpcds_1000_parquet.date_dim
I0403 14:17:50.458034 34319 HdfsTable.java:844] Loading file and block metadata for 1 partitions from 1 paths: tpcds_1000_parquet.date_dim
I0403 14:17:50.458940 34319 HdfsTable.java:848] Loaded file and block metadata for 1 partitions from 1 paths: tpcds_1000_parquet.date_dim
I0403 14:17:50.459019 34319 TableLoader.java:97] Loaded metadata for: tpcds_1000_parquet.date_dim
I0403 14:17:52.067752 57304 catalog-server.cc:320] Publishing update: TABLE:tpcds_1000_parquet.date_dim@3843
I0403 14:17:52.068792 57304 catalog-server.cc:320] Publishing update: CATALOG:44dafc1672d34719:bf64b7285d2a5912@3843
I0403 14:17:54.451196 57276 TableLoadingMgr.java:285] Loading next table from queue: tpcds_1000_parquet.store
I0403 14:17:54.451275 57276 TableLoadingMgr.java:287] Remaining items in queue: 0. Loads in progress: 0
I0403 14:17:54.451402 34392 TableLoader.java:58] Loading metadata for: tpcds_1000_parquet.store
I0403 14:17:54.464722 34392 HdfsTable.java:1145] Fetching partition metadata from the Metastore: tpcds_1000_parquet.store
I0403 14:17:54.466107 34392 HdfsTable.java:1149] Fetched partition metadata from the Metastore: tpcds_1000_parquet.store
I0403 14:17:54.468161 34392 HdfsTable.java:844] Loading file and block metadata for 1 partitions from 1 paths: tpcds_1000_parquet.store
I0403 14:17:54.468992 34392 HdfsTable.java:848] Loaded file and block metadata for 1 partitions from 1 paths: tpcds_1000_parquet.store
I0403 14:17:54.469070 34392 TableLoader.java:97] Loaded metadata for: tpcds_1000_parquet.store
I0403 14:17:56.036121 57304 catalog-server.cc:320] Publishing update: TABLE:tpcds_1000_parquet.store@3844
I0403 14:17:56.037204 57304 catalog-server.cc:320] Publishing update: CATALOG:44dafc1672d34719:bf64b7285d2a5912@3844
I0403 14:17:58.457381 57274 TableLoadingMgr.java:285] Loading next table from queue: tpcds_1000_parquet.item
I0403 14:17:58.457473 57274 TableLoadingMgr.java:287] Remaining items in queue: 0. Loads in progress: 0
I0403 14:17:58.457653 34456 TableLoader.java:58] Loading metadata for: tpcds_1000_parquet.item
I0403 14:17:58.470528 34456 HdfsTable.java:1145] Fetching partition metadata from the Metastore: tpcds_1000_parquet.item
I0403 14:17:58.471864 34456 HdfsTable.java:1149] Fetched partition metadata from the Metastore: tpcds_1000_parquet.item
I0403 14:17:58.474072 34456 HdfsTable.java:844] Loading file and block metadata for 1 partitions from 1 paths: tpcds_1000_parquet.item
I0403 14:17:58.474925 34456 HdfsTable.java:848] Loaded file and block metadata for 1 partitions from 1 paths: tpcds_1000_parquet.item
I0403 14:17:58.475021 34456 TableLoader.java:97] Loaded metadata for: tpcds_1000_parquet.item
I0403 14:18:00.036249 57304 catalog-server.cc:320] Publishing update: TABLE:tpcds_1000_parquet.item@3845
I0403 14:18:00.037330 57304 catalog-server.cc:320] Publishing update: CATALOG:44dafc1672d34719:bf64b7285d2a5912@3845

Coordinator node log

I0403 14:17:32.471491 37742 Frontend.java:833] Requesting prioritized load of table(s): tpcds_1000_parquet.store_sales
I0403 14:17:38.279330 37742 Frontend.java:833] Requesting prioritized load of table(s): tpcds_1000_parquet.store_returns
I0403 14:17:44.361925 37742 Frontend.java:833] Requesting prioritized load of table(s): tpcds_1000_parquet.catalog_sales
I0403 14:17:50.438707 37742 Frontend.java:833] Requesting prioritized load of table(s): tpcds_1000_parquet.date_dim
I0403 14:17:54.451408 37742 Frontend.java:833] Requesting prioritized load of table(s): tpcds_1000_parquet.store
I0403 14:17:58.457484 37742 Frontend.java:833] Requesting prioritized load of table(s): tpcds_1000_parquet.item
I0403 14:18:02.465189 37742 Frontend.java:928] Compiled query.
I0403 14:18:02.593619 37742 impala-beeswax-server.cc:190] get_results_metadata(): query_id=664050071b49c3c8:10b184b900000000
I0403 14:18:02.618315 37742 impala-beeswax-server.cc:233] close(): query_id=664050071b49c3c8:10b184b900000000
I0403 14:18:02.618413 37742 impala-server.cc:921] UnregisterQuery(): query_id=664050071b49c3c8:10b184b900000000
I0403 14:18:02.618422 37742 impala-server.cc:1007] Cancel(): query_id=664050071b49c3c8:10b184b900000000

Issue Links

• breaks: IMPALA-6567 Dataload performance regression due to slow invalidate metadata