[
https://issues.apache.org/jira/browse/IMPALA-14022?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Michael Smith resolved IMPALA-14022.
------------------------------------
Resolution: Fixed
> 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
> Assignee: Michael Smith
> Priority: Major
> Fix For: Impala 5.0.0
>
>
> 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)
