DB::Exception: Not found column (NOT_FOUND_COLUMN_IN_BLOCK) for SELECT ... FINAL SAMPLE #72498
Description
Describe the issue
After updating server from 23.3 to 24.3 we started to get an error NOT_FOUND_COLUMN_IN_BLOCK for some SELECT queries
(see simplified and reproducible example below).
Turning off allow_experimental_analyzer does not help.
It looks like the reason in the level of selected parts. If part has level 0 query is working, for parts with level > 0 query starts to throw the exception.
Pay attention on this diff in the log.
- Failed select (part.level > 0)
2024.11.26 18:30:01.011306 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Test> PartsSplitter: Non intersecting ranges in data parts 1 parts: [part all_1_2_1 with ranges [(0, 1)]]
2024.11.26 18:30:01.011312 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Test> PartsSplitter: Intersecting ranges in data parts 0 parts: []
- Working select (part.level = 0)
2024.11.26 18:29:42.776688 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Non intersecting ranges in data parts 0 parts: []
2024.11.26 18:29:42.776724 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Intersecting ranges in data parts 2 parts: [part all_1_1_0 with ranges [(0, 1)], part all_2_2_0 with ranges [(0, 1)]]
2024.11.26 18:29:42.776741 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Split intersecting ranges into 1 layers
Instead of OPTIMIZE ... FINAL just renaming part all_1_1_0 to all_1_1_1 on the disk and restart CH can be done to break the queries
How to reproduce
CH version 24.10.3
dev-vm.ru-central1.internal :) CREATE TABLE default.test_table03
(
`CounterID` UInt32,
`UserID` UInt64,
`Version` UInt64
)
ENGINE = ReplacingMergeTree(Version)
ORDER BY (CounterID, intHash32(UserID))
SAMPLE BY intHash32(UserID)
SETTINGS index_granularity = 8192
CREATE TABLE default.test_table03
(
`CounterID` UInt32,
`UserID` UInt64,
`Version` UInt64
)
ENGINE = ReplacingMergeTree(Version)
ORDER BY (CounterID, intHash32(UserID))
SAMPLE BY intHash32(UserID)
SETTINGS index_granularity = 8192
Query id: 4ea28152-ef93-4c5d-b209-94a168da091a
Ok.
0 rows in set. Elapsed: 0.025 sec.
dev-vm.ru-central1.internal :) insert into test_table03 SELECT * FROM generateRandom('`CounterID` UInt32, `UserID` UInt64, `Version` UInt64', 1, 10, 2) limit 10
INSERT INTO test_table03 SELECT *
FROM generateRandom('`CounterID` UInt32, `UserID` UInt64, `Version` UInt64', 1, 10, 2)
LIMIT 10
Query id: f0e25154-6859-41e4-9798-e0e581a9fd45
Ok.
0 rows in set. Elapsed: 0.003 sec.
dev-vm.ru-central1.internal :) SELECT *
FROM test_table03
FINAL
SAMPLE 1 / 2
SELECT *
FROM test_table03
FINAL
SAMPLE 1 / 2
Query id: 64964caf-db03-45da-bcd2-d3d07f9bd290
┌──CounterID─┬───────────────UserID─┬──────────────Version─┐
1. │ 153951766 │ 17642005186012218654 │ 7244842965196057084 │
2. │ 730412674 │ 9558594037060121162 │ 15539571320073754492 │
3. │ 1382038526 │ 1355609803008819271 │ 7390467479849635722 │
4. │ 2319105779 │ 18371568619324220532 │ 11652964532125973222 │
5. │ 4107652264 │ 8124171311239967992 │ 17267040165663451487 │
└────────────┴──────────────────────┴──────────────────────┘
5 rows in set. Elapsed: 0.003 sec.
dev-vm.ru-central1.internal :) insert into test_table03 SELECT * FROM generateRandom('`CounterID` UInt32, `UserID` UInt64, `Version` UInt64', 1, 10, 2) limit 10
INSERT INTO test_table03 SELECT *
FROM generateRandom('`CounterID` UInt32, `UserID` UInt64, `Version` UInt64', 1, 10, 2)
LIMIT 10
Query id: a5a7eb9b-9260-4eb2-be72-d0d1d38e89d8
Ok.
0 rows in set. Elapsed: 0.004 sec.
dev-vm.ru-central1.internal :) SELECT *
FROM test_table03
FINAL
SAMPLE 1 / 2
SELECT *
FROM test_table03
FINAL
SAMPLE 1 / 2
Query id: 02506f88-178d-4c34-b7f5-9b096cb3fc7e
┌──CounterID─┬───────────────UserID─┬──────────────Version─┐
1. │ 153951766 │ 17642005186012218654 │ 7244842965196057084 │
2. │ 730412674 │ 9558594037060121162 │ 15539571320073754492 │
3. │ 1382038526 │ 1355609803008819271 │ 7390467479849635722 │
4. │ 2319105779 │ 18371568619324220532 │ 11652964532125973222 │
5. │ 4107652264 │ 8124171311239967992 │ 17267040165663451487 │
└────────────┴──────────────────────┴──────────────────────┘
5 rows in set. Elapsed: 0.004 sec.
dev-vm.ru-central1.internal :) optimize table test_table03 FINAL
OPTIMIZE TABLE test_table03 FINAL
Query id: 9e6b2098-f733-4ed1-b58c-9648c7d0cceb
Ok.
0 rows in set. Elapsed: 0.003 sec.
dev-vm.ru-central1.internal :) SELECT *
FROM test_table03
FINAL
SAMPLE 1 / 2
SELECT *
FROM test_table03
FINAL
SAMPLE 1 / 2
Query id: c081af83-e0d5-4183-88cc-27911ce8d411
Elapsed: 0.003 sec.
Received exception from server (version 24.10.3):
Code: 10. DB::Exception: Received from localhost:9000. DB::Exception: Not found column intHash32(UserID): in block CounterID UInt32 UInt32(size = 0), UserID UInt64 UInt64(size = 0), Version UInt64 UInt64(size = 0). (NOT_FOUND_COLUMN_IN_BLOCK)
Error message and/or stacktrace
Failed query (part.level > 0)
2024.11.26 18:30:01.010508 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Debug> executeQuery: (from [::1]:59466) SELECT * FROM test_table03 FINAL SAMPLE 1 / 2 (stage: Complete)
2024.11.26 18:30:01.010810 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Trace> Planner: Query to stage Complete
2024.11.26 18:30:01.010938 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Trace> Planner: Query from stage FetchColumns to stage Complete
2024.11.26 18:30:01.011075 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Debug> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Key condition: unknown
2024.11.26 18:30:01.011191 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Filtering marks by primary and secondary keys
2024.11.26 18:30:01.011217 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Used generic exclusion search over index for part all_1_2_1 with 1 steps
2024.11.26 18:30:01.011252 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Debug> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Selected 1/1 parts by partition key, 1 parts by primary key, 1/1 marks by primary key, 1 marks to read from 1 ranges
2024.11.26 18:30:01.011278 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Test> PartsSplitter: Parts ranges before sort Part index 0 event Range Start range begin 0 end 1 value (85697048, 2989604029)
Part index 0 event Range End range begin 0 end 1 value (4107652264, 1403130518)
2024.11.26 18:30:01.011286 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Test> PartsSplitter: Parts ranges after sort Part index 0 event Range Start range begin 0 end 1 value (85697048, 2989604029)
Part index 0 event Range End range begin 0 end 1 value (4107652264, 1403130518)
2024.11.26 18:30:01.011306 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Test> PartsSplitter: Non intersecting ranges in data parts 1 parts: [part all_1_2_1 with ranges [(0, 1)]]
2024.11.26 18:30:01.011312 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Test> PartsSplitter: Intersecting ranges in data parts 0 parts: []
2024.11.26 18:30:01.011319 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Test> PartsSplitter: Split intersecting ranges into 0 layers
2024.11.26 18:30:01.011328 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Spreading mark ranges among streams (default reading)
2024.11.26 18:30:01.011355 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Test> MergeTreeReadPoolBase: Will use min_marks_per_task=24
2024.11.26 18:30:01.011364 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Reading 1 ranges in order from part all_1_2_1, approx. 10 rows starting from 0
2024.11.26 18:30:01.011676 [ 1500512 ] {c081af83-e0d5-4183-88cc-27911ce8d411} <Error> executeQuery: Code: 10. DB::Exception: Not found column intHash32(UserID): in block CounterID UInt32 UInt32(size = 0), UserID UInt64 UInt64(size = 0), Version UInt64 UInt64(size = 0). (NOT_FOUND_COLUMN_IN_BLOCK) (version 24.10.3.21 (official build)) (from [::1]:59466) (in query: SELECT * FROM test_table03 FINAL SAMPLE 1 / 2), Stack trace (when copying this message, always include the lines below):
0. DB::Exception::Exception(DB::Exception::MessageMasked&&, int, bool) @ 0x000000000cf7d73b
1. DB::Exception::Exception(PreformattedMessage&&, int) @ 0x0000000007ea888c
2. DB::Exception::Exception<String const&>(int, FormatStringHelperImpl<std::type_identity<String const&>::type>, String const&) @ 0x0000000007ec3c8b
3. DB::ActionsDAG::evaluatePartialResult(std::unordered_map<DB::ActionsDAG::Node const*, DB::ColumnWithTypeAndName, std::hash<DB::ActionsDAG::Node const*>, std::equal_to<DB::ActionsDAG::Node const*>, std::allocator<std::pair<DB::ActionsDAG::Node const* const, DB::ColumnWithTypeAndName>>>&, std::vector<DB::ActionsDAG::Node const*, std::allocator<DB::ActionsDAG::Node const*>> const&, unsigned long, bool) @ 0x0000000010af90f4
4. DB::ActionsDAG::updateHeader(DB::Block const&) const @ 0x0000000010af719d
5. DB::FilterTransform::transformHeader(DB::Block const&, DB::ActionsDAG const*, String const&, bool) @ 0x0000000012c38c13
6. DB::FilterTransform::FilterTransform(DB::Block const&, std::shared_ptr<DB::ExpressionActions>, String, bool, bool, std::shared_ptr<std::atomic<unsigned long>>) @ 0x0000000012c3912f
7. std::shared_ptr<DB::IProcessor> std::__function::__policy_invoker<std::shared_ptr<DB::IProcessor> (DB::Block const&)>::__call_impl<std::__function::__default_alloc_func<DB::ReadFromMergeTree::initializePipeline(DB::QueryPipelineBuilder&, DB::BuildQueryPipelineSettings const&)::$_0, std::shared_ptr<DB::IProcessor> (DB::Block const&)>>(std::__function::__policy_storage const*, DB::Block const&) @ 0x0000000012e15f43
8. DB::Pipe::addSimpleTransform(std::function<std::shared_ptr<DB::IProcessor> (DB::Block const&, DB::Pipe::StreamType)> const&)::$_0::operator()(DB::OutputPort*&, DB::Pipe::StreamType) const @ 0x00000000106c764e
9. DB::Pipe::addSimpleTransform(std::function<std::shared_ptr<DB::IProcessor> (DB::Block const&, DB::Pipe::StreamType)> const&) @ 0x00000000106c746d
10. DB::ReadFromMergeTree::initializePipeline(DB::QueryPipelineBuilder&, DB::BuildQueryPipelineSettings const&) @ 0x0000000012e095d5
11. DB::ISourceStep::updatePipeline(std::vector<std::unique_ptr<DB::QueryPipelineBuilder, std::default_delete<DB::QueryPipelineBuilder>>, std::allocator<std::unique_ptr<DB::QueryPipelineBuilder, std::default_delete<DB::QueryPipelineBuilder>>>>, DB::BuildQueryPipelineSettings const&) @ 0x0000000012dc18ca
12. DB::QueryPlan::buildQueryPipeline(DB::QueryPlanOptimizationSettings const&, DB::BuildQueryPipelineSettings const&) @ 0x0000000012ddfa33
13. DB::InterpreterSelectQueryAnalyzer::buildQueryPipeline() @ 0x00000000113d4b6a
14. DB::InterpreterSelectQueryAnalyzer::execute() @ 0x00000000113d443e
15. DB::executeQueryImpl(char const*, char const*, std::shared_ptr<DB::Context>, DB::QueryFlags, DB::QueryProcessingStage::Enum, DB::ReadBuffer*) @ 0x000000001173b483
16. DB::executeQuery(String const&, std::shared_ptr<DB::Context>, DB::QueryFlags, DB::QueryProcessingStage::Enum) @ 0x00000000117372ba
17. DB::TCPHandler::runImpl() @ 0x000000001292a1f4
18. DB::TCPHandler::run() @ 0x0000000012945658
19. Poco::Net::TCPServerConnection::start() @ 0x0000000015813427
20. Poco::Net::TCPServerDispatcher::run() @ 0x00000000158138b9
21. Poco::PooledThread::run() @ 0x00000000157e0421
22. Poco::ThreadImpl::runnableEntry(void*) @ 0x00000000157de9dd
23. ? @ 0x00007f20cac51ac3
24. ? @ 0x00007f20cace3850
Working query (part.level = 0)
2024.11.26 18:29:42.775278 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Debug> executeQuery: (from [::1]:59466) SELECT * FROM test_table03 FINAL SAMPLE 1 / 2 (stage: Complete)
2024.11.26 18:29:42.775563 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Trace> Planner: Query to stage Complete
2024.11.26 18:29:42.775665 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Trace> Planner: Query from stage FetchColumns to stage Complete
2024.11.26 18:29:42.775817 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Debug> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Key condition: unknown
2024.11.26 18:29:42.775939 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Filtering marks by primary and secondary keys
2024.11.26 18:29:42.776361 [ 1501160 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Used generic exclusion search over index for part all_1_1_0 with 1 steps
2024.11.26 18:29:42.776379 [ 1501218 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Used generic exclusion search over index for part all_2_2_0 with 1 steps
2024.11.26 18:29:42.776619 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Debug> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Selected 2/2 parts by partition key, 2 parts by primary key, 2/2 marks by primary key, 2 marks to read from 2 r
anges
2024.11.26 18:29:42.776660 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Parts ranges before sort Part index 0 event Range Start range begin 0 end 1 value (85697048, 2989604029)
Part index 0 event Range End range begin 0 end 1 value (4107652264, 1403130518)
Part index 1 event Range Start range begin 0 end 1 value (85697048, 2989604029)
Part index 1 event Range End range begin 0 end 1 value (4107652264, 1403130518)
2024.11.26 18:29:42.776673 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Parts ranges after sort Part index 0 event Range Start range begin 0 end 1 value (85697048, 2989604029)
Part index 1 event Range Start range begin 0 end 1 value (85697048, 2989604029)
Part index 0 event Range End range begin 0 end 1 value (4107652264, 1403130518)
Part index 1 event Range End range begin 0 end 1 value (4107652264, 1403130518)
2024.11.26 18:29:42.776688 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Non intersecting ranges in data parts 0 parts: []
2024.11.26 18:29:42.776724 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Intersecting ranges in data parts 2 parts: [part all_1_1_0 with ranges [(0, 1)], part all_2_2_0 with ranges [(0, 1)]]
2024.11.26 18:29:42.776741 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Split intersecting ranges into 1 layers
2024.11.26 18:29:42.776749 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> PartsSplitter: Layer 0 2 parts: [part all_1_1_0 with ranges [(0, 1)], part all_2_2_0 with ranges [(0, 1)]] filter values in (-inf, +inf])
2024.11.26 18:29:42.776783 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> MergeTreeReadPoolBase: Will use min_marks_per_task=8
2024.11.26 18:29:42.776794 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> MergeTreeReadPoolBase: Will use min_marks_per_task=8
2024.11.26 18:29:42.776806 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Reading 1 ranges in order from part all_1_1_0, approx. 10 rows starting from 0
2024.11.26 18:29:42.776824 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Trace> default.test_table03 (d4db5ca2-d8b3-4917-93c7-dc912115f273) (SelectExecutor): Reading 1 ranges in order from part all_2_2_0, approx. 10 rows starting from 0
2024.11.26 18:29:42.777825 [ 1501200 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> MergeTreeMarksLoader: Loading marks from path data.cmrk3
2024.11.26 18:29:42.777908 [ 1501226 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> MergeTreeRangeReader: First reader returned: num_rows: 10, columns: 3, total_rows_per_granule: 10, no filter, column[0]: UInt32(size = 10), column[1]: UInt64(size = 10), column[2]: UInt64
(size = 10), requested columns: CounterID, UserID, Version
2024.11.26 18:29:42.777944 [ 1501226 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> MergeTreeRangeReader: read() returned num_rows: 10, columns: 3, total_rows_per_granule: 10, no filter, column[0]: UInt32(size = 10), column[1]: UInt64(size = 10), column[2]: UInt64(size =
10), sample block CounterID, UserID, Version
2024.11.26 18:29:42.778018 [ 1501200 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> MergeTreeRangeReader: First reader returned: num_rows: 10, columns: 3, total_rows_per_granule: 10, no filter, column[0]: UInt32(size = 10), column[1]: UInt64(size = 10), column[2]: UInt64
(size = 10), requested columns: CounterID, UserID, Version
2024.11.26 18:29:42.778039 [ 1501200 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Test> MergeTreeRangeReader: read() returned num_rows: 10, columns: 3, total_rows_per_granule: 10, no filter, column[0]: UInt32(size = 10), column[1]: UInt64(size = 10), column[2]: UInt64(size =
10), sample block CounterID, UserID, Version
2024.11.26 18:29:42.778602 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Debug> executeQuery: Read 20 rows, 400.00 B in 0.003349 sec., 5971.931919976112 rows/sec., 116.64 KiB/sec.
2024.11.26 18:29:42.778807 [ 1500512 ] {02506f88-178d-4c34-b7f5-9b096cb3fc7e} <Debug> TCPHandler: Processed in 0.004004294 sec.