[
https://issues.apache.org/jira/browse/IMPALA-13799?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17930514#comment-17930514
]
Quanlong Huang commented on IMPALA-13799:
-----------------------------------------
The test drops table test_query_with_tbls_954fd7ae.alltypes and view
test_query_with_tbls_954fd7ae.alltypes_view, then waits for the DROP events to
be processed and impalad gets the latest catalog (i.e. version 12461). It times
out in waiting for the catalog update to arrive.
Uploaded the catalogd logs. The catalog update was sent after the timeout
timestamp:
{code}
W0225 10:14:55.487963 129 CatalogServiceCatalog.java:634] Read lock for table
test_overlap_min_max_filters_44bab696.store_sales was acquired in 10337 msec
...
I0225 10:14:55.507401 129 catalog-server.cc:1321] Collected deletion:
2:TABLE:test_query_with_tbls_954fd7ae.alltypes, version=12460, original
size=85, compressed size=86
...
I0225 10:14:55.507661 129 catalog-server.cc:1321] Collected deletion:
2:VIEW:test_query_with_tbls_954fd7ae.alltypes_view, version=12461, original
size=90, compressed size=91
I0225 10:14:55.507675 129 catalog-server.cc:1321] Collected update:
2:CATALOG_SERVICE_ID, version=12463, original size=60, compressed size=58
I0225 10:14:55.507743 129 JniUtil.java:178] Finished getCatalogDelta request:
Getting catalog delta from version 12455. Time spent: 10s359ms{code}
It was blocked at acquring the table lock of another test table for 10s. We
should increase the timeout since the test runs concurrently with many other
tests.
> Flakiness in TestTestcaseBuilder.test_query_with_tbls due to slow catalog
> updates
> ---------------------------------------------------------------------------------
>
> Key: IMPALA-13799
> URL: https://issues.apache.org/jira/browse/IMPALA-13799
> Project: IMPALA
> Issue Type: Bug
> Components: Test
> Reporter: Quanlong Huang
> Assignee: Quanlong Huang
> Priority: Critical
> Attachments:
> catalogd.cad2c3d4614e.invalid-user.log.INFO.20250225-091541.1.gz
>
>
> Saw TestTestcaseBuilder.test_query_with_tbls failed in an unrelated patch:
> [https://jenkins.impala.io/job/ubuntu-20.04-dockerised-tests/2977/testReport/junit/metadata.test_testcase_builder/TestTestcaseBuilder/test_query_with_tbls/]
> Stacktrace:
> {noformat}
> metadata/test_testcase_builder.py:60: in test_query_with_tbls
> [unique_database + ".alltypes"], [unique_database + ".alltypes_view"])
> metadata/test_testcase_builder.py:106: in _test_export_and_import
> EventProcessorUtils.wait_for_event_processing(self)
> util/event_processor_utils.py:93: in wait_for_event_processing
> impala_cluster, timeout, error_status_possible)
> util/event_processor_utils.py:112: in wait_for_event_processing_impl
> allow_greater=True)
> common/impala_service.py:145: in wait_for_metric_value
> self.__metric_timeout_assert(metric_name, expected_value, timeout, value)
> common/impala_service.py:214: in __metric_timeout_assert
> assert 0, assert_string
> E AssertionError: Metric catalog.curr-version did not reach value 12461 in
> 10s. Actual value was '12455'.
> E Dumping debug webpages in JSON format...{noformat}
> Standard Error:
> {code:java}
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> -- connecting to: localhost:21000
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> -- connecting to localhost:21050 with impyla
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> -- connecting to localhost:28000 with impyla
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> -- connecting to localhost:21050 with impyla
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> set_option('sync_ddl', 'False')
> -- executing against Impala at localhost:21050
> DROP DATABASE IF EXISTS `test_query_with_tbls_954fd7ae` CASCADE;
> -- a043740ae0ba33a3:8a68fbb500000000: getting log for operation
> -- a043740ae0ba33a3:8a68fbb500000000: getting runtime profile operation
> -- a043740ae0ba33a3:8a68fbb500000000: closing query for operation
> -- executing against Impala at localhost:21050
> CREATE DATABASE `test_query_with_tbls_954fd7ae`;
> -- 3746f4281f26eb84:4ed9e8ef00000000: getting log for operation
> -- 3746f4281f26eb84:4ed9e8ef00000000: getting runtime profile operation
> -- 3746f4281f26eb84:4ed9e8ef00000000: closing query for operation
> -- 2025-02-25 10:14:42,678 INFO MainThread: Created database
> "test_query_with_tbls_954fd7ae" for test ID
> "metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls"
> -- closing connection to: localhost:21050
> -- executing against localhost:21000
> create table test_query_with_tbls_954fd7ae.alltypes partitioned by (`year`,
> `month`) as select * from functional.alltypes;
> -- 2025-02-25 10:14:42,755 INFO MainThread: Started query
> 804b410087862222:6bdf0f3600000000
> -- executing against localhost:21000
> create view test_query_with_tbls_954fd7ae.alltypes_view as select * from
> test_query_with_tbls_954fd7ae.alltypes;
> -- 2025-02-25 10:14:43,114 INFO MainThread: Started query
> ce44c036e726876c:2612e06500000000
> -- executing against localhost:21000
> COPY TESTCASE TO '/tmp' select count(*) from
> test_query_with_tbls_954fd7ae.alltypes_view;
> -- 2025-02-25 10:14:43,209 INFO MainThread: Started query
> 3e4d8fc01a0e5684:32848eb900000000
> set_option('client_identifier',
> 'metadata/test_testcase_builder.py::TestTestcaseBuilder::()::test_query_with_tbls')
> set_option('explain_level', '2')
> -- executing against localhost:21000
> explain select count(*) from test_query_with_tbls_954fd7ae.alltypes_view;
> -- 2025-02-25 10:14:43,219 INFO MainThread: Started query
> 474a11ea3c5669b5:cbb9da1500000000
> -- executing against localhost:21000
> drop table if exists test_query_with_tbls_954fd7ae.alltypes;
> -- 2025-02-25 10:14:43,223 INFO MainThread: Started query
> fa43aa6c56b5353c:cf114cec00000000
> -- executing against localhost:21000
> drop view if exists test_query_with_tbls_954fd7ae.alltypes_view;
> -- 2025-02-25 10:14:43,329 INFO MainThread: Started query
> 404ec95510164fe8:a341345d00000000
> -- 2025-02-25 10:14:43,625 DEBUG MainThread: Found 3 impalad/1
> statestored/1 catalogd process(es)
> -- 2025-02-25 10:14:43,636 INFO MainThread: Waiting until events
> processor syncs to event id:43830
> -- 2025-02-25 10:14:44,189 DEBUG MainThread: Metric last-synced-event-id
> has reached the desired value: 43830
> -- 2025-02-25 10:14:44,212 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:44,216 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:45,218 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:45,231 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:46,232 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:46,243 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:47,243 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:47,248 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:48,249 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:48,254 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:49,255 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:49,260 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:50,261 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:50,266 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:51,270 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:51,277 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:52,278 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:52,282 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:53,283 INFO MainThread: Getting metric:
> catalog.curr-version from ip-172-31-54-194:25000
> -- 2025-02-25 10:14:53,286 INFO MainThread: Sleeping 1s before next retry.
> -- 2025-02-25 10:14:54,287 INFO MainThread: Metric catalog.curr-version
> did not reach value 12461 in 10s. Actual value was '12455'. Failing... {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-all-unsubscr...@impala.apache.org
For additional commands, e-mail: issues-all-h...@impala.apache.org
