-
Notifications
You must be signed in to change notification settings - Fork 8.3k
Thread leak (TCPHandler) #38474
Copy link
Copy link
Closed
Labels
testingSpecial issue with list of bugs found by CISpecial issue with list of bugs found by CI
Description
==================
WARNING: ThreadSanitizer: thread leak (pid=643)
Thread T845 'TCPHandler' (tid=10064, finished) created by thread T250 at:
#0 pthread_create <null> (clickhouse+0xb31eb2d) (BuildId: ff6deb04352baabe)
#1 Poco::ThreadImpl::startImpl(Poco::SharedPtr<Poco::Runnable, Poco::ReferenceCounter, Poco::ReleasePolicy<Poco::Runnable> >) build_docker/../contrib/poco/Foundation/src/Thread_POSIX.cpp:202:6 (clickhouse+0x1ef077c2) (BuildId: ff6deb04352baabe)
#2 Poco::Thread::start(Poco::Runnable&) build_docker/../contrib/poco/Foundation/src/Thread.cpp:128:2 (clickhouse+0x1ef0904c) (BuildId: ff6deb04352baabe)
#3 Poco::PooledThread::start() build_docker/../contrib/poco/Foundation/src/ThreadPool.cpp:85:10 (clickhouse+0x1ef0d126) (BuildId: ff6deb04352baabe)
#4 Poco::ThreadPool::getThread() build_docker/../contrib/poco/Foundation/src/ThreadPool.cpp:461:14 (clickhouse+0x1ef0d126)
#5 Poco::ThreadPool::startWithPriority(Poco::Thread::Priority, Poco::Runnable&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) build_docker/../contrib/poco/Foundation/src/ThreadPool.cpp:365:2 (clickhouse+0x1ef0d527) (BuildId: ff6deb04352baabe)
#6 Poco::Net::TCPServerDispatcher::enqueue(Poco::Net::StreamSocket const&) build_docker/../contrib/poco/Net/src/TCPServerDispatcher.cpp:152:17 (clickhouse+0x1ecc052e) (BuildId: ff6deb04352baabe)
#7 Poco::Net::TCPServer::run() build_docker/../contrib/poco/Net/src/TCPServer.cpp:148:21 (clickhouse+0x1ecbf047) (BuildId: ff6deb04352baabe)
#8 Poco::(anonymous namespace)::RunnableHolder::run() build_docker/../contrib/poco/Foundation/src/Thread.cpp:55:11 (clickhouse+0x1ef0964f) (BuildId: ff6deb04352baabe)
#9 Poco::ThreadImpl::runnableEntry(void*) build_docker/../contrib/poco/Foundation/src/Thread_POSIX.cpp:345:27 (clickhouse+0x1ef07d8b) (BuildId: ff6deb04352baabe)
SUMMARY: ThreadSanitizer: thread leak (/usr/bin/clickhouse+0xb31eb2d) (BuildId: ff6deb04352baabe) in pthread_create
==================
zgrep -Fa "[ 10064 ]" clickhouse-server.stress.log.gz | tail -50
2022.06.27 19:14:39.634255 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Trace> ContextAccess (default): Access granted: CREATE DATABASE ON test_puuot9.*
2022.06.27 19:14:39.635504 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Information> DatabaseAtomic (test_puuot9): Metadata processed, database test_puuot9 has 0 tables and 0 dictionaries in total.
2022.06.27 19:14:39.635566 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Information> TablesLoader: Parsed metadata of 0 tables in 1 databases in 0.000203696 sec
2022.06.27 19:14:39.635622 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Test> TablesLoader: Have 0 independent tables:
2022.06.27 19:14:39.635659 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Test> TablesLoader: Have 0 independent tables:
2022.06.27 19:14:39.635695 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Information> TablesLoader: Loading 0 tables with 0 dependency level
2022.06.27 19:14:39.635737 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Information> DatabaseAtomic (test_puuot9): Starting up tables.
2022.06.27 19:14:39.636234 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Debug> DynamicQueryHandler: Done processing query
2022.06.27 19:14:39.639679 [ 10064 ] {c0a004f5-ba61-42cd-9b08-f6d9941ed326} <Debug> MemoryTracker: Peak memory usage (for query): 1.00 MiB.
2022.06.27 19:14:39.639815 [ 10064 ] {} <Debug> MemoryTracker: Peak memory usage (for query): 1.00 MiB.
2022.06.27 19:14:39.639909 [ 10064 ] {} <Debug> HTTP-Session: 50b9622d-d92a-4c9e-a9a7-632aea76cebf Destroying unnamed session
2022.06.27 19:14:40.486714 [ 10064 ] {} <Trace> HTTPHandler-factory: HTTP Request for HTTPHandler-factory. Method: POST, Address: [::1]:35116, User-Agent: (none), Length: 0, Content Type: , Transfer Encoding: identity, X-Forwarded-For: (none)
2022.06.27 19:14:40.487159 [ 10064 ] {} <Trace> DynamicQueryHandler: Request URI: /?allow_experimental_database_replicated=1&query=DROP+DATABASE+test_gp9gsm&database=system&connect_timeout=598&receive_timeout=598&send_timeout=598&http_connection_timeout=598&http_receive_timeout=598&http_send_timeout=598&log_comment=02302_s3_file_pruning.sql
2022.06.27 19:14:40.487305 [ 10064 ] {} <Debug> HTTP-Session: 4036e40d-12f3-4814-90a0-94822ff3dedf Authenticating user 'default' from [::1]:35116
2022.06.27 19:14:40.487595 [ 10064 ] {} <Debug> HTTP-Session: 4036e40d-12f3-4814-90a0-94822ff3dedf Authenticated with global context as user 94309d50-4f52-5250-31bd-74fecac179db
2022.06.27 19:14:40.493948 [ 10064 ] {984606eb-cae4-40d4-9ae9-4c50fc3ce6b8} <Debug> executeQuery: (from [::1]:35116) (comment: 02302_s3_file_pruning.sql) DROP DATABASE test_gp9gsm (stage: Complete)
2022.06.27 19:14:40.494162 [ 10064 ] {984606eb-cae4-40d4-9ae9-4c50fc3ce6b8} <Trace> ContextAccess (default): Access granted: DROP DATABASE ON test_gp9gsm.*
2022.06.27 19:14:40.583326 [ 10064 ] {984606eb-cae4-40d4-9ae9-4c50fc3ce6b8} <Debug> DynamicQueryHandler: Done processing query
2022.06.27 19:14:40.585370 [ 10064 ] {984606eb-cae4-40d4-9ae9-4c50fc3ce6b8} <Debug> MemoryTracker: Peak memory usage (for query): 1.00 MiB.
2022.06.27 19:14:40.585462 [ 10064 ] {} <Debug> MemoryTracker: Peak memory usage (for query): 1.00 MiB.
2022.06.27 19:14:40.585520 [ 10064 ] {} <Debug> HTTP-Session: 4036e40d-12f3-4814-90a0-94822ff3dedf Destroying unnamed session
2022.06.27 19:15:00.226252 [ 10064 ] {} <Trace> TCPHandlerFactory: TCP Request. Address: [::1]:34062
2022.06.27 19:15:00.248440 [ 10064 ] {} <Debug> TCPHandler: Connected ClickHouse client version 22.7.0, revision: 54456, database: test_voh2z3, user: u02294.
2022.06.27 19:15:00.248576 [ 10064 ] {} <Debug> TCP-Session: 51cfd390-f2d6-4d00-b99f-d44765db0881 Authenticating user 'u02294' from [::1]:34062
2022.06.27 19:15:00.248676 [ 10064 ] {} <Debug> TCP-Session: 51cfd390-f2d6-4d00-b99f-d44765db0881 Authenticated with global context as user 2c40c8e1-a161-90bd-4874-27cc5f63119d
2022.06.27 19:15:00.248767 [ 10064 ] {} <Debug> TCP-Session: 51cfd390-f2d6-4d00-b99f-d44765db0881 Creating session context with user_id: 2c40c8e1-a161-90bd-4874-27cc5f63119d
2022.06.27 19:15:04.796915 [ 10064 ] {} <Debug> TCP-Session: 51cfd390-f2d6-4d00-b99f-d44765db0881 Creating query context from session context, user_id: 2c40c8e1-a161-90bd-4874-27cc5f63119d, parent context user: u02294
2022.06.27 19:15:05.666682 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> executeQuery: (from [::1]:34062, user: u02294) (comment: 02294_overcommit_overflow.sh) SELECT number FROM numbers(130000) GROUP BY number SETTINGS max_memory_usage_for_user=5000000,memory_overcommit_ratio_denominator=2000000000000000000,memory_usage_overcommit_max_wait_microseconds=500 (stage: Complete)
2022.06.27 19:15:10.018819 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Trace> ContextAccess (u02294): Access granted: CREATE TEMPORARY TABLE ON *.*
2022.06.27 19:15:12.572547 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
2022.06.27 19:15:12.573066 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Trying to choose query to stop from 9 queries
2022.06.27 19:15:12.573137 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 0/2000000000000000000
2022.06.27 19:15:12.573184 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 0/2000000000000000000
2022.06.27 19:15:12.573220 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 0/2000000000000000000
2022.06.27 19:15:12.573251 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 0/2000000000000000000
2022.06.27 19:15:12.573281 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 2101278/2000000000000000000
2022.06.27 19:15:12.573312 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 2101278/2000000000000000000
2022.06.27 19:15:12.573342 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 0/2000000000000000000
2022.06.27 19:15:12.573371 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 0/2000000000000000000
2022.06.27 19:15:12.573400 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Query has ratio 2101278/2000000000000000000
2022.06.27 19:15:12.573431 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Selected to stop query with overcommit ratio 2101278/2000000000000000000
2022.06.27 19:15:12.574046 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> UserOvercommitTracker: Memory was not freed within timeout
2022.06.27 19:15:44.143125 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Error> executeQuery: Code: 241. DB::Exception: Memory limit (for user) exceeded: would use 6.01 MiB (attempt to allocate chunk of 2101278 bytes), maximum: 4.77 MiB. OvercommitTracker decision: Waiting timeout for memory to be freed is reached.. (MEMORY_LIMIT_EXCEEDED) (version 22.7.1.1) (from [::1]:34062) (comment: 02294_overcommit_overflow.sh) (in query: SELECT number FROM numbers(130000) GROUP BY number SETTINGS max_memory_usage_for_user=5000000,memory_overcommit_ratio_denominator=2000000000000000000,memory_usage_overcommit_max_wait_microseconds=500), Stack trace (when copying this message, always include the lines below):
2022.06.27 19:15:44.162817 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Error> TCPHandler: Code: 241. DB::Exception: Memory limit (for user) exceeded: would use 6.01 MiB (attempt to allocate chunk of 2101278 bytes), maximum: 4.77 MiB. OvercommitTracker decision: Waiting timeout for memory to be freed is reached.. (MEMORY_LIMIT_EXCEEDED), Stack trace (when copying this message, always include the lines below):
2022.06.27 19:15:44.198689 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Warning> TCPHandler: Client has gone away.
2022.06.27 19:15:44.208398 [ 10064 ] {8f344ba3-cd8d-455c-8a43-dab96368b8a2} <Debug> MemoryTracker: Peak memory usage (for query): 2.00 MiB.
2022.06.27 19:15:44.208489 [ 10064 ] {} <Debug> MemoryTracker: Peak memory usage (for query): 2.00 MiB.
2022.06.27 19:15:44.208550 [ 10064 ] {} <Debug> TCPHandler: Processed in 42.965048756 sec.
2022.06.27 19:15:44.208692 [ 10064 ] {} <Debug> TCPHandler: Done processing connection.
2022.06.27 19:15:44.229543 [ 10064 ] {} <Debug> TCP-Session: 51cfd390-f2d6-4d00-b99f-d44765db0881 Destroying unnamed session
Reactions are currently unavailable
Metadata
Metadata
Assignees
Labels
testingSpecial issue with list of bugs found by CISpecial issue with list of bugs found by CI