Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix system.query_views_log for MVs that are pushed from background threads #46668

Merged
merged 2 commits into from
Apr 7, 2023

Conversation

azat
Copy link
Collaborator

@azat azat commented Feb 21, 2023

Changelog category (leave one):

  • Bug Fix (user-visible misbehavior in official stable or prestable release)

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Fix system.query_views_log for MVs that are pushed from background threads (Buffer, Distributed, system.*_log)

Some of such places:

  • push from Buffer
  • push from Distributed sends
  • system.*_log workers

Before #47564 it simply does not work, but after it throws LOGICAL_ERROR
in such situation.

v2: remove expired() check after #46709 got merged
v3: use ThreadGroupStatus ctor with ContextPtr (after #47564)

Cc: @Algunenano
Fixes: #47311

@robot-clickhouse-ci-2 robot-clickhouse-ci-2 added the pr-bugfix Pull request with bugfix, not backported by default label Feb 21, 2023
@azat azat marked this pull request as draft February 22, 2023 09:40
@azat
Copy link
Collaborator Author

azat commented Feb 22, 2023

Stateless tests flaky check (asan) — fail: 12, passed: 89

The failure is real, this is because the query context was wrong, here is a fix - #46709

@azat azat force-pushed the fix-query_views_log-from-bg branch from 015991b to 210f25b Compare February 23, 2023 07:36
@azat azat marked this pull request as ready for review February 23, 2023 07:36
@azat
Copy link
Collaborator Author

azat commented Feb 23, 2023

Stress test (asan) — Sanitizer assert (in stderr.log)

==1657==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x61b000b958b8 at pc 0x000035c57643 bp 0x7f9538821270 sp 0x7f9538821268
READ of size 8 at 0x61b000b958b8 thread T1967
    #0 0x35c57642 in std::__1::shared_ptr<DB::InternalTextLogsQueue>::get[abi:v15000]() const build_docker/../contrib/llvm-project/libcxx/include/__memory/shared_ptr.h:801:16
    #1 0x35c57642 in std::__1::shared_ptr<DB::InternalTextLogsQueue>::operator bool[abi:v15000]() const build_docker/../contrib/llvm-project/libcxx/include/__memory/shared_ptr.h:833:16
    #2 0x35c57642 in DB::TCPHandler::sendLogs() build_docker/../src/Server/TCPHandler.cpp:1943:10
    #3 0x35c72e50 in DB::TCPHandler::runImpl()::$_2::operator()() const build_docker/../src/Server/TCPHandler.cpp:304:21
    #4 0x35c72e50 in decltype(std::declval<DB::TCPHandler::runImpl()::$_2&>()()) std::__1::__invoke[abi:v15000]<DB::TCPHandler::runImpl()::$_2&>(DB::TCPHandler::runImpl()::$_2&) build_docker/../contrib/llvm-project/libcxx/include/__functional/invoke.h:394:23
    #5 0x35c72e50 in void std::__1::__invoke_void_return_wrapper<void, true>::__call<DB::TCPHandler::runImpl()::$_2&>(DB::TCPHandler::runImpl()::$_2&) build_docker/../contrib/llvm-project/libcxx/include/__functional/invoke.h:479:9
    #6 0x35c72e50 in std::__1::__function::__default_alloc_func<DB::TCPHandler::runImpl()::$_2, void ()>::operator()[abi:v15000]() build_docker/../contrib/llvm-project/libcxx/include/__functional/function.h:235:12
    #7 0x35c72e50 in void std::__1::__function::__policy_invoker<void ()>::__call_impl<std::__1::__function::__default_alloc_func<DB::TCPHandler::runImpl()::$_2, void ()>>(std::__1::__function::__policy_storage const*) build_docker/../contrib/llvm-project/libcxx/include/__functional/function.h:716:16
    #8 0x206bc6bb in SignalListener::onFault(int, siginfo_t const&, ucontext_t*, StackTrace const&, unsigned int, DB::ThreadStatus*) const build_docker/../src/Daemon/BaseDaemon.cpp:409:25
    #9 0x206b83b0 in SignalListener::run()::'lambda'()::operator()() const build_docker/../src/Daemon/BaseDaemon.cpp:257:41
    #10 0x206b83b0 in decltype(std::declval<SignalListener::run()::'lambda'()>()()) std::__1::__invoke[abi:v15000]<SignalListener::run()::'lambda'()>(SignalListener::run()::'lambda'()&&) build_docker/../contrib/llvm-project/libcxx/include/__functional/invoke.h:394:23
    #11 0x206b83b0 in void std::__1::__thread_execute[abi:v15000]<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, SignalListener::run()::'lambda'()>(std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, SignalListener::run()::'lambda'()>&, std::__1::__tuple_indices<>) build_docker/../contrib/llvm-project/libcxx/include/thread:284:5
    #12 0x206b83b0 in void* std::__1::__thread_proxy[abi:v15000]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, SignalListener::run()::'lambda'()>>(void*) build_docker/../contrib/llvm-project/libcxx/include/thread:295:5
    #13 0x7fa726d7a608 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x8608) (BuildId: 7b4536f41cdaa5888408e82d0836e33dcf436466)
    #14 0x7fa726c9f132 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x11f132) (BuildId: 1878e6b475720c7c51969e69ab2d276fae6d1dee)

Address 0x61b000b958b8 is a wild pointer inside of access range of size 0x000000000008.
SUMMARY: AddressSanitizer: heap-buffer-overflow build_docker/../contrib/llvm-project/libcxx/include/__memory/shared_ptr.h:801:16 in std::__1::shared_ptr<DB::InternalTextLogsQueue>::get[abi:v15000]() const

And also

/var/log/clickhouse-server/clickhouse-server.err.log:2023.02.23 12:21:58.078097 [ 2313 ] {48af83d8-51f5-482f-83cc-c78191b54095} <Fatal> : Logical error: 'Operation `completePartAndResetDownloader` can be done only by downloader. (CallerId: None:2313, downloader id: 48af83d8-51f5-482f-83cc-c78191b54095:2313)'.
/var/log/clickhouse-server/clickhouse-server.err.log:2023.02.23 12:21:58.079360 [ 2287 ] {48af83d8-51f5-482f-83cc-c78191b54095} <Fatal> : Logical error: 'Operation `write` can be done only by downloader. (CallerId: None:2287, downloader id: 48af83d8-51f5-482f-83cc-c78191b54095:2287)'.
/var/log/clickhouse-server/clickhouse-server.err.log:2023.02.23 12:21:58.079684 [ 2381 ] {48af83d8-51f5-482f-83cc-c78191b54095} <Fatal> : Logical error: 'Operation `completePartAndResetDownloader` can be done only by downloader. (CallerId: None:2381, downloader id: 48af83d8-51f5-482f-83cc-c78191b54095:2381)'.
/var/log/clickhouse-server/clickhouse-server.err.log:2023.02.23 12:21:58.079701 [ 2332 ] {48af83d8-51f5-482f-83cc-c78191b54095} <Fatal> : Logical error: 'Operation `write` can be done only by downloader. (CallerId: None:2332, downloader id: 48af83d8-51f5-482f-83cc-c78191b54095:2332)'.

Seems that it is a known issue (#46624 (comment))

Stress test (debug) — Killed by signal (in clickhouse-server.log)

 [ 124279 ] {} <Fatal> BaseDaemon: (version 23.2.1.1, build id: 23BCEF8A5D6FACFF75D5CB79CBECD30FFC68ECF1) (from thread 1628) (query_id: 9c694f24-aa57-4652-a161-8503bef89657::202302_195_208_1) (query: ) Received signal Illegal instruction (4)
 [ 124279 ] {} <Fatal> BaseDaemon: Illegal operand.
 [ 124279 ] {} <Fatal> BaseDaemon: Stack trace: 0x30ed4a68 0x30ed4f84 0x30ed471b 0x21ad0d05 0x2c2155e1 0x2c21552d 0x2c2154d5 0x2c2154b9 0x2c21512e 0x1919ce54 0x1919cdf9 0x21dee86c 0x21dee7aa 0x21dee775 0x21dee74d 0x21dee6f5 0x21dee579 0x21dee3af 0x21dee2d9 0x21dedcb5 0x21dee1f8 0x2c20aec7 0x2b6ac4e7 0x2b6af48e 0x2b6af435 0x2b6af419 0x2b6af12e 0x1919ce54 0x1919cdf9 0x28e20d0c 0x28e250ed 0x28e25095 
 [ 124279 ] {} <Fatal> BaseDaemon: 4. /build/build_docker/../contrib/llvm-project/compiler-rt/lib/gwp_asan/platform_specific/utilities_posix.cpp:27: gwp_asan::die(char const*) @ 0x30ed4a68 in /usr/bin/clickhouse
 [ 124279 ] {} <Fatal> BaseDaemon: 5. /build/build_docker/../contrib/llvm-project/compiler-rt/lib/gwp_asan/platform_specific/guarded_pool_allocator_posix.cpp:98: gwp_asan::GuardedPoolAllocator::deallocateInGuardedPool(void*, unsigned long) const @ 0x30ed4f84 in /usr/bin/clickhouse
 [ 124279 ] {} <Fatal> BaseDaemon: 6. /build/build_docker/../contrib/llvm-project/compiler-rt/lib/gwp_asan/guarded_pool_allocator.cpp:322: gwp_asan::GuardedPoolAllocator::deallocate(void*) @ 0x30ed471b in /usr/bin/clickhouse

@azat
Copy link
Collaborator Author

azat commented Mar 15, 2023

I've just rebased. Can someone take a look please?

@azat
Copy link
Collaborator Author

azat commented Apr 4, 2023

Kind ping on this one, thanks.

@azat azat force-pushed the fix-query_views_log-from-bg branch 3 times, most recently from f442129 to cfd4a1a Compare April 4, 2023 13:40
@azat
Copy link
Collaborator Author

azat commented Apr 4, 2023

After #46709 the patch became cleaner, no more icky expired() check

@azat azat force-pushed the fix-query_views_log-from-bg branch from cfd4a1a to d84564d Compare April 4, 2023 15:31
…reads

Some of such places:
- push from Buffer
- push from Distributed sends
- system.*_log workers

Before ClickHouse#47564 it simply does not work, but after it throws LOGICAL_ERROR
in such situation.

v2: remove expired() check after ClickHouse#46709 got merged
v3: use ThreadGroupStatus ctor with ContextPtr (after ClickHouse#47564)
Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
else
running_group = std::make_shared<ThreadGroupStatus>();
if (!running_group)
running_group = std::make_shared<ThreadGroupStatus>(context);
Copy link
Member

@CheSema CheSema Apr 6, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you help with the question? When there is a current_thread->getThreadGroup and when there is no group in current thread?

One more question, in case when current_thread do not have TG, why is it right to make a TG for each view instead make one for all?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you help with the question? When there is a current_thread->getThreadGroup and when there is no group in current thread?

In case of background threads, i.e. Buffer flush/Distributed async INSERT

One more question, in case when current_thread do not have TG, why is it right to make a TG for each view insted make one for all?

Basically you are right here, it should be one ThreadGroupStatus, but for this particular place it should not make any difference, and making one ThreadGroupStatus for all views will make the code more complex, since there is not only multiple views, but it is possible to have nested views, so this function can be called recursively, while moving ThreadGroupStatus into the caller will split the code and make it less cleaner, plus you will need to pass to the function.

Copy link
Member

@CheSema CheSema Apr 7, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh I see. The is recursion call buildPushingToViewsChain. And that call appears 6 times in the code. Actually, as for me, it not so much to touch. And only one of them is trigger recursion: src/Interpreters/InterpreterInsertQuery.cpp:276.

In order to achieve one TG for all, we could either pass it through the function args buildPushingToViewsChain.

Or:

Move the block

        ThreadGroupStatusPtr running_group;
        if (current_thread)
            running_group = current_thread->getThreadGroup();
        if (!running_group)
            running_group = std::make_shared<ThreadGroupStatus>(context);

out of the for loop. Then, when we had to make new TG, bind current thread with this new TG with ThreadGroupSwitcher for the scope of buildPushingToViewsChain. That makes following recursive calls to see the new TG. (Or rewrite it in other similat way: if no current_thread->getThreadGroup(), then create it and attach temporarily)

Actually, all this things about finding/creating/attaching TG to the thread should be done between (or inside) InterpreterInsertQuery::buildChainImpl and buildPushingToViewsChain. In that way it looks more simple, without recursion context in the mind.

How do you see this? I do not insist for such approach. You are solving specific problem and the way is OK.
However one TG for MVs allows to collect all the memory accounting and profiles counters in one place: that TG. In case if that had been done in scope if query, all that information would be binded to that query. Your solution already do that binding, that is cool.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One thing: no need to use ThreadGroupSwitcher as long as we bind new thread group to the thread without thread group. That binding could be permanent.

Copy link
Collaborator Author

@azat azat Apr 7, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Then, when we had to make new TG, bind current thread with this new TG with ThreadGroupSwitcher for the scope of buildPushingToViewsChain. That makes following recursive calls to see the new TG. (Or rewrite it in other similat way: if no current_thread->getThreadGroup(), the create it add attach temporarily)

Well, it will work, but this implicit usage looks not clean.

Actually, all this things about finding/creating/attaching TG to the thread should be done between (or inside) InterpreterInsertQuery::buildChainImpl and buildPushingToViewsChain. In that way it looks more simple, without recursion context in the mind.

The reason I kept it in buildPushingToViewsChain, because it play low level games to manipulate the ThreadStatus, and this thing cannot moved to the InterpreterInsertQuery.

And this place will be moved to the InterpreterInsertQuery, then there will be two different places that will do this low level stuff, at first I thought that this is a bad idea, but while writing this paragraph, I changed my mind, so I guess it is OK.

One thing: no need to use ThreadGroupSwitcher as long as we bind new thread group to the thread without thread group. That binding could be permanent.

Yes, make sense, missed the patches where MemoryTrackerThreadSwitcher had been renamed to ThreadGroupSwitcher.

But I found it odd that it is located in the MergeTree code, so what I'm going to do is:

  • move ThreadGroupSwitcher into a separate file
  • rename ThreadGroupStatus to ThreadGroup
  • fix this place with multiple TG attached here

But I think it is better to do this on top of this PR in a separate one (since this includes some refactoring and is not a bugfix anymore, and so if there will be intention to backport this patch this can be done easily), @CheSema objections?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds good!
ThreadGroupSwitcher deserve better place indeed.
However here is it has no use since we create and bind designated TG only if there is no query scope TG. That binding could be permanent without ThreadGroupSwitcher. The other case: if there is a query scope TG, we attach it to all MV's thread statuses, in other words we reuse it.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That binding could be permanent without ThreadGroupSwitcher

Yes, indeed.

So here it is - #48543

@CheSema CheSema merged commit 0503ed6 into ClickHouse:master Apr 7, 2023
146 checks passed
@azat azat deleted the fix-query_views_log-from-bg branch April 7, 2023 12:59
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
pr-bugfix Pull request with bugfix, not backported by default
Projects
None yet
Development

Successfully merging this pull request may close these issues.

query_views_log does not get populated when using a Materialized View attached to a Kafka table
5 participants