There was a race condition when issuing a DDL query on a replica just
after a new replica was added.
If the DDL query is issued after the new replica adds itself to the
list of replicas, but before the new replica has finished its
recovery, then the first replica adds the new replica to the list of
replicas to wait to confirm the query was replicated.
Meanwhile, the new replica is still in recovery and applies queries
from the /metadata snapshot. When it's done, it bumps its log_ptr
without marking the corresponding log entries (if any) as finished.
The first replica then waits until distributed_ddl_task_timeout
expires and wrongly assumes the query was not replicated.
The issue is fixed by remembering the max_log_ptr at the exact point
where the replica adds itself to the list of replicas, then mark as
finished all queries that happened between that max_log_ptr and the
max_log_ptr of the metadata snapshot used in recovery.
The bug was randomly observed during a downstream test. It can be
reproduced more easily by inserting a sleep of a few seconds at the
end of createReplicaNodesInZooKeeper, enough to have time to issue a
DDL query on the first replica.
This runs the `utils/generate-ya-make/generate-ya-make.sh` script to
update the ya.make files that are not updated.
I wonder why they were not updated and how it was missed.
It is possible to trigger
MaterializedMySQLSyncThread::stopSynchronization() from the same thread
in case of some exception at startup, when some interpreter holds the
storage refcnt, and later MaterializedMySQLSyncThread will try to join
itself from the main thread.
Here is a stack trace for example:
<details>
4 0x000000000f7ae45c in Poco::Event::wait (this=0x7f1b90c38170) at ../contrib/poco/Foundation/include/Poco/Event.h:97
5 ThreadFromGlobalPool::join (this=0x7f1b90c23120) at ../src/Common/ThreadPool.h:210
6 DB::MaterializeMySQLSyncThread::stopSynchronization (this=0x7f1b8024ca68) at ../src/Databases/MySQL/MaterializeMySQLSyncThread.cpp:229
7 DB::MaterializeMySQLSyncThread::~MaterializeMySQLSyncThread (this=0x7f1b8024ca68) at ../src/Databases/MySQL/MaterializeMySQLSyncThread.cpp:85
8 0x000000000f816dc8 in DB::DatabaseMaterializeMySQL<DB::DatabaseAtomic>::~DatabaseMaterializeMySQL (this=0x7f1b8024c918) at ../src/Databases/MySQL/DatabaseMaterializeMySQL.h:21
11 std::__1::shared_ptr<DB::IDatabase>::~shared_ptr (this=<optimized out>) at ../contrib/libcxx/include/memory:3212
12 0x000000000f8726a6 in DB::InterpreterCreateQuery::createTable (this=<optimized out>, create=...) at ../src/Interpreters/InterpreterCreateQuery.cpp:952
13 0x000000000f87735c in DB::InterpreterCreateQuery::execute (this=0x7f1aeef59860) at ../src/Interpreters/InterpreterCreateQuery.cpp:1225
14 0x000000000fe22253 in DB::executeQueryImpl (begin=<optimized out>, end=<optimized out>, context=..., internal=true, stage=DB::QueryProcessingStage::Complete, has_query_tail=<optimized out>, istr=<optimized out>) at ../src/Interpreters/executeQuery.cpp:574
15 0x000000000fe208e3 in DB::executeQuery (query=..., context=..., internal=<optimized out>, stage=DB::QueryProcessingStage::FetchColumns, may_have_embedded_data=<optimized out>) at ../src/Interpreters/executeQuery.cpp:933
16 0x000000000faafcde in DB::MySQLInterpreter::InterpreterMySQLDDLQuery<DB::MySQLInterpreter::InterpreterCreateImpl>::execute (this=<optimized out>) at ../src/Interpreters/MySQL/InterpretersMySQLDDLQuery.h:75
17 0x000000000faade78 in DB::InterpreterExternalDDLQuery::execute (this=<optimized out>) at ../src/Interpreters/InterpreterExternalDDLQuery.cpp:64
18 0x000000000fe22253 in DB::executeQueryImpl (begin=<optimized out>, end=<optimized out>, context=..., internal=true, stage=DB::QueryProcessingStage::Complete, has_query_tail=<optimized out>, istr=<optimized out>) at ../src/Interpreters/executeQuery.cpp:574
19 0x000000000fe208e3 in DB::executeQuery (query=..., context=..., internal=<optimized out>, stage=DB::QueryProcessingStage::FetchColumns, may_have_embedded_data=<optimized out>) at ../src/Interpreters/executeQuery.cpp:933
20 0x000000000f7ba406 in DB::tryToExecuteQuery (query_to_execute=..., query_context=..., database=..., comment=...) at ../src/Databases/MySQL/MaterializeMySQLSyncThread.cpp:69
21 0x000000000f7d4b88 in DB::dumpDataForTables() (connection=..., query_prefix=..., database_name=..., mysql_database_name=..., context=..., is_cancelled=..., need_dumping_tables=...) at ../src/Databases/MySQL/MaterializeMySQLSyncThread.cpp:326
22 DB::MaterializeMySQLSyncThread::prepareSynchronized(DB::MaterializeMetadata&)::$_1::operator()() const (this=<optimized out>) at ../src/Databases/MySQL/MaterializeMySQLSyncThread.cpp:391
29 DB::commitMetadata() (function=..., persistent_tmp_path=..., persistent_path=...) at ../src/Databases/MySQL/MaterializeMetadata.cpp:197
30 0x000000000f80a000 in DB::MaterializeMetadata::transaction(DB::MySQLReplication::Position const&, std::__1::function<void ()> const&) (this=0x7f1b6375c3d8, position=..., fun=...) at ../src/Databases/MySQL/MaterializeMetadata.cpp:230
31 0x000000000f7b2231 in DB::MaterializeMySQLSyncThread::prepareSynchronized (this=0x7f1b8024ca68, metadata=...) at ../src/Databases/MySQL/MaterializeMySQLSyncThread.cpp:388
32 0x000000000f7b169c in DB::MaterializeMySQLSyncThread::synchronization (this=0x7f1b8024ca68) at ../src/Databases/MySQL/MaterializeMySQLSyncThread.cpp:180
33 0x000000000f7d4074 in DB::MaterializeMySQLSyncThread::startSynchronization()::$_0::operator()() const (this=<optimized out>) at ../src/Databases/MySQL/MaterializeMySQLSyncThread.cpp:236
</details>
This will allow to avoid superfluous sleep during query execution, since
this not only not desired behavoiur, but also may hang the server, since
if you will execute enough queries that will use MySQL database but will
not allow enough connections (or your MySQL server is too slow) then you
may run out of threads in the global thread pool.
Also note that right now it is possible to get deadlock when the mysql
pool is full, consider the following scenario:
- you have m1 and m2 mysql tables
- you have q1 and q2 queries, bot queries join m1 and m2
- q1 allocated connection for m1 but cannot allocate connection for m2
- q2 allocated connection for m2 but cannot allocate connection for m1
- but to resolve the lock one should give up on the locking while it is not possible right now...
And then you got no free threads and this:
# grep -h ^202 /proc/$(pgrep clickhouse-serv)/task/*/syscall | cut -d' ' -f2 | sort | uniq -c | sort -nr | head
1554 0x7ffb60b92fe8 # mutex in mysqlxx::PoolWithFailover::get
1375 0x7ffb9f1c4748 # mutex in ::PoolEntryHelper::~PoolEntryHelper from DB::MultiplexedConnections::invalidateReplica
1160 0x7ffb612918b8 # mutex in mysqlxx::PoolWithFailover::get
42 0x7ffb9f057984 # mutex in ThreadPoolImpl<std::__1::thread>::worker
*NOTE: 202 is a `futex` with WAIT*
(Went with `syscall` because debugging 10k+ threads is not easy, and
eventually it may TRAP)
