Skip to content

Instantly share code, notes, and snippets.

@Slach

Slach/README.md

Last active January 25, 2021 11:04
Show Gist options
  • Save Slach/a7f2946a108883f6b1d5585b1b5b6b0d to your computer and use it in GitHub Desktop.
Save Slach/a7f2946a108883f6b1d5585b1b5b6b0d to your computer and use it in GitHub Desktop.
Download ZIP
DROP TABLE default.any_non_exists_name ON CLUSTER SYNC - doesn't work
Raw
README.md

ClickHouse 21.1.2 DROP TABLE default.test_repl ON CLUSTER 'default' SYNC failed for Atomic

Steps for reproduce

bash -x ./reproduce.sh

Expected Result

successfull drop table

Actual Result

Code: 159. DB::Exception: Received from localhost:9000. 
DB::Exception: Watching task /clickhouse/task_queue/ddl/query-0000000001 is executing longer than distributed_ddl_task_timeout (=180) seconds. There are 1 unfinished hosts (0 of them are currently active), they are going to execute the query in background.
Raw
atomic_delay_before_drop.xml
<yandex>
<database_atomic_delay_before_drop_table_sec>1</database_atomic_delay_before_drop_table_sec>
</yandex>
Raw
atomic_drop_detach_sync.xml
<yandex>
<profile>
<default>
<database_atomic_wait_for_drop_and_detach_synchronously>1</database_atomic_wait_for_drop_and_detach_synchronously>
</default>
</profile>
</yandex>
Raw
clickhouse-0-0.err.log
2021.01.25 11:01:04.697799 [ 44 ] {} <Warning> Access(local directory): File /var/lib/clickhouse/access/users.list doesn't exist
2021.01.25 11:01:04.698638 [ 44 ] {} <Warning> Access(local directory): Recovering lists in directory /var/lib/clickhouse/access/
2021.01.25 11:01:04.741092 [ 44 ] {} <Warning> Application: Listen [::]:8123 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.743241 [ 44 ] {} <Warning> Application: Listen [::]:9000 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.744627 [ 44 ] {} <Warning> Application: Listen [::]:9009 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.746106 [ 44 ] {} <Warning> Application: Listen [::]:9004 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:11.483542 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Warning> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): It looks like the table /clickhouse/tables/0/test_repl was created by another server at the same moment, will retry
2021.01.25 11:01:54.435690 [ 46 ] {3228c1c4-29ea-4e62-a0f1-975a355dfa8d} <Error> executeQuery: Code: 60, e.displayText() = DB::Exception: Table default.test_repl doesn't exist (version 21.1.2.15 (official build)) (from 127.0.0.1:40636) (in query: SELECT count() FROM default.test_repl), Stack trace (when copying this message, always include the lines below):
0. DB::Exception::Exception<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) @ 0x86fdd61 in /usr/bin/clickhouse
1. void std::__1::__optional_storage_base<DB::Exception, false>::__construct<int const&, char const (&) [23], std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int const&, char const (&) [23], std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) @ 0xeb7b1ef in /usr/bin/clickhouse
2. DB::DatabaseCatalog::getTableImpl(DB::StorageID const&, DB::Context const&, std::__1::optional<DB::Exception>*) const @ 0xeb6dee7 in /usr/bin/clickhouse
3. DB::DatabaseCatalog::getTable(DB::StorageID const&, DB::Context const&) const @ 0xeb739f9 in /usr/bin/clickhouse
4. DB::JoinedTables::getLeftTableStorage() @ 0xf0368d7 in /usr/bin/clickhouse
5. DB::InterpreterSelectQuery::InterpreterSelectQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, std::__1::shared_ptr<DB::IBlockInputStream> const&, std::__1::optional<DB::Pipe>, std::__1::shared_ptr<DB::IStorage> const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&, std::__1::shared_ptr<DB::StorageInMemoryMetadata const> const&) @ 0xee4a688 in /usr/bin/clickhouse
6. DB::InterpreterSelectQuery::InterpreterSelectQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xee49ded in /usr/bin/clickhouse
7. DB::InterpreterSelectWithUnionQuery::buildCurrentChildInterpreter(std::__1::shared_ptr<DB::IAST> const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xf00083a in /usr/bin/clickhouse
8. DB::InterpreterSelectWithUnionQuery::InterpreterSelectWithUnionQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xeffeede in /usr/bin/clickhouse
9. DB::InterpreterFactory::get(std::__1::shared_ptr<DB::IAST>&, DB::Context&, DB::SelectQueryOptions const&) @ 0xee05453 in /usr/bin/clickhouse
10. ? @ 0xf17cdd2 in /usr/bin/clickhouse
11. DB::executeQuery(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, DB::Context&, bool, DB::QueryProcessingStage::Enum, bool) @ 0xf17b99d in /usr/bin/clickhouse
12. DB::TCPHandler::runImpl() @ 0xf8844d6 in /usr/bin/clickhouse
13. DB::TCPHandler::run() @ 0xf8932e7 in /usr/bin/clickhouse
14. Poco::Net::TCPServerConnection::start() @ 0x11dd646f in /usr/bin/clickhouse
15. Poco::Net::TCPServerDispatcher::run() @ 0x11dd7e81 in /usr/bin/clickhouse
16. Poco::PooledThread::run() @ 0x11f03809 in /usr/bin/clickhouse
17. Poco::ThreadImpl::runnableEntry(void*) @ 0x11eff79a in /usr/bin/clickhouse
18. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
19. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.01.25 11:01:54.438776 [ 46 ] {3228c1c4-29ea-4e62-a0f1-975a355dfa8d} <Error> TCPHandler: Code: 60, e.displayText() = DB::Exception: Table default.test_repl doesn't exist, Stack trace:
0. DB::Exception::Exception<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) @ 0x86fdd61 in /usr/bin/clickhouse
1. void std::__1::__optional_storage_base<DB::Exception, false>::__construct<int const&, char const (&) [23], std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int const&, char const (&) [23], std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) @ 0xeb7b1ef in /usr/bin/clickhouse
2. DB::DatabaseCatalog::getTableImpl(DB::StorageID const&, DB::Context const&, std::__1::optional<DB::Exception>*) const @ 0xeb6dee7 in /usr/bin/clickhouse
3. DB::DatabaseCatalog::getTable(DB::StorageID const&, DB::Context const&) const @ 0xeb739f9 in /usr/bin/clickhouse
4. DB::JoinedTables::getLeftTableStorage() @ 0xf0368d7 in /usr/bin/clickhouse
5. DB::InterpreterSelectQuery::InterpreterSelectQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, std::__1::shared_ptr<DB::IBlockInputStream> const&, std::__1::optional<DB::Pipe>, std::__1::shared_ptr<DB::IStorage> const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&, std::__1::shared_ptr<DB::StorageInMemoryMetadata const> const&) @ 0xee4a688 in /usr/bin/clickhouse
6. DB::InterpreterSelectQuery::InterpreterSelectQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xee49ded in /usr/bin/clickhouse
7. DB::InterpreterSelectWithUnionQuery::buildCurrentChildInterpreter(std::__1::shared_ptr<DB::IAST> const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xf00083a in /usr/bin/clickhouse
8. DB::InterpreterSelectWithUnionQuery::InterpreterSelectWithUnionQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xeffeede in /usr/bin/clickhouse
9. DB::InterpreterFactory::get(std::__1::shared_ptr<DB::IAST>&, DB::Context&, DB::SelectQueryOptions const&) @ 0xee05453 in /usr/bin/clickhouse
10. ? @ 0xf17cdd2 in /usr/bin/clickhouse
11. DB::executeQuery(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, DB::Context&, bool, DB::QueryProcessingStage::Enum, bool) @ 0xf17b99d in /usr/bin/clickhouse
12. DB::TCPHandler::runImpl() @ 0xf8844d6 in /usr/bin/clickhouse
13. DB::TCPHandler::run() @ 0xf8932e7 in /usr/bin/clickhouse
14. Poco::Net::TCPServerConnection::start() @ 0x11dd646f in /usr/bin/clickhouse
15. Poco::Net::TCPServerDispatcher::run() @ 0x11dd7e81 in /usr/bin/clickhouse
16. Poco::PooledThread::run() @ 0x11f03809 in /usr/bin/clickhouse
17. Poco::ThreadImpl::runnableEntry(void*) @ 0x11eff79a in /usr/bin/clickhouse
18. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
19. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
Raw
clickhouse-0-0.log
2021.01.25 11:01:04.337074 [ 1 ] {} <Information> Application: Will watch for the process with pid 44
2021.01.25 11:01:04.337780 [ 44 ] {} <Information> Application: Forked a child process to watch
2021.01.25 11:01:04.339016 [ 44 ] {} <Information> SentryWriter: Sending crash reports is disabled
2021.01.25 11:01:04.339600 [ 44 ] {} <Trace> Pipe: Pipe capacity is 1.00 MiB
2021.01.25 11:01:04.430403 [ 44 ] {} <Information> : Starting ClickHouse 21.1.2.15 with revision 54445, build id: E40526A12E9A8F3819A18694F6B798F10C624D5C, PID 44
2021.01.25 11:01:04.436019 [ 44 ] {} <Information> Application: starting up
2021.01.25 11:01:04.674724 [ 44 ] {} <Information> Application: Calculated checksum of the binary: F6479E166DD7E8ABFA19525726186F71, integrity check passed.
2021.01.25 11:01:04.675325 [ 44 ] {} <Information> Application: It looks like the process has no CAP_IPC_LOCK capability, binary mlock will be disabled. It could happen due to incorrect ClickHouse package installation. You could resolve the problem manually with 'sudo setcap cap_ipc_lock=+ep /usr/bin/clickhouse'. Note that it will not work on 'nosuid' mounted filesystems.
2021.01.25 11:01:04.675997 [ 44 ] {} <Debug> Application: rlimit on number of file descriptors is 1048576
2021.01.25 11:01:04.676550 [ 44 ] {} <Debug> Application: Initializing DateLUT.
2021.01.25 11:01:04.676914 [ 44 ] {} <Trace> Application: Initialized DateLUT with time zone 'UTC'.
2021.01.25 11:01:04.677540 [ 44 ] {} <Debug> Application: Setting up /var/lib/clickhouse/tmp/ to store temporary data in it
2021.01.25 11:01:04.681132 [ 44 ] {} <Debug> Application: Configuration parameter 'interserver_http_host' doesn't exist or exists and empty. Will use 'f55da5a02bb1' as replica host.
2021.01.25 11:01:04.681868 [ 44 ] {} <Information> SensitiveDataMaskerConfigRead: 1 query masking rules loaded.
2021.01.25 11:01:04.686531 [ 44 ] {} <Debug> ConfigReloader: Loading config '/etc/clickhouse-server/users.xml'
2021.01.25 11:01:04.694141 [ 44 ] {} <Debug> ConfigReloader: Loaded config '/etc/clickhouse-server/users.xml', performing update on configuration
2021.01.25 11:01:04.695629 [ 44 ] {} <Debug> ConfigReloader: Loaded config '/etc/clickhouse-server/users.xml', performed update on configuration
2021.01.25 11:01:04.696806 [ 44 ] {} <Debug> Access(user directories): Added users.xml access storage 'users.xml', path: /etc/clickhouse-server/users.xml
2021.01.25 11:01:04.697799 [ 44 ] {} <Warning> Access(local directory): File /var/lib/clickhouse/access/users.list doesn't exist
2021.01.25 11:01:04.698638 [ 44 ] {} <Warning> Access(local directory): Recovering lists in directory /var/lib/clickhouse/access/
2021.01.25 11:01:04.699759 [ 44 ] {} <Debug> Access(user directories): Added local directory access storage 'local directory', path: /var/lib/clickhouse/access/
2021.01.25 11:01:04.700262 [ 44 ] {} <Information> Application: Uncompressed cache size was lowered to 6.19 GiB because the system has low amount of memory
2021.01.25 11:01:04.700818 [ 44 ] {} <Information> Application: Setting max_server_memory_usage was set to 11.14 GiB (12.38 GiB available * 0.90 max_server_memory_usage_to_ram_ratio)
2021.01.25 11:01:04.702062 [ 44 ] {} <Information> Application: Loading metadata from /var/lib/clickhouse/
2021.01.25 11:01:04.710033 [ 44 ] {} <Information> DatabaseAtomic (system): Total 0 tables and 0 dictionaries.
2021.01.25 11:01:04.710523 [ 44 ] {} <Information> DatabaseAtomic (system): Starting up tables.
2021.01.25 11:01:04.727976 [ 44 ] {} <Information> DatabaseAtomic (default): Total 0 tables and 0 dictionaries.
2021.01.25 11:01:04.728488 [ 44 ] {} <Information> DatabaseAtomic (default): Starting up tables.
2021.01.25 11:01:04.729060 [ 44 ] {} <Information> DatabaseCatalog: Found 0 partially dropped tables. Will load them and retry removal.
2021.01.25 11:01:04.729467 [ 44 ] {} <Information> BackgroundSchedulePool/BgSchPool: Create BackgroundSchedulePool with 16 threads
2021.01.25 11:01:04.738128 [ 44 ] {} <Debug> Application: Loaded metadata.
2021.01.25 11:01:04.738672 [ 44 ] {} <Trace> Pipe: Pipe capacity is 1.00 MiB
2021.01.25 11:01:04.739885 [ 44 ] {} <Information> Application: It looks like the process has no CAP_SYS_NICE capability, the setting 'os_thread_priority' will have no effect. It could happen due to incorrect ClickHouse package installation. You could resolve the problem manually with 'sudo setcap cap_sys_nice=+ep /usr/bin/clickhouse'. Note that it will not work on 'nosuid' mounted filesystems.
2021.01.25 11:01:04.739903 [ 77 ] {} <Debug> DDLWorker: Started DDLWorker thread
2021.01.25 11:01:04.739936 [ 76 ] {} <Debug> DDLWorker: Started DDLWorker cleanup thread
2021.01.25 11:01:04.741092 [ 44 ] {} <Warning> Application: Listen [::]:8123 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.743241 [ 44 ] {} <Warning> Application: Listen [::]:9000 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.744627 [ 44 ] {} <Warning> Application: Listen [::]:9009 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.746106 [ 44 ] {} <Warning> Application: Listen [::]:9004 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.747483 [ 44 ] {} <Information> Application: Listening for http://0.0.0.0:8123
2021.01.25 11:01:04.748161 [ 44 ] {} <Information> Application: Listening for connections with native protocol (tcp): 0.0.0.0:9000
2021.01.25 11:01:04.748703 [ 44 ] {} <Information> Application: Listening for replica communication (interserver): http://0.0.0.0:9009
2021.01.25 11:01:04.750033 [ 44 ] {} <Trace> MySQLHandlerFactory: Failed to create SSL context. SSL will be disabled. Error: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = SSL context exception: Error loading private key from file /etc/clickhouse-server/server.key: error:02000002:system library:OPENSSL_internal:No such file or directory (version 21.1.2.15 (official build))
2021.01.25 11:01:04.750965 [ 44 ] {} <Trace> MySQLHandlerFactory: Failed to read RSA key pair from server certificate. Error: Code: 76, e.displayText() = DB::Exception: Cannot open certificate file: /etc/clickhouse-server/server.crt. (version 21.1.2.15 (official build))
2021.01.25 11:01:04.751363 [ 44 ] {} <Trace> MySQLHandlerFactory: Generating new RSA key pair.
2021.01.25 11:01:04.790562 [ 77 ] {} <Trace> ZooKeeper: Initialized, hosts: zookeeper:2181
2021.01.25 11:01:04.846792 [ 77 ] {} <Debug> DDLWorker: Scheduling tasks
2021.01.25 11:01:04.846873 [ 76 ] {} <Debug> DDLWorker: Cleaning queue
2021.01.25 11:01:04.854068 [ 77 ] {} <Debug> DDLWorker: Waiting a watch
2021.01.25 11:01:04.995677 [ 44 ] {} <Information> Application: Listening for MySQL compatibility protocol: 0.0.0.0:9004
2021.01.25 11:01:04.998298 [ 44 ] {} <Information> DNSCacheUpdater: Update period 15 seconds
2021.01.25 11:01:04.998945 [ 44 ] {} <Information> Application: Available RAM: 12.38 GiB; physical cores: 4; logical cores: 8.
2021.01.25 11:01:04.999498 [ 44 ] {} <Information> Application: Ready for connections.
2021.01.25 11:01:04.999033 [ 60 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:01:05.000568 [ 60 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:01:07.005067 [ 87 ] {} <Debug> ConfigReloader: Loading config '/etc/clickhouse-server/config.xml'
2021.01.25 11:01:07.017708 [ 87 ] {} <Debug> ConfigReloader: Loaded config '/etc/clickhouse-server/config.xml', performing update on configuration
2021.01.25 11:01:07.021671 [ 87 ] {} <Debug> ConfigReloader: Loaded config '/etc/clickhouse-server/config.xml', performed update on configuration
2021.01.25 11:01:11.357857 [ 46 ] {} <Trace> TCPHandlerFactory: TCP Request. Address: 127.0.0.1:40630
2021.01.25 11:01:11.358509 [ 46 ] {} <Debug> TCPHandler: Connected ClickHouse client version 21.1.0, revision: 54443, user: default.
2021.01.25 11:01:11.359196 [ 46 ] {} <Trace> ContextAccess (default): Settings: readonly=0, allow_ddl=true, allow_introspection_functions=false
2021.01.25 11:01:11.359555 [ 46 ] {} <Trace> ContextAccess (default): List of all grants: GRANT SHOW, SELECT, INSERT, ALTER, CREATE, DROP, TRUNCATE, OPTIMIZE, KILL QUERY, SYSTEM, dictGet, INTROSPECTION, SOURCES ON *.*
2021.01.25 11:01:11.360050 [ 46 ] {} <Trace> ContextAccess (default): List of all grants including implicit: GRANT SHOW, SELECT, INSERT, ALTER, CREATE, DROP, TRUNCATE, OPTIMIZE, KILL QUERY, SYSTEM, dictGet, INTROSPECTION, SOURCES ON *.*
2021.01.25 11:01:11.367491 [ 46 ] {94a585c9-6d25-4d3c-9703-7ce4bfcb142c} <Debug> executeQuery: (from 127.0.0.1:40630, using production parser) CREATE TABLE default.test_repl ON CLUSTER 'default' (n UInt64) ENGINE ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl','{replica}') ORDER BY tuple()
2021.01.25 11:01:11.368323 [ 46 ] {94a585c9-6d25-4d3c-9703-7ce4bfcb142c} <Trace> ContextAccess (default): Access granted: CREATE TABLE ON default.test_repl
2021.01.25 11:01:11.394227 [ 77 ] {} <Debug> DDLWorker: Scheduling tasks
2021.01.25 11:01:11.394245 [ 76 ] {} <Trace> DDLWorker: Too early to clean queue, will do it later.
2021.01.25 11:01:11.409128 [ 46 ] {94a585c9-6d25-4d3c-9703-7ce4bfcb142c} <Debug> executeQuery: Query pipeline:
DDLQueryStatusInputStream
2021.01.25 11:01:11.414636 [ 77 ] {} <Debug> DDLWorker: Waiting a watch
2021.01.25 11:01:11.414817 [ 98 ] {} <Debug> DDLWorker: Processing task query-0000000000 (CREATE TABLE default.test_repl UUID 'b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026' ON CLUSTER default (`n` UInt64) ENGINE = ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl', '{replica}') ORDER BY tuple())
2021.01.25 11:01:11.424007 [ 98 ] {} <Debug> DDLWorker: Executing query: CREATE TABLE default.test_repl UUID 'b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026' (`n` UInt64) ENGINE = ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl', '{replica}') ORDER BY tuple()
2021.01.25 11:01:11.424945 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> executeQuery: (from 0.0.0.0:0, user: , using production parser) /* ddl_entry=query-0000000000 */ CREATE TABLE default.test_repl UUID 'b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026' (`n` UInt64) ENGINE = ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl', '{replica}') ORDER BY tuple()
2021.01.25 11:01:11.435311 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Loading data parts
2021.01.25 11:01:11.437055 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Loaded data parts (0 items)
2021.01.25 11:01:11.457822 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Creating table /clickhouse/tables/0/test_repl
2021.01.25 11:01:11.483542 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Warning> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): It looks like the table /clickhouse/tables/0/test_repl was created by another server at the same moment, will retry
2021.01.25 11:01:11.488279 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): This table /clickhouse/tables/0/test_repl is already created, will add new replica
2021.01.25 11:01:11.504588 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Creating replica /clickhouse/tables/0/test_repl/replicas/clickhouse-0-0
2021.01.25 11:01:11.573583 [ 61 ] {} <Debug> default.test_repl (ReplicatedMergeTreeRestartingThread): Activating replica.
2021.01.25 11:01:11.593599 [ 61 ] {} <Information> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Replica clickhouse-0-1 has log pointer '0', approximate 1 queue lag and 0 queue size
2021.01.25 11:01:11.594035 [ 61 ] {} <Information> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Will mimic clickhouse-0-1
2021.01.25 11:01:11.622097 [ 61 ] {} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Queued 0 parts to be fetched
2021.01.25 11:01:11.622548 [ 61 ] {} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Copied 0 queue entries
2021.01.25 11:01:11.627660 [ 61 ] {} <Debug> default.test_repl (ReplicatedMergeTreeQueue): Loading queue from /clickhouse/tables/0/test_repl/replicas/clickhouse-0-0/queue
2021.01.25 11:01:11.631403 [ 61 ] {} <Debug> default.test_repl (ReplicatedMergeTreeQueue): Having 0 queue entries to load, 0 entries already loaded.
2021.01.25 11:01:11.633477 [ 61 ] {} <Trace> default.test_repl (ReplicatedMergeTreeQueue): Loaded queue
2021.01.25 11:01:11.647308 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> DDLWorker: Executed query: CREATE TABLE default.test_repl UUID 'b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026' (`n` UInt64) ENGINE = ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl', '{replica}') ORDER BY tuple()
2021.01.25 11:01:11.653515 [ 59 ] {} <Information> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Became leader
2021.01.25 11:01:11.693296 [ 46 ] {94a585c9-6d25-4d3c-9703-7ce4bfcb142c} <Information> executeQuery: Read 2 rows, 120.00 B in 0.3252314 sec., 6 rows/sec., 368.97 B/sec.
2021.01.25 11:01:11.693895 [ 46 ] {94a585c9-6d25-4d3c-9703-7ce4bfcb142c} <Debug> MemoryTracker: Peak memory usage (for query): 27.51 KiB.
2021.01.25 11:01:11.694673 [ 46 ] {} <Debug> MemoryTracker: Peak memory usage (for query): 27.51 KiB.
2021.01.25 11:01:11.695378 [ 46 ] {} <Debug> TCPHandler: Processed in 0.328394 sec.
2021.01.25 11:01:11.696050 [ 46 ] {} <Debug> TCPHandler: Done processing connection.
2021.01.25 11:01:12.215350 [ 51 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 4 entries to flush
2021.01.25 11:01:12.215918 [ 51 ] {} <Debug> SystemLog (system.query_log): Creating new table system.query_log for QueryLog
2021.01.25 11:01:12.216578 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushing system log, 3 entries to flush
2021.01.25 11:01:12.216951 [ 52 ] {} <Debug> SystemLog (system.query_thread_log): Creating new table system.query_thread_log for QueryThreadLog
2021.01.25 11:01:12.216951 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 2 entries to flush
2021.01.25 11:01:12.217380 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:12.218042 [ 53 ] {} <Debug> SystemLog (system.trace_log): Creating new table system.trace_log for TraceLog
2021.01.25 11:01:12.218377 [ 55 ] {} <Debug> SystemLog (system.metric_log): Creating new table system.metric_log for MetricLog
2021.01.25 11:01:12.226315 [ 52 ] {} <Debug> system.query_thread_log (bd03ce89-75b3-4410-82f9-16a9da1e401b): Loading data parts
2021.01.25 11:01:12.226377 [ 51 ] {} <Debug> system.query_log (01bdc8a6-c48e-4b70-9cce-8cc3538ee9f3): Loading data parts
2021.01.25 11:01:12.227070 [ 52 ] {} <Debug> system.query_thread_log (bd03ce89-75b3-4410-82f9-16a9da1e401b): Loaded data parts (0 items)
2021.01.25 11:01:12.227856 [ 51 ] {} <Debug> system.query_log (01bdc8a6-c48e-4b70-9cce-8cc3538ee9f3): Loaded data parts (0 items)
2021.01.25 11:01:12.230028 [ 53 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Loading data parts
2021.01.25 11:01:12.230923 [ 53 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Loaded data parts (0 items)
2021.01.25 11:01:12.234357 [ 55 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Loading data parts
2021.01.25 11:01:12.235423 [ 55 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Loaded data parts (0 items)
2021.01.25 11:01:12.236683 [ 52 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:12.237313 [ 51 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:12.238290 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:12.242587 [ 51 ] {} <Trace> system.query_log (01bdc8a6-c48e-4b70-9cce-8cc3538ee9f3): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:01:12.242953 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:01:12.243552 [ 51 ] {} <Trace> SystemLog (system.query_log): Flushed system log
2021.01.25 11:01:12.243848 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:12.244096 [ 52 ] {} <Trace> system.query_thread_log (bd03ce89-75b3-4410-82f9-16a9da1e401b): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:01:12.245280 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushed system log
2021.01.25 11:01:12.248284 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:12.252304 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:01:12.253749 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:19.744735 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 11 entries to flush
2021.01.25 11:01:19.745782 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:19.747885 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:01:19.748761 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:19.754500 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:19.759520 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:19.767748 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:01:19.769358 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:20.001350 [ 65 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:01:20.004135 [ 65 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:01:27.249590 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:27.270068 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:01:27.273453 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:27.279404 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_3_3_0 to 202101_3_3_0.
2021.01.25 11:01:27.282814 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:27.304904 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:27.365693 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_3_3_0 to 202101_3_3_0.
2021.01.25 11:01:27.394813 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:27.973074 [ 77 ] {} <Debug> DDLWorker: Scheduling tasks
2021.01.25 11:01:27.973174 [ 76 ] {} <Trace> DDLWorker: Too early to clean queue, will do it later.
2021.01.25 11:01:28.042560 [ 77 ] {} <Debug> DDLWorker: Waiting a watch
2021.01.25 11:01:28.042605 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> DDLWorker: Processing task query-0000000001 (DROP TABLE default.test_repl ON CLUSTER default NO DELAY)
2021.01.25 11:01:28.092900 [ 98 ] {1230858d-9a12-4dd8-abd7-4b9882b7ea0e} <Debug> DDLWorker: Executing query: DROP TABLE default.test_repl NO DELAY
2021.01.25 11:01:28.098343 [ 98 ] {dca4a54e-30be-4d80-a56a-136ca7a06ce4} <Debug> executeQuery: (from 0.0.0.0:0, user: , using production parser) /* ddl_entry=query-0000000001 */ DROP TABLE default.test_repl NO DELAY
2021.01.25 11:01:28.100981 [ 98 ] {dca4a54e-30be-4d80-a56a-136ca7a06ce4} <Trace> default.test_repl (ReplicatedMergeTreeRestartingThread): Restarting thread finished
2021.01.25 11:01:28.182751 [ 98 ] {dca4a54e-30be-4d80-a56a-136ca7a06ce4} <Trace> default.test_repl (ReplicatedMergeTreeRestartingThread): Waiting for threads to finish
2021.01.25 11:01:28.188416 [ 98 ] {dca4a54e-30be-4d80-a56a-136ca7a06ce4} <Information> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Stopped being leader
2021.01.25 11:01:28.306707 [ 98 ] {dca4a54e-30be-4d80-a56a-136ca7a06ce4} <Trace> default.test_repl (ReplicatedMergeTreeRestartingThread): Threads finished
2021.01.25 11:01:28.355137 [ 98 ] {dca4a54e-30be-4d80-a56a-136ca7a06ce4} <Debug> DatabaseCatalog: Waiting for table b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026 to be finally dropped
2021.01.25 11:01:30.000350 [ 81 ] {} <Debug> AsynchronousMetrics: MemoryTracking: was 6.96 MiB, peak 18.24 MiB, will set to 321.27 MiB (RSS), difference: 314.31 MiB
2021.01.25 11:01:34.784553 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:01:34.785868 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:34.788711 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_4_4_0 to 202101_4_4_0.
2021.01.25 11:01:34.789573 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:34.900562 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:34.908090 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:34.913881 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_4_4_0 to 202101_4_4_0.
2021.01.25 11:01:34.915960 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:35.005421 [ 59 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:01:35.007855 [ 59 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:01:42.290379 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 9 entries to flush
2021.01.25 11:01:42.291280 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:42.292719 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_5_5_0 to 202101_5_5_0.
2021.01.25 11:01:42.293526 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:42.416621 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:01:42.425321 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:42.431206 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_5_5_0 to 202101_5_5_0.
2021.01.25 11:01:42.433064 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:49.794305 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:01:49.795701 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.797628 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_6_6_0 to 202101_6_6_0.
2021.01.25 11:01:49.798420 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:49.798568 [ 66 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Selected 6 parts from 202101_1_1_0 to 202101_6_6_0
2021.01.25 11:01:49.799495 [ 66 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.800243 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merging 6 parts: from 202101_1_1_0 to 202101_6_6_0 into Compact
2021.01.25 11:01:49.800817 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:01:49.801437 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_1_0, total 2 rows starting from the beginning of the part
2021.01.25 11:01:49.802324 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_2_2_0, total 11 rows starting from the beginning of the part
2021.01.25 11:01:49.804145 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_3_3_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.806655 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_4_4_0, total 7 rows starting from the beginning of the part
2021.01.25 11:01:49.809034 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_5_5_0, total 9 rows starting from the beginning of the part
2021.01.25 11:01:49.809894 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_6_6_0, total 7 rows starting from the beginning of the part
2021.01.25 11:01:49.814942 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merge sorted 44 rows, containing 10 columns (10 merged, 0 gathered) in 0.0147739 sec., 2978.225113206398 rows/sec., 561.59 KiB/sec.
2021.01.25 11:01:49.816886 [ 101 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_merge_202101_1_6_1 to 202101_1_6_1.
2021.01.25 11:01:49.817514 [ 101 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merged 6 parts: from 202101_1_1_0 to 202101_6_6_0
2021.01.25 11:01:49.818068 [ 101 ] {} <Debug> MemoryTracker: Peak memory usage: 4.04 MiB.
2021.01.25 11:01:49.933788 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:49.944770 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.957448 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_6_6_0 to 202101_6_6_0.
2021.01.25 11:01:49.958612 [ 60 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Selected 6 parts from 202101_1_1_0 to 202101_6_6_0
2021.01.25 11:01:49.959446 [ 60 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.959716 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:49.960299 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merging 6 parts: from 202101_1_1_0 to 202101_6_6_0 into Compact
2021.01.25 11:01:49.962220 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:01:49.964178 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_1_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.968075 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_2_2_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.971628 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_3_3_0, total 7 rows starting from the beginning of the part
2021.01.25 11:01:49.975036 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_4_4_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.978534 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_5_5_0, total 7 rows starting from the beginning of the part
2021.01.25 11:01:49.983719 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_6_6_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:50.008793 [ 65 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:01:50.011363 [ 65 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:01:50.042820 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merge sorted 46 rows, containing 255 columns (255 merged, 0 gathered) in 0.0825217 sec., 557.4291368209816 rows/sec., 1.08 MiB/sec.
2021.01.25 11:01:50.050543 [ 95 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_merge_202101_1_6_1 to 202101_1_6_1.
2021.01.25 11:01:50.052237 [ 95 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merged 6 parts: from 202101_1_1_0 to 202101_6_6_0
2021.01.25 11:01:50.053068 [ 95 ] {} <Debug> MemoryTracker: Peak memory usage: 4.10 MiB.
2021.01.25 11:01:54.415463 [ 46 ] {} <Trace> TCPHandlerFactory: TCP Request. Address: 127.0.0.1:40636
2021.01.25 11:01:54.416294 [ 46 ] {} <Debug> TCPHandler: Connected ClickHouse client version 21.1.0, revision: 54443, user: default.
2021.01.25 11:01:54.425739 [ 46 ] {3228c1c4-29ea-4e62-a0f1-975a355dfa8d} <Debug> executeQuery: (from 127.0.0.1:40636, using production parser) SELECT count() FROM default.test_repl
2021.01.25 11:01:54.435690 [ 46 ] {3228c1c4-29ea-4e62-a0f1-975a355dfa8d} <Error> executeQuery: Code: 60, e.displayText() = DB::Exception: Table default.test_repl doesn't exist (version 21.1.2.15 (official build)) (from 127.0.0.1:40636) (in query: SELECT count() FROM default.test_repl), Stack trace (when copying this message, always include the lines below):
0. DB::Exception::Exception<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) @ 0x86fdd61 in /usr/bin/clickhouse
1. void std::__1::__optional_storage_base<DB::Exception, false>::__construct<int const&, char const (&) [23], std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int const&, char const (&) [23], std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) @ 0xeb7b1ef in /usr/bin/clickhouse
2. DB::DatabaseCatalog::getTableImpl(DB::StorageID const&, DB::Context const&, std::__1::optional<DB::Exception>*) const @ 0xeb6dee7 in /usr/bin/clickhouse
3. DB::DatabaseCatalog::getTable(DB::StorageID const&, DB::Context const&) const @ 0xeb739f9 in /usr/bin/clickhouse
4. DB::JoinedTables::getLeftTableStorage() @ 0xf0368d7 in /usr/bin/clickhouse
5. DB::InterpreterSelectQuery::InterpreterSelectQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, std::__1::shared_ptr<DB::IBlockInputStream> const&, std::__1::optional<DB::Pipe>, std::__1::shared_ptr<DB::IStorage> const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&, std::__1::shared_ptr<DB::StorageInMemoryMetadata const> const&) @ 0xee4a688 in /usr/bin/clickhouse
6. DB::InterpreterSelectQuery::InterpreterSelectQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xee49ded in /usr/bin/clickhouse
7. DB::InterpreterSelectWithUnionQuery::buildCurrentChildInterpreter(std::__1::shared_ptr<DB::IAST> const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xf00083a in /usr/bin/clickhouse
8. DB::InterpreterSelectWithUnionQuery::InterpreterSelectWithUnionQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xeffeede in /usr/bin/clickhouse
9. DB::InterpreterFactory::get(std::__1::shared_ptr<DB::IAST>&, DB::Context&, DB::SelectQueryOptions const&) @ 0xee05453 in /usr/bin/clickhouse
10. ? @ 0xf17cdd2 in /usr/bin/clickhouse
11. DB::executeQuery(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, DB::Context&, bool, DB::QueryProcessingStage::Enum, bool) @ 0xf17b99d in /usr/bin/clickhouse
12. DB::TCPHandler::runImpl() @ 0xf8844d6 in /usr/bin/clickhouse
13. DB::TCPHandler::run() @ 0xf8932e7 in /usr/bin/clickhouse
14. Poco::Net::TCPServerConnection::start() @ 0x11dd646f in /usr/bin/clickhouse
15. Poco::Net::TCPServerDispatcher::run() @ 0x11dd7e81 in /usr/bin/clickhouse
16. Poco::PooledThread::run() @ 0x11f03809 in /usr/bin/clickhouse
17. Poco::ThreadImpl::runnableEntry(void*) @ 0x11eff79a in /usr/bin/clickhouse
18. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
19. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.01.25 11:01:54.438776 [ 46 ] {3228c1c4-29ea-4e62-a0f1-975a355dfa8d} <Error> TCPHandler: Code: 60, e.displayText() = DB::Exception: Table default.test_repl doesn't exist, Stack trace:
0. DB::Exception::Exception<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) @ 0x86fdd61 in /usr/bin/clickhouse
1. void std::__1::__optional_storage_base<DB::Exception, false>::__construct<int const&, char const (&) [23], std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int const&, char const (&) [23], std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) @ 0xeb7b1ef in /usr/bin/clickhouse
2. DB::DatabaseCatalog::getTableImpl(DB::StorageID const&, DB::Context const&, std::__1::optional<DB::Exception>*) const @ 0xeb6dee7 in /usr/bin/clickhouse
3. DB::DatabaseCatalog::getTable(DB::StorageID const&, DB::Context const&) const @ 0xeb739f9 in /usr/bin/clickhouse
4. DB::JoinedTables::getLeftTableStorage() @ 0xf0368d7 in /usr/bin/clickhouse
5. DB::InterpreterSelectQuery::InterpreterSelectQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, std::__1::shared_ptr<DB::IBlockInputStream> const&, std::__1::optional<DB::Pipe>, std::__1::shared_ptr<DB::IStorage> const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&, std::__1::shared_ptr<DB::StorageInMemoryMetadata const> const&) @ 0xee4a688 in /usr/bin/clickhouse
6. DB::InterpreterSelectQuery::InterpreterSelectQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xee49ded in /usr/bin/clickhouse
7. DB::InterpreterSelectWithUnionQuery::buildCurrentChildInterpreter(std::__1::shared_ptr<DB::IAST> const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xf00083a in /usr/bin/clickhouse
8. DB::InterpreterSelectWithUnionQuery::InterpreterSelectWithUnionQuery(std::__1::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > const&) @ 0xeffeede in /usr/bin/clickhouse
9. DB::InterpreterFactory::get(std::__1::shared_ptr<DB::IAST>&, DB::Context&, DB::SelectQueryOptions const&) @ 0xee05453 in /usr/bin/clickhouse
10. ? @ 0xf17cdd2 in /usr/bin/clickhouse
11. DB::executeQuery(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, DB::Context&, bool, DB::QueryProcessingStage::Enum, bool) @ 0xf17b99d in /usr/bin/clickhouse
12. DB::TCPHandler::runImpl() @ 0xf8844d6 in /usr/bin/clickhouse
13. DB::TCPHandler::run() @ 0xf8932e7 in /usr/bin/clickhouse
14. Poco::Net::TCPServerConnection::start() @ 0x11dd646f in /usr/bin/clickhouse
15. Poco::Net::TCPServerDispatcher::run() @ 0x11dd7e81 in /usr/bin/clickhouse
16. Poco::PooledThread::run() @ 0x11f03809 in /usr/bin/clickhouse
17. Poco::ThreadImpl::runnableEntry(void*) @ 0x11eff79a in /usr/bin/clickhouse
18. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
19. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.01.25 11:01:54.439811 [ 46 ] {3228c1c4-29ea-4e62-a0f1-975a355dfa8d} <Debug> MemoryTracker: Peak memory usage (for query): 0.00 B.
2021.01.25 11:01:54.440391 [ 46 ] {} <Debug> TCPHandler: Processed in 0.0154608 sec.
2021.01.25 11:01:54.441884 [ 46 ] {} <Debug> TCPHandler: Done processing connection.
2021.01.25 11:01:57.245645 [ 51 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 1 entries to flush
2021.01.25 11:01:57.248353 [ 51 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:57.248744 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushing system log, 1 entries to flush
2021.01.25 11:01:57.250652 [ 52 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:57.251272 [ 51 ] {} <Trace> system.query_log (01bdc8a6-c48e-4b70-9cce-8cc3538ee9f3): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:01:57.252079 [ 51 ] {} <Trace> SystemLog (system.query_log): Flushed system log
2021.01.25 11:01:57.252886 [ 52 ] {} <Trace> system.query_thread_log (bd03ce89-75b3-4410-82f9-16a9da1e401b): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:01:57.253629 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushed system log
2021.01.25 11:01:57.299142 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:57.300102 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:57.301406 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_7_7_0 to 202101_7_7_0.
2021.01.25 11:01:57.302223 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:57.460910 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:01:57.467903 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:57.472363 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_7_7_0 to 202101_7_7_0.
2021.01.25 11:01:57.473871 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:04.717410 [ 54 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushing system log, 53 entries to flush
2021.01.25 11:02:04.717944 [ 54 ] {} <Debug> SystemLog (system.asynchronous_metric_log): Creating new table system.asynchronous_metric_log for AsynchronousMetricLog
2021.01.25 11:02:04.725107 [ 54 ] {} <Debug> system.asynchronous_metric_log (5cf5cbff-9580-45f4-82ec-5937979bb74e): Loading data parts
2021.01.25 11:02:04.726130 [ 54 ] {} <Debug> system.asynchronous_metric_log (5cf5cbff-9580-45f4-82ec-5937979bb74e): Loaded data parts (0 items)
2021.01.25 11:02:04.732900 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:04.734248 [ 54 ] {} <Trace> system.asynchronous_metric_log (5cf5cbff-9580-45f4-82ec-5937979bb74e): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:02:04.734886 [ 54 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushed system log
2021.01.25 11:02:04.802893 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:04.804018 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:04.805662 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_8_8_0 to 202101_8_8_0.
2021.01.25 11:02:04.806563 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:04.974632 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:04.981322 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:04.986086 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_8_8_0 to 202101_8_8_0.
2021.01.25 11:02:04.988434 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:05.012227 [ 58 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:02:05.014161 [ 58 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:02:12.307267 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:12.308110 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:12.309409 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_9_9_0 to 202101_9_9_0.
2021.01.25 11:02:12.310145 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:12.489215 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:12.493998 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:12.497163 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_9_9_0 to 202101_9_9_0.
2021.01.25 11:02:12.498288 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:19.810675 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:19.811508 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:19.818093 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_10_10_0 to 202101_10_10_0.
2021.01.25 11:02:19.818836 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:19.998882 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:20.004103 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:20.008778 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_10_10_0 to 202101_10_10_0.
2021.01.25 11:02:20.010192 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:20.014984 [ 71 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:02:20.016701 [ 71 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:02:27.319458 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:27.320089 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:27.321269 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_11_11_0 to 202101_11_11_0.
2021.01.25 11:02:27.321892 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:27.321982 [ 69 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Selected 6 parts from 202101_1_6_1 to 202101_11_11_0
2021.01.25 11:02:27.322710 [ 69 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:27.323163 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merging 6 parts: from 202101_1_6_1 to 202101_11_11_0 into Compact
2021.01.25 11:02:27.323496 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:02:27.323825 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_6_1, total 44 rows starting from the beginning of the part
2021.01.25 11:02:27.324268 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_7_7_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.324721 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_8_8_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.325124 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_9_9_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.325581 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_10_10_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.326082 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_11_11_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.328931 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merge sorted 82 rows, containing 10 columns (10 merged, 0 gathered) in 0.0057694 sec., 14212.916421118314 rows/sec., 2.81 MiB/sec.
2021.01.25 11:02:27.329806 [ 101 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_merge_202101_1_11_2 to 202101_1_11_2.
2021.01.25 11:02:27.330268 [ 101 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merged 6 parts: from 202101_1_6_1 to 202101_11_11_0
2021.01.25 11:02:27.330607 [ 101 ] {} <Debug> MemoryTracker: Peak memory usage: 4.05 MiB.
2021.01.25 11:02:27.510977 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:27.515238 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:27.518813 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_11_11_0 to 202101_11_11_0.
2021.01.25 11:02:27.519743 [ 58 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Selected 6 parts from 202101_1_6_1 to 202101_11_11_0
2021.01.25 11:02:27.520303 [ 58 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:27.520175 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:27.520865 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merging 6 parts: from 202101_1_6_1 to 202101_11_11_0 into Compact
2021.01.25 11:02:27.521909 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:02:27.522952 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_6_1, total 46 rows starting from the beginning of the part
2021.01.25 11:02:27.525454 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_7_7_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.527889 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_8_8_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.530146 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_9_9_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.532402 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_10_10_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.534647 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_11_11_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.557125 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merge sorted 83 rows, containing 255 columns (255 merged, 0 gathered) in 0.0362339 sec., 2290.672546979486 rows/sec., 4.43 MiB/sec.
2021.01.25 11:02:27.559460 [ 95 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_merge_202101_1_11_2 to 202101_1_11_2.
2021.01.25 11:02:27.560222 [ 95 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merged 6 parts: from 202101_1_6_1 to 202101_11_11_0
2021.01.25 11:02:27.560680 [ 95 ] {} <Debug> MemoryTracker: Peak memory usage: 4.10 MiB.
2021.01.25 11:02:30.000220 [ 81 ] {} <Debug> AsynchronousMetrics: MemoryTracking: was 321.74 MiB, peak 325.79 MiB, will set to 333.00 MiB (RSS), difference: 11.26 MiB
2021.01.25 11:02:34.822468 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:34.823391 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:34.824988 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_12_12_0 to 202101_12_12_0.
2021.01.25 11:02:34.825732 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:35.017464 [ 66 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:02:35.019807 [ 66 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:02:35.021250 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:35.029020 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:35.034612 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_12_12_0 to 202101_12_12_0.
2021.01.25 11:02:35.036708 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:42.326289 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 9 entries to flush
2021.01.25 11:02:42.326984 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:42.327976 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_13_13_0 to 202101_13_13_0.
2021.01.25 11:02:42.328469 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:42.537341 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:42.541726 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:42.545265 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_13_13_0 to 202101_13_13_0.
2021.01.25 11:02:42.546255 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:49.829255 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:49.830100 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:49.831303 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_14_14_0 to 202101_14_14_0.
2021.01.25 11:02:49.831935 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:50.021041 [ 72 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:02:50.022700 [ 72 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:02:50.046706 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:50.051632 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:50.055843 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_14_14_0 to 202101_14_14_0.
2021.01.25 11:02:50.057120 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:57.332658 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:57.333752 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:57.335004 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_15_15_0 to 202101_15_15_0.
2021.01.25 11:02:57.335537 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:57.557651 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:57.562299 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:57.565325 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_15_15_0 to 202101_15_15_0.
2021.01.25 11:02:57.566653 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:04.735540 [ 54 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushing system log, 53 entries to flush
2021.01.25 11:03:04.736389 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:04.737537 [ 54 ] {} <Trace> system.asynchronous_metric_log (5cf5cbff-9580-45f4-82ec-5937979bb74e): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:03:04.738187 [ 54 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushed system log
2021.01.25 11:03:04.836035 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:04.836889 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:04.843804 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_16_16_0 to 202101_16_16_0.
2021.01.25 11:03:04.844827 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:04.844923 [ 67 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Selected 6 parts from 202101_1_11_2 to 202101_16_16_0
2021.01.25 11:03:04.845714 [ 67 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:04.846358 [ 99 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merging 6 parts: from 202101_1_11_2 to 202101_16_16_0 into Compact
2021.01.25 11:03:04.846928 [ 99 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:03:04.847417 [ 99 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_11_2, total 82 rows starting from the beginning of the part
2021.01.25 11:03:04.848097 [ 99 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_12_12_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:04.848788 [ 99 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_13_13_0, total 9 rows starting from the beginning of the part
2021.01.25 11:03:04.849386 [ 99 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_14_14_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:04.850102 [ 99 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_15_15_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:04.850745 [ 99 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_16_16_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:04.853053 [ 99 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merge sorted 121 rows, containing 10 columns (10 merged, 0 gathered) in 0.0067387 sec., 17955.98557585291 rows/sec., 3.63 MiB/sec.
2021.01.25 11:03:04.854501 [ 99 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_merge_202101_1_16_3 to 202101_1_16_3.
2021.01.25 11:03:04.855119 [ 99 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merged 6 parts: from 202101_1_11_2 to 202101_16_16_0
2021.01.25 11:03:04.855647 [ 99 ] {} <Debug> MemoryTracker: Peak memory usage: 4.05 MiB.
2021.01.25 11:03:05.023323 [ 61 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:03:05.025168 [ 61 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:03:05.067130 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:05.073068 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:05.078032 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_16_16_0 to 202101_16_16_0.
2021.01.25 11:03:05.078784 [ 58 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Selected 6 parts from 202101_1_11_2 to 202101_16_16_0
2021.01.25 11:03:05.079097 [ 58 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:05.079320 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:05.079475 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merging 6 parts: from 202101_1_11_2 to 202101_16_16_0 into Compact
2021.01.25 11:03:05.081221 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:03:05.082259 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_11_2, total 83 rows starting from the beginning of the part
2021.01.25 11:03:05.084727 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_12_12_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:05.087471 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_13_13_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:05.089968 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_14_14_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:05.092579 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_15_15_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:05.095762 [ 95 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_16_16_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:05.124112 [ 95 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merge sorted 121 rows, containing 255 columns (255 merged, 0 gathered) in 0.0446167 sec., 2711.9890085999186 rows/sec., 5.25 MiB/sec.
2021.01.25 11:03:05.127383 [ 95 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_merge_202101_1_16_3 to 202101_1_16_3.
2021.01.25 11:03:05.128110 [ 95 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merged 6 parts: from 202101_1_11_2 to 202101_16_16_0
2021.01.25 11:03:05.128454 [ 95 ] {} <Debug> MemoryTracker: Peak memory usage: 4.10 MiB.
2021.01.25 11:03:12.345658 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:12.346494 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:12.347537 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_17_17_0 to 202101_17_17_0.
2021.01.25 11:03:12.348187 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:12.579766 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:12.586119 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:12.589488 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_17_17_0 to 202101_17_17_0.
2021.01.25 11:03:12.590605 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:19.849190 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:19.850038 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:19.851182 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_18_18_0 to 202101_18_18_0.
2021.01.25 11:03:19.851753 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:20.025789 [ 58 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:03:20.027116 [ 58 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:03:20.091248 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:20.095462 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:20.098231 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_18_18_0 to 202101_18_18_0.
2021.01.25 11:03:20.099316 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:27.352839 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:27.353696 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:27.354803 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_19_19_0 to 202101_19_19_0.
2021.01.25 11:03:27.355326 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:27.599859 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:27.604540 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:27.607923 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_19_19_0 to 202101_19_19_0.
2021.01.25 11:03:27.609064 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:30.000420 [ 81 ] {} <Debug> AsynchronousMetrics: MemoryTracking: was 333.34 MiB, peak 337.34 MiB, will set to 324.20 MiB (RSS), difference: -9.13 MiB
2021.01.25 11:03:34.855775 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:34.856558 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:34.857536 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_20_20_0 to 202101_20_20_0.
2021.01.25 11:03:34.858082 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:35.027836 [ 62 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:03:35.029627 [ 62 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:03:35.109653 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:35.114672 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:35.117868 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_20_20_0 to 202101_20_20_0.
2021.01.25 11:03:35.118933 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:42.358514 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:42.358990 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:42.360036 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_21_21_0 to 202101_21_21_0.
2021.01.25 11:03:42.360455 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:42.360514 [ 61 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Selected 6 parts from 202101_1_16_3 to 202101_21_21_0
2021.01.25 11:03:42.360927 [ 61 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:42.361225 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merging 6 parts: from 202101_1_16_3 to 202101_21_21_0 into Compact
2021.01.25 11:03:42.361490 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:03:42.361710 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_16_3, total 121 rows starting from the beginning of the part
2021.01.25 11:03:42.362044 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_17_17_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.362395 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_18_18_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.362716 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_19_19_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.363039 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_20_20_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.363404 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_21_21_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.365052 [ 101 ] {} <Debug> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merge sorted 159 rows, containing 10 columns (10 merged, 0 gathered) in 0.0038239 sec., 41580.58526635111 rows/sec., 8.52 MiB/sec.
2021.01.25 11:03:42.365788 [ 101 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_merge_202101_1_21_4 to 202101_1_21_4.
2021.01.25 11:03:42.366076 [ 101 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b) (MergerMutator): Merged 6 parts: from 202101_1_16_3 to 202101_21_21_0
2021.01.25 11:03:42.366254 [ 101 ] {} <Debug> MemoryTracker: Peak memory usage: 4.07 MiB.
2021.01.25 11:03:42.619452 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:42.625701 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:42.639641 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_21_21_0 to 202101_21_21_0.
2021.01.25 11:03:42.640442 [ 72 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Selected 6 parts from 202101_1_16_3 to 202101_21_21_0
2021.01.25 11:03:42.640811 [ 72 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:42.640959 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:42.641290 [ 101 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merging 6 parts: from 202101_1_16_3 to 202101_21_21_0 into Compact
2021.01.25 11:03:42.641995 [ 101 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:03:42.643392 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_16_3, total 121 rows starting from the beginning of the part
2021.01.25 11:03:42.646363 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_17_17_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.649459 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_18_18_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.661117 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_19_19_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.664408 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_20_20_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.667511 [ 101 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_21_21_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.693881 [ 101 ] {} <Debug> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merge sorted 158 rows, containing 255 columns (255 merged, 0 gathered) in 0.0525798 sec., 3004.9562759843134 rows/sec., 5.82 MiB/sec.
2021.01.25 11:03:42.696859 [ 101 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_merge_202101_1_21_4 to 202101_1_21_4.
2021.01.25 11:03:42.697592 [ 101 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd) (MergerMutator): Merged 6 parts: from 202101_1_16_3 to 202101_21_21_0
2021.01.25 11:03:42.697992 [ 101 ] {} <Debug> MemoryTracker: Peak memory usage: 4.10 MiB.
2021.01.25 11:03:49.861162 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:49.861858 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:49.867981 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_22_22_0 to 202101_22_22_0.
2021.01.25 11:03:49.868677 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:50.030271 [ 71 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:03:50.031682 [ 71 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:03:50.141605 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:50.146437 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:50.149623 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_22_22_0 to 202101_22_22_0.
2021.01.25 11:03:50.150781 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:57.369346 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:57.370321 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:57.372809 [ 53 ] {} <Trace> system.trace_log (62f1606a-9e94-4268-b44a-265b2b6c535b): Renaming temporary part tmp_insert_202101_23_23_0 to 202101_23_23_0.
2021.01.25 11:03:57.373429 [ 53 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:57.651471 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:57.656036 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:57.659319 [ 55 ] {} <Trace> system.metric_log (48571d47-6f6b-47ec-8a7a-7414d2b1fedd): Renaming temporary part tmp_insert_202101_23_23_0 to 202101_23_23_0.
2021.01.25 11:03:57.660478 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
Raw
clickhouse-0-1.err.log
2021.01.25 11:01:04.665971 [ 44 ] {} <Warning> Access(local directory): File /var/lib/clickhouse/access/users.list doesn't exist
2021.01.25 11:01:04.666815 [ 44 ] {} <Warning> Access(local directory): Recovering lists in directory /var/lib/clickhouse/access/
2021.01.25 11:01:04.716400 [ 44 ] {} <Warning> Application: Listen [::]:8123 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.718203 [ 44 ] {} <Warning> Application: Listen [::]:9000 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.719677 [ 44 ] {} <Warning> Application: Listen [::]:9009 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.720845 [ 44 ] {} <Warning> Application: Listen [::]:9004 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:48.795082 [ 46 ] {cda6510e-aa60-4078-a49e-f96812b7b55b} <Error> executeQuery: Code: 159, e.displayText() = DB::Exception: Watching task /clickhouse/task_queue/ddl/query-0000000001 is executing longer than distributed_ddl_task_timeout (=20) seconds. There are 2 unfinished hosts (0 of them are currently active), they are going to execute the query in background (version 21.1.2.15 (official build)) (from 127.0.0.1:40634) (in query: DROP TABLE default.test_repl ON CLUSTER 'default' NO DELAY), Stack trace (when copying this message, always include the lines below):
0. DB::Exception::Exception<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, long&, unsigned long&, unsigned long&>(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, long&, unsigned long&, unsigned long&) @ 0xeb689b3 in /usr/bin/clickhouse
1. DB::DDLQueryStatusInputStream::readImpl() @ 0xeb68273 in /usr/bin/clickhouse
2. DB::IBlockInputStream::read() @ 0xe98a1d5 in /usr/bin/clickhouse
3. DB::AsynchronousBlockInputStream::calculate() @ 0xe98649d in /usr/bin/clickhouse
4. ? @ 0xe986db8 in /usr/bin/clickhouse
5. ThreadPoolImpl<ThreadFromGlobalPool>::worker(std::__1::__list_iterator<ThreadFromGlobalPool, void*>) @ 0x86441bd in /usr/bin/clickhouse
6. ThreadFromGlobalPool::ThreadFromGlobalPool<void ThreadPoolImpl<ThreadFromGlobalPool>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda1'()>(void&&, void ThreadPoolImpl<ThreadFromGlobalPool>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda1'()&&...)::'lambda'()::operator()() @ 0x864671f in /usr/bin/clickhouse
7. ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>) @ 0x86415ed in /usr/bin/clickhouse
8. ? @ 0x86451a3 in /usr/bin/clickhouse
9. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
10. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.01.25 11:01:48.796863 [ 46 ] {cda6510e-aa60-4078-a49e-f96812b7b55b} <Error> TCPHandler: Code: 159, e.displayText() = DB::Exception: Watching task /clickhouse/task_queue/ddl/query-0000000001 is executing longer than distributed_ddl_task_timeout (=20) seconds. There are 2 unfinished hosts (0 of them are currently active), they are going to execute the query in background, Stack trace:
0. DB::Exception::Exception<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, long&, unsigned long&, unsigned long&>(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, long&, unsigned long&, unsigned long&) @ 0xeb689b3 in /usr/bin/clickhouse
1. DB::DDLQueryStatusInputStream::readImpl() @ 0xeb68273 in /usr/bin/clickhouse
2. DB::IBlockInputStream::read() @ 0xe98a1d5 in /usr/bin/clickhouse
3. DB::AsynchronousBlockInputStream::calculate() @ 0xe98649d in /usr/bin/clickhouse
4. ? @ 0xe986db8 in /usr/bin/clickhouse
5. ThreadPoolImpl<ThreadFromGlobalPool>::worker(std::__1::__list_iterator<ThreadFromGlobalPool, void*>) @ 0x86441bd in /usr/bin/clickhouse
6. ThreadFromGlobalPool::ThreadFromGlobalPool<void ThreadPoolImpl<ThreadFromGlobalPool>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda1'()>(void&&, void ThreadPoolImpl<ThreadFromGlobalPool>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda1'()&&...)::'lambda'()::operator()() @ 0x864671f in /usr/bin/clickhouse
7. ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>) @ 0x86415ed in /usr/bin/clickhouse
8. ? @ 0x86451a3 in /usr/bin/clickhouse
9. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
10. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
Raw
clickhouse-0-1.log
2021.01.25 11:01:04.247192 [ 1 ] {} <Information> Application: Will watch for the process with pid 44
2021.01.25 11:01:04.247096 [ 44 ] {} <Information> Application: Forked a child process to watch
2021.01.25 11:01:04.249019 [ 44 ] {} <Information> SentryWriter: Sending crash reports is disabled
2021.01.25 11:01:04.249726 [ 44 ] {} <Trace> Pipe: Pipe capacity is 1.00 MiB
2021.01.25 11:01:04.341996 [ 44 ] {} <Information> : Starting ClickHouse 21.1.2.15 with revision 54445, build id: E40526A12E9A8F3819A18694F6B798F10C624D5C, PID 44
2021.01.25 11:01:04.347580 [ 44 ] {} <Information> Application: starting up
2021.01.25 11:01:04.638873 [ 44 ] {} <Information> Application: Calculated checksum of the binary: F6479E166DD7E8ABFA19525726186F71, integrity check passed.
2021.01.25 11:01:04.639539 [ 44 ] {} <Information> Application: It looks like the process has no CAP_IPC_LOCK capability, binary mlock will be disabled. It could happen due to incorrect ClickHouse package installation. You could resolve the problem manually with 'sudo setcap cap_ipc_lock=+ep /usr/bin/clickhouse'. Note that it will not work on 'nosuid' mounted filesystems.
2021.01.25 11:01:04.640135 [ 44 ] {} <Debug> Application: rlimit on number of file descriptors is 1048576
2021.01.25 11:01:04.640473 [ 44 ] {} <Debug> Application: Initializing DateLUT.
2021.01.25 11:01:04.640919 [ 44 ] {} <Trace> Application: Initialized DateLUT with time zone 'UTC'.
2021.01.25 11:01:04.641406 [ 44 ] {} <Debug> Application: Setting up /var/lib/clickhouse/tmp/ to store temporary data in it
2021.01.25 11:01:04.647718 [ 44 ] {} <Debug> Application: Configuration parameter 'interserver_http_host' doesn't exist or exists and empty. Will use '891a7d56b13b' as replica host.
2021.01.25 11:01:04.648498 [ 44 ] {} <Information> SensitiveDataMaskerConfigRead: 1 query masking rules loaded.
2021.01.25 11:01:04.654655 [ 44 ] {} <Debug> ConfigReloader: Loading config '/etc/clickhouse-server/users.xml'
2021.01.25 11:01:04.662021 [ 44 ] {} <Debug> ConfigReloader: Loaded config '/etc/clickhouse-server/users.xml', performing update on configuration
2021.01.25 11:01:04.664045 [ 44 ] {} <Debug> ConfigReloader: Loaded config '/etc/clickhouse-server/users.xml', performed update on configuration
2021.01.25 11:01:04.665173 [ 44 ] {} <Debug> Access(user directories): Added users.xml access storage 'users.xml', path: /etc/clickhouse-server/users.xml
2021.01.25 11:01:04.665971 [ 44 ] {} <Warning> Access(local directory): File /var/lib/clickhouse/access/users.list doesn't exist
2021.01.25 11:01:04.666815 [ 44 ] {} <Warning> Access(local directory): Recovering lists in directory /var/lib/clickhouse/access/
2021.01.25 11:01:04.668330 [ 44 ] {} <Debug> Access(user directories): Added local directory access storage 'local directory', path: /var/lib/clickhouse/access/
2021.01.25 11:01:04.668843 [ 44 ] {} <Information> Application: Uncompressed cache size was lowered to 6.19 GiB because the system has low amount of memory
2021.01.25 11:01:04.669410 [ 44 ] {} <Information> Application: Setting max_server_memory_usage was set to 11.14 GiB (12.38 GiB available * 0.90 max_server_memory_usage_to_ram_ratio)
2021.01.25 11:01:04.670847 [ 44 ] {} <Information> Application: Loading metadata from /var/lib/clickhouse/
2021.01.25 11:01:04.679596 [ 44 ] {} <Information> DatabaseAtomic (system): Total 0 tables and 0 dictionaries.
2021.01.25 11:01:04.680132 [ 44 ] {} <Information> DatabaseAtomic (system): Starting up tables.
2021.01.25 11:01:04.699836 [ 44 ] {} <Information> DatabaseAtomic (default): Total 0 tables and 0 dictionaries.
2021.01.25 11:01:04.700243 [ 44 ] {} <Information> DatabaseAtomic (default): Starting up tables.
2021.01.25 11:01:04.700733 [ 44 ] {} <Information> DatabaseCatalog: Found 0 partially dropped tables. Will load them and retry removal.
2021.01.25 11:01:04.701122 [ 44 ] {} <Information> BackgroundSchedulePool/BgSchPool: Create BackgroundSchedulePool with 16 threads
2021.01.25 11:01:04.713440 [ 44 ] {} <Debug> Application: Loaded metadata.
2021.01.25 11:01:04.714167 [ 44 ] {} <Trace> Pipe: Pipe capacity is 1.00 MiB
2021.01.25 11:01:04.715108 [ 44 ] {} <Information> Application: It looks like the process has no CAP_SYS_NICE capability, the setting 'os_thread_priority' will have no effect. It could happen due to incorrect ClickHouse package installation. You could resolve the problem manually with 'sudo setcap cap_sys_nice=+ep /usr/bin/clickhouse'. Note that it will not work on 'nosuid' mounted filesystems.
2021.01.25 11:01:04.715333 [ 76 ] {} <Debug> DDLWorker: Started DDLWorker thread
2021.01.25 11:01:04.715413 [ 75 ] {} <Debug> DDLWorker: Started DDLWorker cleanup thread
2021.01.25 11:01:04.716400 [ 44 ] {} <Warning> Application: Listen [::]:8123 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.718203 [ 44 ] {} <Warning> Application: Listen [::]:9000 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.719677 [ 44 ] {} <Warning> Application: Listen [::]:9009 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.720845 [ 44 ] {} <Warning> Application: Listen [::]:9004 failed: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = DNS error: EAI: Address family for hostname not supported (version 21.1.2.15 (official build)). If it is an IPv6 or IPv4 address and your host has disabled IPv6 or IPv4, then consider to specify not disabled IPv4 or IPv6 address to listen in <listen_host> element of configuration file. Example for disabled IPv6: <listen_host>0.0.0.0</listen_host> . Example for disabled IPv4: <listen_host>::</listen_host>
2021.01.25 11:01:04.721783 [ 44 ] {} <Information> Application: Listening for http://0.0.0.0:8123
2021.01.25 11:01:04.722370 [ 44 ] {} <Information> Application: Listening for connections with native protocol (tcp): 0.0.0.0:9000
2021.01.25 11:01:04.722859 [ 44 ] {} <Information> Application: Listening for replica communication (interserver): http://0.0.0.0:9009
2021.01.25 11:01:04.723954 [ 44 ] {} <Trace> MySQLHandlerFactory: Failed to create SSL context. SSL will be disabled. Error: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = SSL context exception: Error loading private key from file /etc/clickhouse-server/server.key: error:02000002:system library:OPENSSL_internal:No such file or directory (version 21.1.2.15 (official build))
2021.01.25 11:01:04.724731 [ 44 ] {} <Trace> MySQLHandlerFactory: Failed to read RSA key pair from server certificate. Error: Code: 76, e.displayText() = DB::Exception: Cannot open certificate file: /etc/clickhouse-server/server.crt. (version 21.1.2.15 (official build))
2021.01.25 11:01:04.725244 [ 44 ] {} <Trace> MySQLHandlerFactory: Generating new RSA key pair.
2021.01.25 11:01:04.789591 [ 76 ] {} <Trace> ZooKeeper: Initialized, hosts: zookeeper:2181
2021.01.25 11:01:04.843335 [ 76 ] {} <Debug> DDLWorker: Scheduling tasks
2021.01.25 11:01:04.843466 [ 75 ] {} <Debug> DDLWorker: Cleaning queue
2021.01.25 11:01:04.853212 [ 76 ] {} <Debug> DDLWorker: Waiting a watch
2021.01.25 11:01:04.860140 [ 44 ] {} <Information> Application: Listening for MySQL compatibility protocol: 0.0.0.0:9004
2021.01.25 11:01:04.861858 [ 44 ] {} <Information> DNSCacheUpdater: Update period 15 seconds
2021.01.25 11:01:04.862320 [ 44 ] {} <Information> Application: Available RAM: 12.38 GiB; physical cores: 4; logical cores: 8.
2021.01.25 11:01:04.862365 [ 59 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:01:04.862662 [ 44 ] {} <Information> Application: Ready for connections.
2021.01.25 11:01:04.863034 [ 59 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:01:06.869293 [ 87 ] {} <Debug> ConfigReloader: Loading config '/etc/clickhouse-server/config.xml'
2021.01.25 11:01:06.881643 [ 87 ] {} <Debug> ConfigReloader: Loaded config '/etc/clickhouse-server/config.xml', performing update on configuration
2021.01.25 11:01:06.885593 [ 87 ] {} <Debug> ConfigReloader: Loaded config '/etc/clickhouse-server/config.xml', performed update on configuration
2021.01.25 11:01:11.394045 [ 76 ] {} <Debug> DDLWorker: Scheduling tasks
2021.01.25 11:01:11.394096 [ 75 ] {} <Trace> DDLWorker: Too early to clean queue, will do it later.
2021.01.25 11:01:11.414390 [ 76 ] {} <Debug> DDLWorker: Waiting a watch
2021.01.25 11:01:11.414600 [ 89 ] {} <Debug> DDLWorker: Processing task query-0000000000 (CREATE TABLE default.test_repl UUID 'b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026' ON CLUSTER default (`n` UInt64) ENGINE = ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl', '{replica}') ORDER BY tuple())
2021.01.25 11:01:11.421364 [ 89 ] {} <Debug> DDLWorker: Executing query: CREATE TABLE default.test_repl UUID 'b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026' (`n` UInt64) ENGINE = ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl', '{replica}') ORDER BY tuple()
2021.01.25 11:01:11.422259 [ 89 ] {877f7e84-059c-425b-a644-307cdb3f7c36} <Debug> executeQuery: (from 0.0.0.0:0, user: , using production parser) /* ddl_entry=query-0000000000 */ CREATE TABLE default.test_repl UUID 'b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026' (`n` UInt64) ENGINE = ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl', '{replica}') ORDER BY tuple()
2021.01.25 11:01:11.431368 [ 89 ] {877f7e84-059c-425b-a644-307cdb3f7c36} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Loading data parts
2021.01.25 11:01:11.433049 [ 89 ] {877f7e84-059c-425b-a644-307cdb3f7c36} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Loaded data parts (0 items)
2021.01.25 11:01:11.455319 [ 89 ] {877f7e84-059c-425b-a644-307cdb3f7c36} <Debug> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Creating table /clickhouse/tables/0/test_repl
2021.01.25 11:01:11.553802 [ 61 ] {} <Debug> default.test_repl (ReplicatedMergeTreeRestartingThread): Activating replica.
2021.01.25 11:01:11.569707 [ 61 ] {} <Debug> default.test_repl (ReplicatedMergeTreeQueue): Loading queue from /clickhouse/tables/0/test_repl/replicas/clickhouse-0-1/queue
2021.01.25 11:01:11.573698 [ 61 ] {} <Debug> default.test_repl (ReplicatedMergeTreeQueue): Having 0 queue entries to load, 0 entries already loaded.
2021.01.25 11:01:11.576358 [ 61 ] {} <Trace> default.test_repl (ReplicatedMergeTreeQueue): Loaded queue
2021.01.25 11:01:11.601097 [ 89 ] {877f7e84-059c-425b-a644-307cdb3f7c36} <Debug> DDLWorker: Executed query: CREATE TABLE default.test_repl UUID 'b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026' (`n` UInt64) ENGINE = ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl', '{replica}') ORDER BY tuple()
2021.01.25 11:01:11.609301 [ 62 ] {} <Information> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Became leader
2021.01.25 11:01:12.184544 [ 53 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 2 entries to flush
2021.01.25 11:01:12.185063 [ 53 ] {} <Debug> SystemLog (system.query_log): Creating new table system.query_log for QueryLog
2021.01.25 11:01:12.186750 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushing system log, 1 entries to flush
2021.01.25 11:01:12.187241 [ 52 ] {} <Debug> SystemLog (system.query_thread_log): Creating new table system.query_thread_log for QueryThreadLog
2021.01.25 11:01:12.189336 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:12.189541 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 2 entries to flush
2021.01.25 11:01:12.189813 [ 55 ] {} <Debug> SystemLog (system.metric_log): Creating new table system.metric_log for MetricLog
2021.01.25 11:01:12.190165 [ 54 ] {} <Debug> SystemLog (system.trace_log): Creating new table system.trace_log for TraceLog
2021.01.25 11:01:12.193852 [ 53 ] {} <Debug> system.query_log (58fc1786-5bef-48ec-999c-b6f58bd6dfd9): Loading data parts
2021.01.25 11:01:12.194802 [ 53 ] {} <Debug> system.query_log (58fc1786-5bef-48ec-999c-b6f58bd6dfd9): Loaded data parts (0 items)
2021.01.25 11:01:12.201047 [ 54 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Loading data parts
2021.01.25 11:01:12.201082 [ 52 ] {} <Debug> system.query_thread_log (d3a6fc83-9b72-4308-9a4f-abe980ecba17): Loading data parts
2021.01.25 11:01:12.201825 [ 54 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Loaded data parts (0 items)
2021.01.25 11:01:12.202554 [ 52 ] {} <Debug> system.query_thread_log (d3a6fc83-9b72-4308-9a4f-abe980ecba17): Loaded data parts (0 items)
2021.01.25 11:01:12.204063 [ 55 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Loading data parts
2021.01.25 11:01:12.204883 [ 55 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Loaded data parts (0 items)
2021.01.25 11:01:12.205863 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:12.208902 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:12.209441 [ 52 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:12.209850 [ 53 ] {} <Trace> system.query_log (58fc1786-5bef-48ec-999c-b6f58bd6dfd9): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:01:12.210695 [ 53 ] {} <Trace> SystemLog (system.query_log): Flushed system log
2021.01.25 11:01:12.210928 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:01:12.211860 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:12.212227 [ 52 ] {} <Trace> system.query_thread_log (d3a6fc83-9b72-4308-9a4f-abe980ecba17): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:01:12.213055 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushed system log
2021.01.25 11:01:12.215495 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:12.222474 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:01:12.224046 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:19.535058 [ 46 ] {} <Trace> TCPHandlerFactory: TCP Request. Address: 127.0.0.1:40632
2021.01.25 11:01:19.535708 [ 46 ] {} <Debug> TCPHandler: Connected ClickHouse client version 21.1.0, revision: 54443, user: default.
2021.01.25 11:01:19.536269 [ 46 ] {} <Trace> ContextAccess (default): Settings: readonly=0, allow_ddl=true, allow_introspection_functions=false
2021.01.25 11:01:19.536655 [ 46 ] {} <Trace> ContextAccess (default): List of all grants: GRANT SHOW, SELECT, INSERT, ALTER, CREATE, DROP, TRUNCATE, OPTIMIZE, KILL QUERY, SYSTEM, dictGet, INTROSPECTION, SOURCES ON *.*
2021.01.25 11:01:19.536979 [ 46 ] {} <Trace> ContextAccess (default): List of all grants including implicit: GRANT SHOW, SELECT, INSERT, ALTER, CREATE, DROP, TRUNCATE, OPTIMIZE, KILL QUERY, SYSTEM, dictGet, INTROSPECTION, SOURCES ON *.*
2021.01.25 11:01:19.546550 [ 46 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Debug> executeQuery: (from 127.0.0.1:40632, using production parser) SELECT count() FROM default.test_repl
2021.01.25 11:01:19.548163 [ 46 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Trace> ContextAccess (default): Access granted: SELECT(n) ON default.test_repl
2021.01.25 11:01:19.548984 [ 46 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Trace> InterpreterSelectQuery: WithMergeableState -> Complete
2021.01.25 11:01:19.550313 [ 90 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Trace> MergingAggregatedTransform: Reading blocks of partially aggregated data.
2021.01.25 11:01:19.550772 [ 90 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Trace> MergingAggregatedTransform: Read 1 blocks of partially aggregated data, total 1 rows.
2021.01.25 11:01:19.551184 [ 90 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Trace> Aggregator: Merging partially aggregated single-level data.
2021.01.25 11:01:19.551652 [ 90 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Trace> Aggregator: Merged partially aggregated single-level data.
2021.01.25 11:01:19.552060 [ 90 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Trace> Aggregator: Converting aggregated data to blocks
2021.01.25 11:01:19.552434 [ 90 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Trace> Aggregator: Converted aggregated data to blocks. 1 rows, 8.00 B in 2.56e-05 sec. (39062.5 rows/sec., 305.18 KiB/sec.)
2021.01.25 11:01:19.553897 [ 46 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Information> executeQuery: Read 1 rows, 4.01 KiB in 0.0067331 sec., 148 rows/sec., 595.24 KiB/sec.
2021.01.25 11:01:19.554335 [ 46 ] {63a77128-2f92-4f30-a765-f25eeb577583} <Debug> MemoryTracker: Peak memory usage (for query): 0.00 B.
2021.01.25 11:01:19.555055 [ 46 ] {} <Debug> TCPHandler: Processed in 0.0093999 sec.
2021.01.25 11:01:19.623116 [ 46 ] {} <Debug> TCPHandler: Done processing connection.
2021.01.25 11:01:19.711308 [ 53 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 2 entries to flush
2021.01.25 11:01:19.712508 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 9 entries to flush
2021.01.25 11:01:19.713327 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:19.713623 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushing system log, 2 entries to flush
2021.01.25 11:01:19.713882 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:19.716044 [ 52 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:19.716719 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:01:19.717389 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:19.717890 [ 53 ] {} <Trace> system.query_log (58fc1786-5bef-48ec-999c-b6f58bd6dfd9): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:01:19.718457 [ 52 ] {} <Trace> system.query_thread_log (d3a6fc83-9b72-4308-9a4f-abe980ecba17): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:01:19.718714 [ 53 ] {} <Trace> SystemLog (system.query_log): Flushed system log
2021.01.25 11:01:19.719299 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushed system log
2021.01.25 11:01:19.724745 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:19.730794 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:19.736090 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:01:19.737698 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:19.864225 [ 64 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:01:19.868710 [ 64 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:01:27.218025 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:27.235281 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:27.238329 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:01:27.239722 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_3_3_0 to 202101_3_3_0.
2021.01.25 11:01:27.264014 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:27.268706 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:27.297124 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_3_3_0 to 202101_3_3_0.
2021.01.25 11:01:27.309693 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:27.769058 [ 46 ] {} <Trace> TCPHandlerFactory: TCP Request. Address: 127.0.0.1:40634
2021.01.25 11:01:27.770429 [ 46 ] {} <Debug> TCPHandler: Connected ClickHouse client version 21.1.0, revision: 54443, user: default.
2021.01.25 11:01:27.795929 [ 46 ] {cda6510e-aa60-4078-a49e-f96812b7b55b} <Debug> executeQuery: (from 127.0.0.1:40634, using production parser) DROP TABLE default.test_repl ON CLUSTER 'default' NO DELAY
2021.01.25 11:01:27.809422 [ 46 ] {cda6510e-aa60-4078-a49e-f96812b7b55b} <Trace> ContextAccess (default): Access granted: DROP TABLE, DROP VIEW ON default.test_repl
2021.01.25 11:01:27.973290 [ 76 ] {} <Debug> DDLWorker: Scheduling tasks
2021.01.25 11:01:27.973333 [ 75 ] {} <Trace> DDLWorker: Too early to clean queue, will do it later.
2021.01.25 11:01:28.036710 [ 46 ] {cda6510e-aa60-4078-a49e-f96812b7b55b} <Debug> executeQuery: Query pipeline:
DDLQueryStatusInputStream
2021.01.25 11:01:28.042448 [ 76 ] {} <Debug> DDLWorker: Waiting a watch
2021.01.25 11:01:28.042510 [ 89 ] {877f7e84-059c-425b-a644-307cdb3f7c36} <Debug> DDLWorker: Processing task query-0000000001 (DROP TABLE default.test_repl ON CLUSTER default NO DELAY)
2021.01.25 11:01:28.082010 [ 89 ] {877f7e84-059c-425b-a644-307cdb3f7c36} <Debug> DDLWorker: Executing query: DROP TABLE default.test_repl NO DELAY
2021.01.25 11:01:28.087650 [ 89 ] {9ba7a9f3-1952-4402-9ed3-6425b7ef6f52} <Debug> executeQuery: (from 0.0.0.0:0, user: , using production parser) /* ddl_entry=query-0000000001 */ DROP TABLE default.test_repl NO DELAY
2021.01.25 11:01:28.090152 [ 89 ] {9ba7a9f3-1952-4402-9ed3-6425b7ef6f52} <Trace> default.test_repl (ReplicatedMergeTreeRestartingThread): Restarting thread finished
2021.01.25 11:01:28.118688 [ 89 ] {9ba7a9f3-1952-4402-9ed3-6425b7ef6f52} <Trace> default.test_repl (ReplicatedMergeTreeRestartingThread): Waiting for threads to finish
2021.01.25 11:01:28.161884 [ 89 ] {9ba7a9f3-1952-4402-9ed3-6425b7ef6f52} <Information> default.test_repl (b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026): Stopped being leader
2021.01.25 11:01:28.241959 [ 89 ] {9ba7a9f3-1952-4402-9ed3-6425b7ef6f52} <Trace> default.test_repl (ReplicatedMergeTreeRestartingThread): Threads finished
2021.01.25 11:01:28.256851 [ 89 ] {9ba7a9f3-1952-4402-9ed3-6425b7ef6f52} <Debug> DatabaseCatalog: Waiting for table b6c8cc2f-6c50-4fa7-a8ca-c87642cf9026 to be finally dropped
2021.01.25 11:01:30.000342 [ 81 ] {} <Debug> AsynchronousMetrics: MemoryTracking: was 6.99 MiB, peak 14.93 MiB, will set to 313.04 MiB (RSS), difference: 306.05 MiB
2021.01.25 11:01:34.719696 [ 53 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 1 entries to flush
2021.01.25 11:01:34.721655 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:34.725061 [ 53 ] {} <Trace> system.query_log (58fc1786-5bef-48ec-999c-b6f58bd6dfd9): Renaming temporary part tmp_insert_202101_3_3_0 to 202101_3_3_0.
2021.01.25 11:01:34.726000 [ 53 ] {} <Trace> SystemLog (system.query_log): Flushed system log
2021.01.25 11:01:34.774436 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 24 entries to flush
2021.01.25 11:01:34.775447 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:34.779762 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_4_4_0 to 202101_4_4_0.
2021.01.25 11:01:34.780758 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:34.826417 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:34.833324 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:34.838601 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_4_4_0 to 202101_4_4_0.
2021.01.25 11:01:34.840232 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:34.870151 [ 67 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:01:34.872935 [ 67 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:01:42.281437 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 23 entries to flush
2021.01.25 11:01:42.282335 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:42.284036 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_5_5_0 to 202101_5_5_0.
2021.01.25 11:01:42.284719 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:42.340818 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:01:42.345320 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:42.350196 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_5_5_0 to 202101_5_5_0.
2021.01.25 11:01:42.351690 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:48.795082 [ 46 ] {cda6510e-aa60-4078-a49e-f96812b7b55b} <Error> executeQuery: Code: 159, e.displayText() = DB::Exception: Watching task /clickhouse/task_queue/ddl/query-0000000001 is executing longer than distributed_ddl_task_timeout (=20) seconds. There are 2 unfinished hosts (0 of them are currently active), they are going to execute the query in background (version 21.1.2.15 (official build)) (from 127.0.0.1:40634) (in query: DROP TABLE default.test_repl ON CLUSTER 'default' NO DELAY), Stack trace (when copying this message, always include the lines below):
0. DB::Exception::Exception<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, long&, unsigned long&, unsigned long&>(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, long&, unsigned long&, unsigned long&) @ 0xeb689b3 in /usr/bin/clickhouse
1. DB::DDLQueryStatusInputStream::readImpl() @ 0xeb68273 in /usr/bin/clickhouse
2. DB::IBlockInputStream::read() @ 0xe98a1d5 in /usr/bin/clickhouse
3. DB::AsynchronousBlockInputStream::calculate() @ 0xe98649d in /usr/bin/clickhouse
4. ? @ 0xe986db8 in /usr/bin/clickhouse
5. ThreadPoolImpl<ThreadFromGlobalPool>::worker(std::__1::__list_iterator<ThreadFromGlobalPool, void*>) @ 0x86441bd in /usr/bin/clickhouse
6. ThreadFromGlobalPool::ThreadFromGlobalPool<void ThreadPoolImpl<ThreadFromGlobalPool>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda1'()>(void&&, void ThreadPoolImpl<ThreadFromGlobalPool>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda1'()&&...)::'lambda'()::operator()() @ 0x864671f in /usr/bin/clickhouse
7. ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>) @ 0x86415ed in /usr/bin/clickhouse
8. ? @ 0x86451a3 in /usr/bin/clickhouse
9. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
10. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.01.25 11:01:48.796863 [ 46 ] {cda6510e-aa60-4078-a49e-f96812b7b55b} <Error> TCPHandler: Code: 159, e.displayText() = DB::Exception: Watching task /clickhouse/task_queue/ddl/query-0000000001 is executing longer than distributed_ddl_task_timeout (=20) seconds. There are 2 unfinished hosts (0 of them are currently active), they are going to execute the query in background, Stack trace:
0. DB::Exception::Exception<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, long&, unsigned long&, unsigned long&>(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, long&, unsigned long&, unsigned long&) @ 0xeb689b3 in /usr/bin/clickhouse
1. DB::DDLQueryStatusInputStream::readImpl() @ 0xeb68273 in /usr/bin/clickhouse
2. DB::IBlockInputStream::read() @ 0xe98a1d5 in /usr/bin/clickhouse
3. DB::AsynchronousBlockInputStream::calculate() @ 0xe98649d in /usr/bin/clickhouse
4. ? @ 0xe986db8 in /usr/bin/clickhouse
5. ThreadPoolImpl<ThreadFromGlobalPool>::worker(std::__1::__list_iterator<ThreadFromGlobalPool, void*>) @ 0x86441bd in /usr/bin/clickhouse
6. ThreadFromGlobalPool::ThreadFromGlobalPool<void ThreadPoolImpl<ThreadFromGlobalPool>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda1'()>(void&&, void ThreadPoolImpl<ThreadFromGlobalPool>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda1'()&&...)::'lambda'()::operator()() @ 0x864671f in /usr/bin/clickhouse
7. ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>) @ 0x86415ed in /usr/bin/clickhouse
8. ? @ 0x86451a3 in /usr/bin/clickhouse
9. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
10. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.01.25 11:01:48.798792 [ 46 ] {cda6510e-aa60-4078-a49e-f96812b7b55b} <Debug> MemoryTracker: Peak memory usage (for query): 13.91 KiB.
2021.01.25 11:01:48.799297 [ 46 ] {} <Debug> MemoryTracker: Peak memory usage (for query): 13.91 KiB.
2021.01.25 11:01:48.799743 [ 46 ] {} <Debug> TCPHandler: Processed in 21.0045846 sec.
2021.01.25 11:01:48.800844 [ 46 ] {} <Debug> TCPHandler: Done processing connection.
2021.01.25 11:01:49.720400 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushing system log, 2 entries to flush
2021.01.25 11:01:49.722579 [ 52 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.725278 [ 52 ] {} <Trace> system.query_thread_log (d3a6fc83-9b72-4308-9a4f-abe980ecba17): Renaming temporary part tmp_insert_202101_3_3_0 to 202101_3_3_0.
2021.01.25 11:01:49.726429 [ 52 ] {} <Trace> SystemLog (system.query_thread_log): Flushed system log
2021.01.25 11:01:49.726919 [ 53 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 1 entries to flush
2021.01.25 11:01:49.729036 [ 53 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.731930 [ 53 ] {} <Trace> system.query_log (58fc1786-5bef-48ec-999c-b6f58bd6dfd9): Renaming temporary part tmp_insert_202101_4_4_0 to 202101_4_4_0.
2021.01.25 11:01:49.734203 [ 53 ] {} <Trace> SystemLog (system.query_log): Flushed system log
2021.01.25 11:01:49.785302 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 20 entries to flush
2021.01.25 11:01:49.786292 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.787832 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_6_6_0 to 202101_6_6_0.
2021.01.25 11:01:49.788750 [ 69 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Selected 6 parts from 202101_1_1_0 to 202101_6_6_0
2021.01.25 11:01:49.788974 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:49.789333 [ 69 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.790576 [ 90 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merging 6 parts: from 202101_1_1_0 to 202101_6_6_0 into Compact
2021.01.25 11:01:49.791217 [ 90 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:01:49.791713 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_1_0, total 2 rows starting from the beginning of the part
2021.01.25 11:01:49.792622 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_2_2_0, total 9 rows starting from the beginning of the part
2021.01.25 11:01:49.793544 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_3_3_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.794435 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_4_4_0, total 24 rows starting from the beginning of the part
2021.01.25 11:01:49.795467 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_5_5_0, total 23 rows starting from the beginning of the part
2021.01.25 11:01:49.796611 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_6_6_0, total 20 rows starting from the beginning of the part
2021.01.25 11:01:49.800540 [ 90 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merge sorted 86 rows, containing 10 columns (10 merged, 0 gathered) in 0.0100099 sec., 8591.49442052368 rows/sec., 1.58 MiB/sec.
2021.01.25 11:01:49.802158 [ 90 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_merge_202101_1_6_1 to 202101_1_6_1.
2021.01.25 11:01:49.802884 [ 90 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merged 6 parts: from 202101_1_1_0 to 202101_6_6_0
2021.01.25 11:01:49.803652 [ 90 ] {} <Debug> MemoryTracker: Peak memory usage: 4.05 MiB.
2021.01.25 11:01:49.852319 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:49.860396 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.866615 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_6_6_0 to 202101_6_6_0.
2021.01.25 11:01:49.868017 [ 62 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Selected 6 parts from 202101_1_1_0 to 202101_6_6_0
2021.01.25 11:01:49.868676 [ 62 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:49.869552 [ 92 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merging 6 parts: from 202101_1_1_0 to 202101_6_6_0 into Compact
2021.01.25 11:01:49.869610 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:01:49.870703 [ 92 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:01:49.872114 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_1_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.873711 [ 71 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:01:49.877294 [ 71 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:01:49.877397 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_2_2_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.882348 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_3_3_0, total 7 rows starting from the beginning of the part
2021.01.25 11:01:49.886161 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_4_4_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.890538 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_5_5_0, total 7 rows starting from the beginning of the part
2021.01.25 11:01:49.894930 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_6_6_0, total 8 rows starting from the beginning of the part
2021.01.25 11:01:49.949121 [ 92 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merge sorted 46 rows, containing 255 columns (255 merged, 0 gathered) in 0.0795918 sec., 577.9489846944032 rows/sec., 1.12 MiB/sec.
2021.01.25 11:01:49.954371 [ 92 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_merge_202101_1_6_1 to 202101_1_6_1.
2021.01.25 11:01:49.955818 [ 92 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merged 6 parts: from 202101_1_1_0 to 202101_6_6_0
2021.01.25 11:01:49.956429 [ 92 ] {} <Debug> MemoryTracker: Peak memory usage: 4.10 MiB.
2021.01.25 11:01:57.290044 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:01:57.291180 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:57.293153 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_7_7_0 to 202101_7_7_0.
2021.01.25 11:01:57.294890 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:01:57.371008 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:01:57.379809 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:01:57.385909 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_7_7_0 to 202101_7_7_0.
2021.01.25 11:01:57.387715 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:04.690598 [ 56 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushing system log, 53 entries to flush
2021.01.25 11:02:04.691253 [ 56 ] {} <Debug> SystemLog (system.asynchronous_metric_log): Creating new table system.asynchronous_metric_log for AsynchronousMetricLog
2021.01.25 11:02:04.703650 [ 56 ] {} <Debug> system.asynchronous_metric_log (094de0e3-1860-436f-8541-44efb46fb5b9): Loading data parts
2021.01.25 11:02:04.704562 [ 56 ] {} <Debug> system.asynchronous_metric_log (094de0e3-1860-436f-8541-44efb46fb5b9): Loaded data parts (0 items)
2021.01.25 11:02:04.718110 [ 56 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:04.721556 [ 56 ] {} <Trace> system.asynchronous_metric_log (094de0e3-1860-436f-8541-44efb46fb5b9): Renaming temporary part tmp_insert_202101_1_1_0 to 202101_1_1_0.
2021.01.25 11:02:04.722391 [ 56 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushed system log
2021.01.25 11:02:04.795995 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:04.797005 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:04.798909 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_8_8_0 to 202101_8_8_0.
2021.01.25 11:02:04.799705 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:04.878345 [ 72 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:02:04.880353 [ 72 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:02:04.888348 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:04.896271 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:04.901610 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_8_8_0 to 202101_8_8_0.
2021.01.25 11:02:04.904175 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:12.300568 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:12.301477 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:12.302663 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_9_9_0 to 202101_9_9_0.
2021.01.25 11:02:12.303284 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:12.405006 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:12.410463 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:12.418800 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_9_9_0 to 202101_9_9_0.
2021.01.25 11:02:12.419924 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:19.803906 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:19.804850 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:19.806299 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_10_10_0 to 202101_10_10_0.
2021.01.25 11:02:19.807037 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:19.881309 [ 71 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:02:19.883197 [ 71 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:02:19.920518 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:19.926552 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:19.930636 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_10_10_0 to 202101_10_10_0.
2021.01.25 11:02:19.932307 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:27.307532 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:27.308304 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:27.309287 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_11_11_0 to 202101_11_11_0.
2021.01.25 11:02:27.309962 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:27.310032 [ 66 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Selected 6 parts from 202101_1_6_1 to 202101_11_11_0
2021.01.25 11:02:27.310743 [ 66 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:27.311131 [ 93 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merging 6 parts: from 202101_1_6_1 to 202101_11_11_0 into Compact
2021.01.25 11:02:27.311538 [ 93 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:02:27.311921 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_6_1, total 86 rows starting from the beginning of the part
2021.01.25 11:02:27.312502 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_7_7_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.313038 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_8_8_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.313601 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_9_9_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.314207 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_10_10_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.314772 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_11_11_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.316712 [ 93 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merge sorted 124 rows, containing 10 columns (10 merged, 0 gathered) in 0.0055892 sec., 22185.643741501466 rows/sec., 4.28 MiB/sec.
2021.01.25 11:02:27.317812 [ 93 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_merge_202101_1_11_2 to 202101_1_11_2.
2021.01.25 11:02:27.318405 [ 93 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merged 6 parts: from 202101_1_6_1 to 202101_11_11_0
2021.01.25 11:02:27.318817 [ 93 ] {} <Debug> MemoryTracker: Peak memory usage: 4.05 MiB.
2021.01.25 11:02:27.432926 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:27.439325 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:27.448096 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_11_11_0 to 202101_11_11_0.
2021.01.25 11:02:27.448880 [ 70 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Selected 6 parts from 202101_1_6_1 to 202101_11_11_0
2021.01.25 11:02:27.449232 [ 70 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:27.449334 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:27.449715 [ 91 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merging 6 parts: from 202101_1_6_1 to 202101_11_11_0 into Compact
2021.01.25 11:02:27.450725 [ 91 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:02:27.453473 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_6_1, total 46 rows starting from the beginning of the part
2021.01.25 11:02:27.456042 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_7_7_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.458399 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_8_8_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.460769 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_9_9_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.463018 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_10_10_0, total 8 rows starting from the beginning of the part
2021.01.25 11:02:27.465279 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_11_11_0, total 7 rows starting from the beginning of the part
2021.01.25 11:02:27.486742 [ 91 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merge sorted 83 rows, containing 255 columns (255 merged, 0 gathered) in 0.0370322 sec., 2241.2927128282954 rows/sec., 4.34 MiB/sec.
2021.01.25 11:02:27.489423 [ 91 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_merge_202101_1_11_2 to 202101_1_11_2.
2021.01.25 11:02:27.490104 [ 91 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merged 6 parts: from 202101_1_6_1 to 202101_11_11_0
2021.01.25 11:02:27.490540 [ 91 ] {} <Debug> MemoryTracker: Peak memory usage: 4.10 MiB.
2021.01.25 11:02:30.000308 [ 81 ] {} <Debug> AsynchronousMetrics: MemoryTracking: was 313.54 MiB, peak 317.59 MiB, will set to 318.41 MiB (RSS), difference: 4.87 MiB
2021.01.25 11:02:34.810578 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:34.811443 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:34.818247 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_12_12_0 to 202101_12_12_0.
2021.01.25 11:02:34.819228 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:34.884223 [ 58 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:02:34.886392 [ 58 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:02:34.950276 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:34.957911 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:34.961945 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_12_12_0 to 202101_12_12_0.
2021.01.25 11:02:34.963577 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:42.319865 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 9 entries to flush
2021.01.25 11:02:42.320688 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:42.321787 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_13_13_0 to 202101_13_13_0.
2021.01.25 11:02:42.322414 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:42.464430 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:42.469105 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:42.471869 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_13_13_0 to 202101_13_13_0.
2021.01.25 11:02:42.472862 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:49.822883 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:49.823792 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:49.824961 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_14_14_0 to 202101_14_14_0.
2021.01.25 11:02:49.825581 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:49.887689 [ 61 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:02:49.889206 [ 61 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:02:49.973443 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:49.978798 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:49.982017 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_14_14_0 to 202101_14_14_0.
2021.01.25 11:02:49.983472 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:02:57.326204 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:02:57.327020 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:57.333911 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_15_15_0 to 202101_15_15_0.
2021.01.25 11:02:57.334472 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:02:57.484088 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:02:57.488711 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:02:57.496778 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_15_15_0 to 202101_15_15_0.
2021.01.25 11:02:57.497884 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:04.723001 [ 56 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushing system log, 53 entries to flush
2021.01.25 11:03:04.724034 [ 56 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:04.725285 [ 56 ] {} <Trace> system.asynchronous_metric_log (094de0e3-1860-436f-8541-44efb46fb5b9): Renaming temporary part tmp_insert_202101_2_2_0 to 202101_2_2_0.
2021.01.25 11:03:04.725989 [ 56 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushed system log
2021.01.25 11:03:04.835013 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:04.835979 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:04.837733 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_16_16_0 to 202101_16_16_0.
2021.01.25 11:03:04.838490 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:04.838617 [ 62 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Selected 6 parts from 202101_1_11_2 to 202101_16_16_0
2021.01.25 11:03:04.839430 [ 62 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:04.840019 [ 92 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merging 6 parts: from 202101_1_11_2 to 202101_16_16_0 into Compact
2021.01.25 11:03:04.840424 [ 92 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:03:04.840791 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_11_2, total 124 rows starting from the beginning of the part
2021.01.25 11:03:04.841362 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_12_12_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:04.842000 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_13_13_0, total 9 rows starting from the beginning of the part
2021.01.25 11:03:04.842664 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_14_14_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:04.843269 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_15_15_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:04.843961 [ 92 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_16_16_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:04.848388 [ 92 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merge sorted 162 rows, containing 10 columns (10 merged, 0 gathered) in 0.0083594 sec., 19379.381295308278 rows/sec., 3.83 MiB/sec.
2021.01.25 11:03:04.849816 [ 92 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_merge_202101_1_16_3 to 202101_1_16_3.
2021.01.25 11:03:04.850350 [ 92 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merged 6 parts: from 202101_1_11_2 to 202101_16_16_0
2021.01.25 11:03:04.850737 [ 92 ] {} <Debug> MemoryTracker: Peak memory usage: 4.07 MiB.
2021.01.25 11:03:04.889984 [ 71 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:03:04.891928 [ 71 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:03:04.998494 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:05.004783 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:05.008843 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_16_16_0 to 202101_16_16_0.
2021.01.25 11:03:05.009738 [ 63 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Selected 6 parts from 202101_1_11_2 to 202101_16_16_0
2021.01.25 11:03:05.010235 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:05.010268 [ 63 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:05.011386 [ 91 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merging 6 parts: from 202101_1_11_2 to 202101_16_16_0 into Compact
2021.01.25 11:03:05.012335 [ 91 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:03:05.013438 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_11_2, total 83 rows starting from the beginning of the part
2021.01.25 11:03:05.016244 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_12_12_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:05.019016 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_13_13_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:05.021883 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_14_14_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:05.024729 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_15_15_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:05.027551 [ 91 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_16_16_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:05.057464 [ 91 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merge sorted 121 rows, containing 255 columns (255 merged, 0 gathered) in 0.0460623 sec., 2626.8770773495894 rows/sec., 5.09 MiB/sec.
2021.01.25 11:03:05.060215 [ 91 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_merge_202101_1_16_3 to 202101_1_16_3.
2021.01.25 11:03:05.061031 [ 91 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merged 6 parts: from 202101_1_11_2 to 202101_16_16_0
2021.01.25 11:03:05.061440 [ 91 ] {} <Debug> MemoryTracker: Peak memory usage: 4.10 MiB.
2021.01.25 11:03:12.339346 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:12.340262 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:12.341300 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_17_17_0 to 202101_17_17_0.
2021.01.25 11:03:12.341853 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:12.510911 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:12.515847 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:12.519217 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_17_17_0 to 202101_17_17_0.
2021.01.25 11:03:12.520482 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:19.842262 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:19.843060 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:19.844239 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_18_18_0 to 202101_18_18_0.
2021.01.25 11:03:19.844777 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:19.892899 [ 67 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:03:19.894516 [ 67 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:03:20.021036 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:20.025234 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:20.028154 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_18_18_0 to 202101_18_18_0.
2021.01.25 11:03:20.029377 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:27.345351 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:27.346137 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:27.347072 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_19_19_0 to 202101_19_19_0.
2021.01.25 11:03:27.347660 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:27.530147 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:27.535135 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:27.538305 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_19_19_0 to 202101_19_19_0.
2021.01.25 11:03:27.539503 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:30.000420 [ 81 ] {} <Debug> AsynchronousMetrics: MemoryTracking: was 318.76 MiB, peak 322.76 MiB, will set to 318.78 MiB (RSS), difference: 21.94 KiB
2021.01.25 11:03:34.848471 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:34.849246 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:34.850212 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_20_20_0 to 202101_20_20_0.
2021.01.25 11:03:34.850732 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:34.895211 [ 64 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:03:34.896718 [ 64 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:03:35.040060 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:35.044663 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:35.047579 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_20_20_0 to 202101_20_20_0.
2021.01.25 11:03:35.048637 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:42.351342 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:42.352195 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:42.353421 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_21_21_0 to 202101_21_21_0.
2021.01.25 11:03:42.353936 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:42.354025 [ 71 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Selected 6 parts from 202101_1_16_3 to 202101_21_21_0
2021.01.25 11:03:42.354795 [ 71 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:42.355262 [ 90 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merging 6 parts: from 202101_1_16_3 to 202101_21_21_0 into Compact
2021.01.25 11:03:42.355696 [ 90 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:03:42.356088 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_16_3, total 162 rows starting from the beginning of the part
2021.01.25 11:03:42.356630 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_17_17_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.357069 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_18_18_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.357404 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_19_19_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.357724 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_20_20_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.358123 [ 90 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_21_21_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.359766 [ 90 ] {} <Debug> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merge sorted 200 rows, containing 10 columns (10 merged, 0 gathered) in 0.0044982 sec., 44462.22933617892 rows/sec., 8.93 MiB/sec.
2021.01.25 11:03:42.360623 [ 90 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_merge_202101_1_21_4 to 202101_1_21_4.
2021.01.25 11:03:42.360962 [ 90 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e) (MergerMutator): Merged 6 parts: from 202101_1_16_3 to 202101_21_21_0
2021.01.25 11:03:42.361208 [ 90 ] {} <Debug> MemoryTracker: Peak memory usage: 4.07 MiB.
2021.01.25 11:03:42.549183 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:42.553794 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:42.556630 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_21_21_0 to 202101_21_21_0.
2021.01.25 11:03:42.557299 [ 62 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Selected 6 parts from 202101_1_16_3 to 202101_21_21_0
2021.01.25 11:03:42.557713 [ 62 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:42.557723 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:42.558224 [ 93 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merging 6 parts: from 202101_1_16_3 to 202101_21_21_0 into Compact
2021.01.25 11:03:42.558901 [ 93 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.01.25 11:03:42.560355 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_1_16_3, total 121 rows starting from the beginning of the part
2021.01.25 11:03:42.562243 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_17_17_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.564121 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_18_18_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.566145 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_19_19_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.568410 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_20_20_0, total 8 rows starting from the beginning of the part
2021.01.25 11:03:42.570677 [ 93 ] {} <Trace> MergeTreeSequentialSource: Reading 2 marks from part 202101_21_21_0, total 7 rows starting from the beginning of the part
2021.01.25 11:03:42.594685 [ 93 ] {} <Debug> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merge sorted 158 rows, containing 255 columns (255 merged, 0 gathered) in 0.0364605 sec., 4333.456754570014 rows/sec., 8.39 MiB/sec.
2021.01.25 11:03:42.596887 [ 93 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_merge_202101_1_21_4 to 202101_1_21_4.
2021.01.25 11:03:42.597472 [ 93 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36) (MergerMutator): Merged 6 parts: from 202101_1_16_3 to 202101_21_21_0
2021.01.25 11:03:42.597781 [ 93 ] {} <Debug> MemoryTracker: Peak memory usage: 4.10 MiB.
2021.01.25 11:03:49.854578 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:49.855414 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:49.856562 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_22_22_0 to 202101_22_22_0.
2021.01.25 11:03:49.857140 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:49.897680 [ 63 ] {} <Debug> DNSResolver: Updating DNS cache
2021.01.25 11:03:49.899214 [ 63 ] {} <Debug> DNSResolver: Updated DNS cache
2021.01.25 11:03:50.058635 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:50.063556 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:50.066247 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_22_22_0 to 202101_22_22_0.
2021.01.25 11:03:50.067036 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
2021.01.25 11:03:57.357658 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush
2021.01.25 11:03:57.358517 [ 54 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:57.359596 [ 54 ] {} <Trace> system.trace_log (0d67c315-b4ab-42ad-859b-10875c95844e): Renaming temporary part tmp_insert_202101_23_23_0 to 202101_23_23_0.
2021.01.25 11:03:57.360176 [ 54 ] {} <Trace> SystemLog (system.trace_log): Flushed system log
2021.01.25 11:03:57.567779 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush
2021.01.25 11:03:57.573044 [ 55 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 235.09 GiB.
2021.01.25 11:03:57.576526 [ 55 ] {} <Trace> system.metric_log (6d8e518e-0872-49bd-871c-4249ef21ea36): Renaming temporary part tmp_insert_202101_23_23_0 to 202101_23_23_0.
2021.01.25 11:03:57.577626 [ 55 ] {} <Trace> SystemLog (system.metric_log): Flushed system log
Raw
distributed_ddl_timeout.xml
<yandex>
<profiles>
<default>
<distributed_ddl_task_timeout>20</distributed_ddl_task_timeout>
</default>
</profiles>
</yandex>
Raw
docker-compose.yaml
version: "3"
services:
zookeeper:
image: zookeeper:${ZOOKEEPER_VERSION:-latest}
clickhouse-0-0-0:
image: yandex/clickhouse-server:${CLICKHOUSE_VERSION:-latest}
volumes:
- ./atomic_delay_before_drop.xml:/etc/clickhouse-server/config.d/atomic_delay_before_drop.xml
- ./distributed_ddl_timeout.xml:/etc/clickhouse-server/users.d/distributed_ddl_timeout.xml
- ./atomic_drop_detach_sync.xml:/etc/clickhouse-server/users.d/atomic_drop_detach_sync.xml
- ./remote_servers.xml:/etc/clickhouse-server/config.d/remote_servers.xml
- ./zookeeper.xml:/etc/clickhouse-server/config.d/zookeeper.xml
- ./macros-0-0.xml:/etc/clickhouse-server/config.d/macros.xml
- ./clickhouse-0-0.log:/var/log/clickhouse-server/clickhouse-server.log
- ./clickhouse-0-0.err.log:/var/log/clickhouse-server/clickhouse-server.err.log
networks:
default:
aliases:
- clickhouse-0-0
clickhouse-0-1-0:
image: yandex/clickhouse-server:${CLICKHOUSE_VERSION:-latest}
volumes:
- ./atomic_delay_before_drop.xml:/etc/clickhouse-server/config.d/atomic_delay_before_drop.xml
- ./distributed_ddl_timeout.xml:/etc/clickhouse-server/users.d/distributed_ddl_timeout.xml
- ./remote_servers.xml:/etc/clickhouse-server/config.d/remote_servers.xml
- ./atomic_drop_detach_sync.xml:/etc/clickhouse-server/users.d/atomic_drop_detach_sync.xml
- ./zookeeper.xml:/etc/clickhouse-server/config.d/zookeeper.xml
- ./macros-0-1.xml:/etc/clickhouse-server/config.d/macros.xml
- ./clickhouse-0-1.log:/var/log/clickhouse-server/clickhouse-server.log
- ./clickhouse-0-1.err.log:/var/log/clickhouse-server/clickhouse-server.err.log
networks:
default:
aliases:
- clickhouse-0-1
networks:
default:
Raw
macros-0-0.xml
<yandex>
<macros>
<shard>0</shard>
<replica>clickhouse-0-0</replica>
</macros>
</yandex>
Raw
macros-0-1.xml
<yandex>
<macros>
<shard>0</shard>
<replica>clickhouse-0-1</replica>
</macros>
</yandex>
Raw
remote_servers.xml
<yandex>
<remote_servers>
<default>
<shard>
<internal_replication>true</internal_replication>
<replica>
<host>clickhouse-0-0-0</host>
<port>9000</port>
</replica>
<replica>
<host>clickhouse-0-1-0</host>
<port>9000</port>
</replica>
</shard>
</default>
</remote_servers>
</yandex>
Raw
reproduce.sh
#!/usr/bin/env bash
set -xue
set -o pipefail
rm -rf *.log
touch clickhouse-0-0.log clickhouse-0-0.err.log clickhouse-0-1.log clickhouse-0-1.err.log
for CLICKHOUSE_VERSION in latest 21.2 21.1 20.12 20.11 20.10; do
export CLICKHOUSE_VERSION=${CLICKHOUSE_VERSION}
docker-compose down
docker-compose up -d zookeeper
sleep 5
docker-compose up -d clickhouse-0-0-0 clickhouse-0-1-0
sleep 5
docker-compose exec clickhouse-0-0-0 clickhouse-client -q "CREATE TABLE default.test_repl ON CLUSTER 'default' (n UInt64) ENGINE ReplicatedMergeTree('/clickhouse/tables/{shard}/test_repl','{replica}') ORDER BY tuple()"
sleep 5
docker-compose exec clickhouse-0-1-0 clickhouse-client -q "SELECT count() FROM default.test_repl"
docker-compose exec clickhouse-0-1-0 clickhouse-client -q "DROP TABLE default.test_repl ON CLUSTER 'default' NO DELAY" || true
# table really deleted but completion doesn't return to ZK DDL queue
docker-compose exec clickhouse-0-0-0 clickhouse-client -q "SELECT count() FROM default.test_repl"
done
Raw
zookeeper.xml
<yandex>
<zookeeper>
<node><host>zookeeper</host><post>2181</post></node>
</zookeeper>
</yandex>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment