Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
Impala 4.0.0
-
None
-
ghx-label-13
Description
TestScratchLimit::test_with_unlimited_scratch_limit has been intermittently crashing in ubuntu-16.04-dockerised-tests environment after result spooling is enabled by default in IMPALA-9856. We decide to disable result spooling for TestScratchLimit in IMPALA-10559. However, we still need to investigate what is the root cause of the intermittent crash.
I tried to loop the test overnight with minicluster of 2 impalad and the following modification on test_with_unlimited_scratch_limit query options:
- spool_query_results=1
- buffer_pool_limit=24m
- max_result_spooling_mem=4m
At iteration 589, test_with_unlimited_scratch_limit crash with the following logs.
impalad.INFO
I0314 00:15:16.495184 10628 impala-beeswax-server.cc:541] TClientRequest.queryOptions: TQueryOptions {
01: abort_on_error (bool) = true,
02: max_errors (i32) = 100,
03: disable_codegen (bool) = false,
04: batch_size (i32) = 0,
05: num_nodes (i32) = 0,
06: max_scan_range_length (i64) = 0,
07: num_scanner_threads (i32) = 0,
11: debug_action (string) = "",
12: mem_limit (i64) = 0,
15: hbase_caching (i32) = 0,
16: hbase_cache_blocks (bool) = false,
17: parquet_file_size (i64) = 0,
18: explain_level (i32) = 1,
19: sync_ddl (bool) = false,
24: disable_outermost_topn (bool) = false,
26: query_timeout_s (i32) = 0,
27: buffer_pool_limit (i64) = 25165824,
28: appx_count_distinct (bool) = false,
29: disable_unsafe_spills (bool) = false,
31: exec_single_node_rows_threshold (i32) = 0,
32: optimize_partition_key_scans (bool) = false,
33: replica_preference (i32) = 0,
34: schedule_random_replica (bool) = false,
36: disable_streaming_preaggregations (bool) = false,
37: runtime_filter_mode (i32) = 2,
38: runtime_bloom_filter_size (i32) = 1048576,
39: runtime_filter_wait_time_ms (i32) = 0,
40: disable_row_runtime_filtering (bool) = false,
41: max_num_runtime_filters (i32) = 10,
42: parquet_annotate_strings_utf8 (bool) = false,
43: parquet_fallback_schema_resolution (i32) = 0,
45: s3_skip_insert_staging (bool) = true,
46: runtime_filter_min_size (i32) = 1048576,
47: runtime_filter_max_size (i32) = 16777216,
48: prefetch_mode (i32) = 1,
49: strict_mode (bool) = false,
50: scratch_limit (i64) = -1,
51: enable_expr_rewrites (bool) = true,
52: decimal_v2 (bool) = true,
53: parquet_dictionary_filtering (bool) = true,
54: parquet_array_resolution (i32) = 0,
55: parquet_read_statistics (bool) = true,
56: default_join_distribution_mode (i32) = 0,
57: disable_codegen_rows_threshold (i32) = 5000,
58: default_spillable_buffer_size (i64) = 2097152,
59: min_spillable_buffer_size (i64) = 65536,
60: max_row_size (i64) = 524288,
61: idle_session_timeout (i32) = 0,
62: compute_stats_min_sample_size (i64) = 1073741824,
63: exec_time_limit_s (i32) = 0,
64: shuffle_distinct_exprs (bool) = true,
65: max_mem_estimate_for_admission (i64) = 0,
66: thread_reservation_limit (i32) = 3000,
67: thread_reservation_aggregate_limit (i32) = 0,
68: kudu_read_mode (i32) = 0,
69: allow_erasure_coded_files (bool) = false,
70: timezone (string) = "",
71: scan_bytes_limit (i64) = 0,
72: cpu_limit_s (i64) = 0,
73: topn_bytes_limit (i64) = 536870912,
74: client_identifier (string) = "query_test/test_scratch_limit.py::TestScratchLimit::()::test_with_unlimited_scratch_limit[protocol:beeswax|exec_option:{'batch_size':0;'num_nodes':0;'disable_codegen_rows_threshold':5000;'disable_codegen':False;'abort_on_error':1;'exec_single_node_rows_th",
75: resource_trace_ratio (double) = 0,
76: num_remote_executor_candidates (i32) = 3,
77: num_rows_produced_limit (i64) = 0,
78: planner_testcase_mode (bool) = false,
79: default_file_format (i32) = 0,
80: parquet_timestamp_type (i32) = 0,
81: parquet_read_page_index (bool) = true,
82: parquet_write_page_index (bool) = true,
84: disable_hdfs_num_rows_estimate (bool) = false,
86: spool_query_results (bool) = true,
87: default_transactional_type (i32) = 0,
88: statement_expression_limit (i32) = 250000,
89: max_statement_length_bytes (i32) = 16777216,
90: disable_data_cache (bool) = false,
91: max_result_spooling_mem (i64) = 4194304,
92: max_spilled_result_spooling_mem (i64) = 1073741824,
93: disable_hbase_num_rows_estimate (bool) = false,
94: fetch_rows_timeout_ms (i64) = 10000,
95: now_string (string) = "",
96: parquet_object_store_split_size (i64) = 268435456,
97: mem_limit_executors (i64) = 0,
98: broadcast_bytes_limit (i64) = 34359738368,
99: preagg_bytes_limit (i64) = -1,
100: enable_cnf_rewrites (bool) = true,
101: max_cnf_exprs (i32) = 200,
102: kudu_snapshot_read_timestamp_micros (i64) = 0,
103: retry_failed_queries (bool) = false,
104: enabled_runtime_filter_types (i32) = 3,
105: async_codegen (bool) = false,
106: enable_distinct_semi_join_optimization (bool) = true,
107: sort_run_bytes_limit (i64) = -1,
108: max_fs_writers (i32) = 0,
109: refresh_updated_hms_partitions (bool) = false,
110: spool_all_results_for_retries (bool) = true,
112: use_local_tz_for_unix_timestamp_conversions (bool) = false,
113: convert_legacy_hive_parquet_utc_timestamps (bool) = false,
114: enable_outer_join_to_inner_transformation (bool) = false,
115: targeted_kudu_scan_range_length (i64) = -1,
116: report_skew_limit (double) = 1,
117: optimize_simple_limit (bool) = false,
118: use_dop_for_costing (bool) = true,
119: broadcast_to_partition_factor (double) = 1,
120: join_rows_produced_limit (i64) = 0,
121: utf8_mode (bool) = false,
122: analytic_rank_pushdown_threshold (i64) = 1000,
123: minmax_filter_threshold (double) = 0,
124: minmax_filtering_level (i32) = 1,
}
I0314 00:15:16.495311 10628 impala-server.cc:1247] Found local timezone "America/Los_Angeles".
I0314 00:15:16.498564 10628 impala-server.cc:1304] f54227735548245d:fc498f1400000000] Registered query query_id=f54227735548245d:fc498f1400000000 session_id=ec437b1251da7828:462192f6533a37a8
I0314 00:15:16.503772 10628 Frontend.java:1598] f54227735548245d:fc498f1400000000] Analyzing query: select o_orderdate, o_custkey, o_comment
from tpch.orders
order by o_orderdate db: default
I0314 00:15:16.504245 10628 BaseAuthorizationChecker.java:110] f54227735548245d:fc498f1400000000] Authorization check took 0 ms
I0314 00:15:16.504266 10628 Frontend.java:1640] f54227735548245d:fc498f1400000000] Analysis and authorization finished.
I0314 00:15:16.506330 10629 admission-controller.cc:1696] f54227735548245d:fc498f1400000000] Trying to admit id=f54227735548245d:fc498f1400000000 in pool_name=default-pool executor_group_name=default per_host_mem_estimate=264.93 MB dedicated_coord_mem_estimate=124.18 MB max_requests=-1 max_queued=200 max_mem=-1.00 B
I0314 00:15:16.506346 10629 admission-controller.cc:1704] f54227735548245d:fc498f1400000000] Stats: agg_num_running=0, agg_num_queued=0, agg_mem_reserved=0, local_host(local_mem_admitted=0, num_admitted_running=0, num_queued=0, backend_mem_reserved=0, topN_query_stats: queries=[], total_mem_consumed=0; pool_level_stats: num_running=0, min=0, max=0, pool_total_mem=0)
I0314 00:15:16.506363 10629 admission-controller.cc:1212] f54227735548245d:fc498f1400000000] Admitting query id=f54227735548245d:fc498f1400000000
I0314 00:15:16.506400 10629 impala-server.cc:2130] f54227735548245d:fc498f1400000000] Registering query locations
I0314 00:15:16.506425 10629 coordinator.cc:150] f54227735548245d:fc498f1400000000] Exec() query_id=f54227735548245d:fc498f1400000000 stmt=select o_orderdate, o_custkey, o_comment
from tpch.orders
order by o_orderdate
I0314 00:15:16.506711 10629 coordinator.cc:474] f54227735548245d:fc498f1400000000] starting execution on 2 backends for query_id=f54227735548245d:fc498f1400000000
I0314 00:15:16.507216 24247 control-service.cc:148] f54227735548245d:fc498f1400000000] ExecQueryFInstances(): query_id=f54227735548245d:fc498f1400000000 coord=lv-desktop:27000 #instances=2
I0314 00:15:16.507802 10633 query-state.cc:948] f54227735548245d:fc498f1400000002] Executing instance. instance_id=f54227735548245d:fc498f1400000002 fragment_idx=1 per_fragment_instance_idx=1 coord_state_idx=0 #in-flight=1
I0314 00:15:16.507810 10629 coordinator.cc:533] f54227735548245d:fc498f1400000000] started execution on 2 backends for query_id=f54227735548245d:fc498f1400000000
I0314 00:15:16.507913 10634 query-state.cc:948] f54227735548245d:fc498f1400000000] Executing instance. instance_id=f54227735548245d:fc498f1400000000 fragment_idx=0 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=2
I0314 00:15:18.587622 24267 krpc-data-stream-mgr.cc:427] Reduced stream ID cache from 33 items, to 32, eviction took: 0
I0314 00:15:20.481271 10628 impala-beeswax-server.cc:215] get_results_metadata(): query_id=f54227735548245d:fc498f1400000000
F0314 00:15:21.669415 10634 reservation-tracker.cc:436] f54227735548245d:fc498f1400000000] Check failed: used_reservation_.Load() + child_reservations_.Load() <= reservation_.Load() (6291456 vs. 4194304) 4194304 + 2097152 > 4194304
Wrote minidump to /home/riza/workspace/impala/logs/cluster/minidumps/impalad/e521ac50-121b-49aa-716f458f-51920619.dmp
impalad.ERROR
Log file created at: 2021/03/13 22:41:15 Running on machine: lv-desktop Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg E0313 22:41:15.237749 24033 logging.cc:148] stderr will be logged to this file. 21/03/13 22:41:16 INFO util.JvmPauseMonitor: Starting JVM pause monitor F0314 00:15:21.669415 10634 reservation-tracker.cc:436] f54227735548245d:fc498f1400000000] Check failed: used_reservation_.Load() + child_reservations_.Load() <= reservation_.Load() (6291456 vs. 4194304) 4194304 + 2097152 > 4194304 *** Check failure stack trace: *** @ 0x549bf3c google::LogMessage::Fail() @ 0x549d82c google::LogMessage::SendToLog() @ 0x549b89a google::LogMessage::Flush() @ 0x549f498 google::LogMessageFatal::~LogMessageFatal() @ 0x2965d86 impala::ReservationTracker::CheckConsistency() @ 0x2964ea2 impala::ReservationTracker::TransferReservationTo() @ 0x29584d3 impala::BufferPool::ClientHandle::SaveReservation() @ 0x2f31cf2 impala::BufferedTupleStream::NextReadPage() @ 0x2f33051 impala::BufferedTupleStream::UnpinStream() @ 0x2fa0575 impala::SpillableRowBatchQueue::AddBatch() @ 0x2b6f2bc impala::BufferedPlanRootSink::Send() @ 0x24cc429 impala::FragmentInstanceState::ExecInternal() @ 0x24c842f impala::FragmentInstanceState::Exec() @ 0x240c567 impala::QueryState::ExecFInstance() @ 0x240a965 _ZZN6impala10QueryState15StartFInstancesEvENKUlvE_clEv @ 0x240f536 _ZN5boost6detail8function26void_function_obj_invoker0IZN6impala10QueryState15StartFInstancesEvEUlvE_vE6invokeERNS1_15function_bufferE @ 0x22b6621 boost::function0<>::operator()() @ 0x2926cb3 impala::Thread::SuperviseThread() @ 0x292f614 boost::_bi::list5<>::operator()<>() @ 0x292f538 boost::_bi::bind_t<>::operator()() @ 0x292f4f9 boost::detail::thread_data<>::run() @ 0x41a2f41 thread_proxy @ 0x7f6d1981f6da start_thread @ 0x7f6d160ea71e clone Wrote minidump to /home/riza/workspace/impala/logs/cluster/minidumps/impalad/e521ac50-121b-49aa-716f458f-51920619.dmp
I'm also attaching the resolved dump of e521ac50-121b-49aa-716f458f-51920619.dmp.
It looks like result spooling + sort query + low buffer_pool_limit used in test_with_unlimited_scratch_limit reveal some bug in BufferedPlanRootSink/BufferedTupleStream.
New row batch is added to BufferedPlanRootSink, but there is not enough memory. At the same time, all rows in the read_page_ of the read iterator has been fully read. The underlying BufferedTupleStream try to spill, but I suspect nothing got spilled. Nothing get freed including the read_page_ that has been fully read.
Attachments
Attachments
Issue Links
- is caused by
-
IMPALA-8890 DCHECK(!page->attached_to_output_batch) in SpillableRowBatchQueue::AddBatch
-
- Resolved
-
- is related to
-
-
- Resolved
-