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

Do not print write to tunnel which is already closed log if query is canceled expectedly before #4208

Open
XuHuaiyu opened this issue Mar 9, 2022 · 0 comments
Labels
type/enhancement The issue or PR belongs to an enhancement.

Comments

@XuHuaiyu
Copy link
Contributor

XuHuaiyu commented Mar 9, 2022

Enhancement

We can see from the log that the query is canceled, and all tunnels are closed.
If MPPTask.runImpl tries to write to the tunnel later, an exception write to tunnel which is already closed will be thrown.
The error logs will be printed in this case, which will make the users confused. The exception is actually expected.
Thus we should avoid print the error log for this case.

102869:[2022/03/08 20:08:42.330 +08:00] [WARN] [<unknown>] ["TaskManager:Begin cancel query: 431683357167058946"] [thread_id=512]
102870:[2022/03/08 20:08:42.330 +08:00] [WARN] [<unknown>] ["TaskManager:Remaining task in query 431683357167058946 are: <query:431683357167058946,task:3> "] [thread_id=512]
102871:[2022/03/08 20:08:42.330 +08:00] [WARN] [MPPTask.cpp:396] ["MPPTask:<query:431683357167058946,task:3> Begin cancel task: <query:431683357167058946,task:3>"] [thread_id=27115]
102872:[2022/03/08 20:08:42.330 +08:00] [ERROR] [<unknown>] ["MPPTask:<query:431683357167058946,task:3> tunnel3+-1 grpc writes failed."] [thread_id=450]
102873:[2022/03/08 20:08:42.331 +08:00] [WARN] [<unknown>] ["MPPTask:<query:431683357167058946,task:3> Finish cancel task from running"] [thread_id=27115]
102874:[2022/03/08 20:08:42.331 +08:00] [WARN] [<unknown>] ["TaskManager:Finish cancel query: 431683357167058946"] [thread_id=512]
102875-[2022/03/08 20:08:42.335 +08:00] [WARN] [CoprocessorHandler.cpp:112] ["CoprocessorHandler:grpc::Status DB::CoprocessorHandler::execute(): LockException: region 705, message: "] [thread_id=344]
102876-[2022/03/08 20:08:42.335 +08:00] [WARN] [CoprocessorHandler.cpp:112] ["CoprocessorHandler:grpc::Status DB::CoprocessorHandler::execute(): LockException: region 2153, message: "] [thread_id=308]
102877-[2022/03/08 20:08:42.335 +08:00] [WARN] [CoprocessorHandler.cpp:112] ["CoprocessorHandler:grpc::Status DB::CoprocessorHandler::execute(): LockException: region 698, message: "] [thread_id=294]
102878-[2022/03/08 20:08:42.335 +08:00] [WARN] [CoprocessorHandler.cpp:112] ["CoprocessorHandler:grpc::Status DB::CoprocessorHandler::execute(): LockException: region 565, message: "] [thread_id=337]
102879:[2022/03/08 20:08:42.387 +08:00] [ERROR] [MPPTask.cpp:332] ["MPPTask:<query:431683357167058946,task:3> task running meets error: DB::Exception: write to tunnel which is already closed,grpc writes failed. Stack Trace : 0. /tiflash/tiflash(StackTrace::StackTrace()+0x13) [0x4d34443]
102880-1. /tiflash/tiflash(DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int)+0x26) [0x4d31a46]
102881-2. /tiflash/tiflash(DB::MPPTunnelBase<grpc_impl::ServerWriter<mpp::MPPDataPacket> >::write(mpp::MPPDataPacket const&, bool)+0x56f) [0xa8912bf]
102882-3. /tiflash/tiflash(DB::MPPTunnelSetBase<DB::MPPTunnel>::write(tipb::SelectResponse&)+0x34) [0xa893a54]
102883-4. /tiflash/tiflash(void DB::StreamingDAGResponseWriter<std::__1::shared_ptr<DB::MPPTunnelSet> >::batchWrite<true>()+0x77) [0xa854ff7]
102884-5. /tiflash/tiflash(DB::UnionBlockInputStream<(DB::StreamUnionMode)0, true>::readSuffix()+0x4a) [0xa84eeda]
102885-6. /tiflash/tiflash(DB::MPPTask::runImpl()+0x986) [0xa87ee16]
102886-7. /tiflash/tiflash(std::__1::__packaged_task_func<auto DB::wrapInvocable<std::__1::function<void ()>&>(bool, std::__1::function<void ()>&)::'lambda'(), std::__1::allocator<auto DB::wrapInvocable<std::__1::function<void ()>&>(bool, std::__1::function<void ()>&)::'lambda'()>, void ()>::operator()()+0x6e) [0x4dfe16e]
102887-8. /tiflash/tiflash(std::__1::packaged_task<void ()>::operator()()+0x45) [0x4dfe2d5]
102888-9. /tiflash/tiflash(DB::executeTask(std::__1::unique_ptr<DB::IExecutableTask, std::__1::default_delete<DB::IExecutableTask> > const&)+0x78) [0x4d92128]
102889-10. /tiflash/tiflash(DB::DynamicThreadPool::fixedWork(unsigned long)+0xb5) [0x4d91ae5]
102890-11. /tiflash/tiflash(auto std::__1::thread DB::ThreadFactory::newThread<void (DB::DynamicThreadPool::*)(unsigned long), DB::DynamicThreadPool*, unsigned long&>(bool, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, void (DB::DynamicThreadPool::*&&)(unsigned long), DB::DynamicThreadPool*&&, unsigned long&)::'lambda'(auto&&...)::operator()<DB::DynamicThreadPool*, unsigned long>(auto&&...) const+0x121) [0x4d93151]
102891-12. /tiflash/tiflash() [0x4d92f79]
102892-13. /lib64/libpthread.so.0(+0x7ea5) [0x7f3ab86c8ea5]
102893-14. /lib64/libc.so.6(clone+0x6d) [0x7f3ab81db96d]
102894-"] [thread_id=135]
102895-[2022/03/08 20:08:42.422 +08:00] [ERROR] [Exception.cpp:64] ["MPPTask:Failed to write error DB::Exception: write to tunnel which is already closed,grpc writes failed. to tunnel: tunnel3+-1: Code: 0, e.displayText() = DB::Exception: write to tunnel which is already closed,grpc writes failed., e.what() = DB::Exception, Stack trace:
102896-
102897-0. /tiflash/tiflash(StackTrace::StackTrace()+0x13) [0x4d34443]
102898-1. /tiflash/tiflash(DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int)+0x26) [0x4d31a46]
102899-2. /tiflash/tiflash(DB::MPPTunnelBase<grpc_impl::ServerWriter<mpp::MPPDataPacket> >::write(mpp::MPPDataPacket const&, bool)+0x56f) [0xa8912bf]
102900-3. /tiflash/tiflash(DB::MPPTask::writeErrToAllTunnels(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)+0x76) [0xa8801e6]
102901-4. /tiflash/tiflash(DB::MPPTask::runImpl()+0xb49) [0xa87efd9]
102902-5. /tiflash/tiflash(std::__1::__packaged_task_func<auto DB::wrapInvocable<std::__1::function<void ()>&>(bool, std::__1::function<void ()>&)::'lambda'(), std::__1::allocator<auto DB::wrapInvocable<std::__1::function<void ()>&>(bool, std::__1::function<void ()>&)::'lambda'()>, void ()>::operator()()+0x6e) [0x4dfe16e]
102903-6. /tiflash/tiflash(std::__1::packaged_task<void ()>::operator()()+0x45) [0x4dfe2d5]
102904-7. /tiflash/tiflash(DB::executeTask(std::__1::unique_ptr<DB::IExecutableTask, std::__1::default_delete<DB::IExecutableTask> > const&)+0x78) [0x4d92128]
102905-8. /tiflash/tiflash(DB::DynamicThreadPool::fixedWork(unsigned long)+0xb5) [0x4d91ae5]
102906-9. /tiflash/tiflash(auto std::__1::thread DB::ThreadFactory::newThread<void (DB::DynamicThreadPool::*)(unsigned long), DB::DynamicThreadPool*, unsigned long&>(bool, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, void (DB::DynamicThreadPool::*&&)(unsigned long), DB::DynamicThreadPool*&&, unsigned long&)::'lambda'(auto&&...)::operator()<DB::DynamicThreadPool*, unsigned long>(auto&&...) const+0x121) [0x4d93151]
102907-10. /tiflash/tiflash() [0x4d92f79]
102908-11. /lib64/libpthread.so.0(+0x7ea5) [0x7f3ab86c8ea5]
102909-12. /lib64/libc.so.6(clone+0x6d) [0x7f3ab81db96d]
102910-"] [thread_id=135]
102911:[2022/03/08 20:08:42.422 +08:00] [ERROR] [<unknown>] ["TaskManager:The task <query:431683357167058946,task:3> cannot be found and fail to unregister"] [thread_id=135]
102912:[2022/03/08 20:08:42.422 +08:00] [WARN] [<unknown>] ["MPPTask:<query:431683357167058946,task:3> finish task which was cancelled before"] [thread_id=135]
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type/enhancement The issue or PR belongs to an enhancement.
Projects
None yet
Development

No branches or pull requests

1 participant