Skip to content

Thread leak (TCPHandler) #38474

@tavplubix

Description

@tavplubix

https://s3.amazonaws.com/clickhouse-test-reports/38335/fe1b1aa77ba89d68abebc62dac536dee17d4ddc9/stress_test__thread__actions_.html

==================
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

Metadata

Metadata

Assignees

Labels

testingSpecial issue with list of bugs found by CI

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions