Michael Smith created IMPALA-14022:
--------------------------------------
Summary: test_alter_table_rename_independent fails intermittently
Key: IMPALA-14022
URL: https://issues.apache.org/jira/browse/IMPALA-14022
Project: IMPALA
Issue Type: Task
Components: Infrastructure
Affects Versions: Impala 5.0.0
Reporter: Michael Smith
metadata.test_ddl.TestDdlStatements.test_alter_table_rename_independent failed
with a timeout. Looking at logs, we see
{code}
alter table test_alter_table_rename_independent_7de44076.tbl_1 rename to
test_alter_table_rename_independent_7de44076.tbl_3;
-- 2025-04-28 18:03:50,726 INFO MainThread: Started query
a64edb1c7caf5920:de27e23600000000
-- 2025-04-28 18:03:50,727 INFO MainThread: beeswax: executing async
localhost:21000
alter table test_alter_table_rename_independent_7de44076.tbl_2 rename to
test_alter_table_rename_independent_7de44076.tbl_4;
-- 2025-04-28 18:03:50,736 INFO MainThread: Started query
3f441e55a077dd7b:5d649a6c00000000
-- 2025-04-28 18:03:50,736 INFO MainThread:
a64edb1c7caf5920:de27e23600000000: waiting for query to reach FINISHED state
-- 2025-04-28 18:04:00,749 INFO MainThread: beeswax: closing beeswax
connection to: localhost:21000
{code}
so we timed out waiting for the 1st alter to finish.
catalogd logs show
{code}
I0428 18:03:50.726923 2326115 JniUtil.java:167]
a64edb1c7caf5920:de27e23600000000] execDdl request: ALTER_TABLE
test_alter_table_rename_independent_7de44076.tbl_1 RENAME_TABLE issued by
jenkins
I0428 18:03:50.741663 2326115 DebugUtils.java:168]
a64edb1c7caf5920:de27e23600000000] Sleeping for 5000 msec to execute debug
action catalogd_table_rename_delay
I0428 18:03:55.742517 2326115 MetastoreEventsProcessor.java:408]
a64edb1c7caf5920:de27e23600000000] Fetching ALTER_TABLE events started from id
54776 to 54783. Gap: 7
I0428 18:03:55.744583 2326115 Table.java:246]
a64edb1c7caf5920:de27e23600000000] createEventId_ for table:
test_alter_table_rename_independent_7de44076.tbl_3 set to: 54740
I0428 18:03:55.744626 2326115 Table.java:261]
a64edb1c7caf5920:de27e23600000000] lastSyncedEventId_ for table:
test_alter_table_rename_independent_7de44076.tbl_3 set from -1 to 54740
I0428 18:03:55.744678 2326115 Table.java:246]
a64edb1c7caf5920:de27e23600000000] createEventId_ for table:
test_alter_table_rename_independent_7de44076.tbl_3 set to: 54777
I0428 18:03:55.744707 2326115 Table.java:261]
a64edb1c7caf5920:de27e23600000000] lastSyncedEventId_ for table:
test_alter_table_rename_independent_7de44076.tbl_3 set from 54740 to 54777
I0428 18:03:55.744742 2326115 CatalogServiceCatalog.java:1340]
a64edb1c7caf5920:de27e23600000000] Added catalog version 57730 in table's
test_alter_table_rename_independent_7de44076.tbl_3 in-flight events
I0428 18:03:55.744798 2326115 CatalogServiceCatalog.java:3693]
a64edb1c7caf5920:de27e23600000000] Should wait for next update for
TABLE:test_alter_table_rename_independent_7de44076.tbl_1: older version 57697
is sent. Expects a version >= 57735.
I0428 18:03:55.744841 2326115 CatalogServiceCatalog.java:3603]
a64edb1c7caf5920:de27e23600000000] Topic update for updates not found yet. Last
sent catalog version: 57713. Updated objects:
[TABLE:test_alter_table_rename_independent_7de44076.tbl_3 version: 57736],
deleted objects: [TABLE:test_alter_table_rename_independent_7de44076.tbl_1
version: 57735]
I0428 18:03:55.760998 2326115 CatalogServiceCatalog.java:3693]
a64edb1c7caf5920:de27e23600000000] Should wait for next update for
TABLE:test_alter_table_rename_independent_7de44076.tbl_1: older version 57697
is sent. Expects a version >= 57735.
I0428 18:03:55.761102 2326115 CatalogServiceCatalog.java:3603]
a64edb1c7caf5920:de27e23600000000] Topic update for updates not found yet. Last
sent catalog version: 57733. Updated objects:
[TABLE:test_alter_table_rename_independent_7de44076.tbl_3 version: 57736],
deleted objects: [TABLE:test_alter_table_rename_independent_7de44076.tbl_1
version: 57735]
I0428 18:03:56.250380 2326115 CatalogServiceCatalog.java:3640]
a64edb1c7caf5920:de27e23600000000] Operation using SYNC_DDL is waiting for
catalog version 57745 to be sent. Time to identify topic update (msec): 506.
I0428 18:03:56.250574 2326115 JniUtil.java:178]
a64edb1c7caf5920:de27e23600000000] Finished execDdl request: ALTER_TABLE
test_alter_table_rename_independent_7de44076.tbl_1 RENAME_TABLE issued by
jenkins. Time spent: 5s524ms
{code}
which shows the alter takes 5.5 seconds, with 5 seconds spent in the debug
action.
impalad shows
{code}
I0428 18:03:50.717921 2382103 impala-server.cc:1480]
a64edb1c7caf5920:de27e23600000000] Registered query
query_id=a64edb1c7caf5920:de27e23600000000
session_id=f5484dbaf1634fb1:5b83b427ba6e17b5
I0428 18:03:50.725986 2382103 Frontend.java:3693]
a64edb1c7caf5920:de27e23600000000] Searching for planner to use...
I0428 18:03:50.726011 2382103 Frontend.java:2361]
a64edb1c7caf5920:de27e23600000000] Using Original Planner.
I0428 18:03:50.726033 2382103 Frontend.java:2389]
a64edb1c7caf5920:de27e23600000000] Analyzing query: alter table
test_alter_table_rename_independent_7de44076.tbl_1 rename to
test_alter_table_rename_independent_7de44076.tbl_3 db: default
I0428 18:03:50.726060 2382103 Frontend.java:2423]
a64edb1c7caf5920:de27e23600000000] The original executor group sets from
executor membership snapshot: [TExecutorGroupSet(curr_num_executors:3,
expected_num_executors:20, exec_group_name_prefix:)]
I0428 18:03:50.726092 2382103 Frontend.java:2443]
a64edb1c7caf5920:de27e23600000000] A total of 2 executor group sets to be
considered for auto-scaling: [TExecutorGroupSet(curr_num_executors:3,
expected_num_executors:20, exec_group_name_prefix:small,
max_mem_limit:67108864, num_cores_per_executor:8),
TExecutorGroupSet(curr_num_executors:3, expected_num_executors:20,
exec_group_name_prefix:large, max_mem_limit:9223372036854775807,
num_cores_per_executor:2147483647)]
I0428 18:03:50.726117 2382103 Frontend.java:2484]
a64edb1c7caf5920:de27e23600000000] Consider executor group set:
TExecutorGroupSet(curr_num_executors:3, expected_num_executors:20,
exec_group_name_prefix:small, max_mem_limit:67108864, num_cores_per_executor:8)
with assumption of 0 cores per node.
I0428 18:03:50.726307 2382103 AnalysisContext.java:512]
a64edb1c7caf5920:de27e23600000000] Analysis took 0 ms
I0428 18:03:50.726346 2382103 BaseAuthorizationChecker.java:114]
a64edb1c7caf5920:de27e23600000000] Authorization check took 0 ms
I0428 18:03:50.726367 2382103 Frontend.java:2926]
a64edb1c7caf5920:de27e23600000000] Analysis and authorization finished.
I0428 18:03:50.726397 2382103 RequestPoolService.java:198]
a64edb1c7caf5920:de27e23600000000] Default pool only, scheduler allocation is
not specified.
I0428 18:03:50.726442 2382103 Frontend.java:2707]
a64edb1c7caf5920:de27e23600000000] Selected executor group:
TExecutorGroupSet(curr_num_executors:3, expected_num_executors:20,
exec_group_name_prefix:small, max_mem_limit:67108864,
num_cores_per_executor:8), reason: query is not auto-scalable
I0428 18:03:50.726675 2382103 client-request-state.cc:836]
a64edb1c7caf5920:de27e23600000000] DDL exec mode=asynchronous
I0428 18:03:50.726734 2382104 client-request-state.cc:755]
a64edb1c7caf5920:de27e23600000000] Running in worker thread
I0428 18:03:56.260279 2382104 ImpaladCatalog.java:232]
a64edb1c7caf5920:de27e23600000000] Deleting:
TABLE:test_alter_table_rename_independent_7de44076.tbl_1 version: 57735 size:
409
I0428 18:03:56.260316 2382104 ImpaladCatalog.java:232]
a64edb1c7caf5920:de27e23600000000] Adding:
TABLE:test_alter_table_rename_independent_7de44076.tbl_3 version: 57736 size:
104
I0428 18:03:56.260386 2382104 impala-server.cc:2316]
a64edb1c7caf5920:de27e23600000000] Waiting for catalog version: 57745 current
version: 57713
I0428 18:03:58.719236 2382104 impala-server.cc:2331]
a64edb1c7caf5920:de27e23600000000] Applied catalog version: 57745
I0428 18:03:58.719250 2382104 impala-server.cc:2340]
a64edb1c7caf5920:de27e23600000000] Waiting for min subscriber topic version:
69573 current version: 69561
I0428 18:04:00.719626 2382104 impala-server.cc:2357]
a64edb1c7caf5920:de27e23600000000] Min catalog topic version of coordinators:
69573
I0428 18:04:00.749621 2382103 impala-server.cc:1586] UnregisterQuery():
query_id=a64edb1c7caf5920:de27e23600000000
I0428 18:04:00.749867 1656892 impala-server.cc:1623] Query successfully
unregistered: query_id=a64edb1c7caf5920:de27e23600000000
{code}
the alter largely finishes in 6 seconds, then waits for the catalog to catch
up. That seems to take just over 10 seconds, leading to the timeout.
This test probably needs to be run serially to avoid delays in catalog
processing, or updated to assert time spent on the alter (without caring about
the catalog delays).
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
