Client disconnect fails to abort a lock wait

Goal

When a client disconnects without saying goodbye (it crashed, was killed, the network failed, a firewall dropped the connection), a session that is processing a statement must be killed, and its resources released. Typical case: the statement waits for an InnoDB row lock, and its transaction keeps the locks that other sessions now wait for, for a client that no longer exists.

• The error log gets one specific line about it: Aborted connection N to db: ... (Client disconnected).
• When the client disconnects gracefully (COM_QUIT), that line must not be present.
• When the client is idle, waiting for a new command, nothing changes. The existing mechanisms already catch the error on the next read, and log it as Aborted connection ... (Got an error reading communication packets).

Why the existing mechanisms are not enough

The server learns that the peer is gone only when it reads from or writes to the socket. There are two proactive checks, in the idle wait for the next command, and in some waits (a lock wait polls periodically). Neither covers the general case. A statement that does not talk to the client for a long time (a heavy join, a sort, a SLEEP, a wait on a table lock or a metadata lock that does not poll the connection) never notices. Polling the socket from every such place is not an option, there are too many of them, and it costs a system call each.

Approach

Ask the OS to tell us. Every client socket is registered with a single watcher thread, which uses the reactive notification the platform has, and registers only for events that need no read of the socket (no data is consumed or reported). When a socket reports that the peer is gone, the watcher does what KILL does: find the THD by thread id, and set a kill state that wakes the thread up and makes it end. No new locking rule: the watcher takes the locks KILL takes, and never touches the socket.

The kill state

A new KILL_DISCONNECT (12; KILL_CONNECTION and the states above it move up by two).

• Statement-level like KILL QUERY, so the running statement is aborted the usual way, by every wait that already checks killed.
• But it is not reset when a statement starts. The event can arrive while the connection is idle, or between statements. The state is then kept, and aborts the next statement, instead of letting a statement run for a client that is gone.
• When it aborted a statement, the connection ends after the error is sent. The error is still sent: a client that only half-closed its side reads it, and responses stay in step. Commands that the client pipelined behind the aborted statement must not run, so the connection ends.
• The reason is logged once. It is logged where the statement ends: in net_send_error_packet(), and also at the end of dispatch_command(), for a statement whose error was handled by someone (a stored procedure handler, the SQL service of a plugin) and ended with an OK.

COM_QUIT, FIN, and why a crash looks the same

A client that quits normally sends COM_QUIT, and then closes the socket. The FIN usually arrives together with COM_QUIT, or before the server has read it. The socket therefore reports "peer closed" while the command that explains why is still unread. A client that crashed, or was killed, produces the same FIN (or a reset, which is the same for our purposes). From the socket alone, the two are not distinguishable, and they must not be: the log line must appear for the crash and not for the quit.

Two things make it right:

1. COM_QUIT removes the connection from the watch before it is handled, and a kill state of KILL_DISCONNECT that arrives for a connection that is quitting is ignored.
2. The watcher waits for 5 ms after each batch of events (the sleep is interrupted when the watcher is told to stop, except on Windows, where it is a Sleep() and takes a timer tick, about 15 ms). A normal disconnect then gives the connection thread the time to read COM_QUIT and remove the socket from the set, and the pending event goes away with it. The watcher does not look up the THD, under the lock of the thread list, for every connection that quits.

A client that closes the socket and never sends COM_QUIT is, by definition, not a graceful disconnect, and is reported.

The delay is measured, it is not a guess. Connect, SELECT 1, disconnect over a unix socket with 32 clients was 37% slower with the watcher without the delay, and 3% slower with it (8 clients: 7%, below 1%). On Windows with 64 to 512 clients over TCP the lookups were 22% of the disconnects without the delay and are below 1% with it, and the throughput is within the noise.

The variable

disconnect_watcher, a global, boolean, ON by default. Setting it OFF switches the watcher off for the connections made afterwards. It exists only on the platforms that have a watcher. If the watcher cannot start (the OS call fails), the variable is OFF, with a warning in the log, and cannot be set ON. The embedded server has no watcher. The variable is a safety valve: a site that finds the behavior unwelcome can go back to the old one without a new binary.

Platforms

• Linux: one epoll set, with the watcher thread waiting for it. Aborting a statement takes locks and may wait for the victim, which must not delay accepting connections, hence a thread of its own. EPOLLRDHUP is requested (a close by the peer, which is also how a crashed client looks, may be only a FIN), EPOLLERR and EPOLLHUP are always reported. The sockets are oneshot. The thread is stopped through a pipe that is in the set.
• BSD and macOS: kqueue, same thread. On the BSDs an EVFILT_READ filter with EV_CLEAR, and the low water mark set out of reach, so that only EV_EOF and socket errors report, and incoming data does not. macOS clamps the low water mark to the receive buffer, so a command that fills the buffer would fire the filter. It has a socket filter, EVFILT_SOCK with NOTE_CONNRESET and NOTE_READCLOSED, that reports a reset and a shutdown of the read side, never data. It is private to XNU (libdispatch uses it too).
• Windows sockets: an I/O completion port, notified by an event. WSAEventSelect(FD_CLOSE) sets an event when the peer closes or resets the connection, and a wait completion packet (NtCreateWaitCompletionPacket, NtAssociateWaitCompletionPacket, NtCancelWaitCompletionPacket) makes the kernel post a completion to the port when that event is signaled. The watcher thread takes the completions in batches, with one GetQueuedCompletionStatusEx. The packets are sparsely documented, they are in ntdll and not in the SDK, so they are loaded with GetProcAddress, but they are used in large projects (the Go runtime, for example). The completion key is the connection id by value, so a completion that is handled after the connection is gone finds nothing.
• Windows named pipes have no such notification: there is no "peer closed" event on a pipe handle that can be waited for without reading. A local pipe client is a process, and a process handle can be waited for. So the watcher waits for the exit of the client process (the pid comes from GetNamedPipeClientProcessId). Connections of one process share a refcounted process handle, a process is opened once. If the server may not open it (a client of another user), the client is impersonated for that, which needs SeImpersonatePrivilege; a service has it, enabled. Otherwise a warning is logged once and such connections are not watched. Remote pipe clients are not watched, the pid is not valid on this machine. A client that only closes the pipe, and does not exit, is not noticed. That is the price of there being no event.

Interactions

• Galera (wsrep): connections are not aborted. A thread in the commit phase must not be killed by a bare kill flag, the provider has its own rules for aborting a transaction.
• Replication dump threads are watched like any other connection.
• Stale events: the watcher finds the THD by id, under LOCK_thd_kill, like KILL. A connection that is gone is not found, and an id is reused only after 2^32 connections (in the worst case 2^32 / the number of connections).
• Shutdown: events are ignored once the server aborts, the resources are released after the connections have ended.
• Threads that are reused (the thread cache): a new connection starts without the state of the previous one. Covered by a test.
• thd_net_is_killed(): a plain KILL_DISCONNECT is not a kill for the network layer, so the read error is reported as usual and not as "Connection was killed".
• mysqltest: dirty_close takes an optional linger (the default, FIN) or nolinger (SO_LINGER 0, the server gets a reset) argument.

Tests

main.disconnect_lock_wait (FIN, linger and reset; OFF), disconnect_lock_owner (the transaction is rolled back, its locks are released), disconnect_wait_kinds (a CPU-bound statement and a table level lock wait, which do not poll the connection themselves), disconnect_lock_wait_idle, disconnect_lock_wait_pipe (Windows), disconnect_thread_reuse, plugins.test_sql_service_disconnect, sys_vars.disconnect_watcher_basic, and mysql_client_test test_disconnect_pipelined (two commands in one write and a half-close while the first waits for a lock: the connection ends, the second is not run).

Existing tests that raced with the old behavior are adjusted to pass with the watcher ON and OFF.

Known limitations, not done

• BSD and macOS: written against the kernel sources, not run.
• Galera exemption: not tested.
• A Windows named pipe client that closes the pipe without exiting.
• Deferred tests: pipelined requests on a pipe, two pipes of one process, switching the variable at runtime, the race with KILL.

Original bug report by Marko

I noticed that test innodb.xa_recovery is consuming innodb_lock_wait_timeout=50 seconds extra time starting with the 10.11 branch.

I narrowed down the reason to the only send statement in the test. The test waits the execution of that statement to be blocked. Subsequently, it expects a DROP TABLE t2 to fail with ER_LOCK_WAIT_TIMEOUT:

43

SET innodb_lock_wait_timeout=1;

44

--error ER_LOCK_WAIT_TIMEOUT

45

DROP TABLE t2;

46

47

disconnect con1;

48

49

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;

50

--disable_ps2_protocol

51

SELECT * FROM t1;

52

--enable_ps2_protocol

53

XA ROLLBACK 'x';

I debugged this as follows:

mysql-test/mtr --rr innodb.xa_recovery

rr replay mysql-test/var/log/mysqld.1.rr/mariadbd-1

I set a breakpoint to the only my_cond_timedwait() call in lock0lock.cc, as well as on innobase_close_connection and innobase_kill_query. It turns out that these functions were not called in response to the disconnect con1. The lock wait would keep blocked until it times out or is coincidentally interrupted by something else. In 10.6, the test completes faster because the above XA ROLLBACK 'x' happens to abort the wait:

#0  ___pthread_cond_signal (cond=0x7fe481201210) at ./nptl/pthread_cond_signal.c:36

#1  0x000055ab95428465 in lock_wait_end<false> (trx=<optimized out>) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:2292

#2  lock_grant (lock=lock@entry=0x7fe481201280) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:2315

#3  0x000055ab9542dee8 in lock_rec_dequeue_from_page (in_lock=<optimized out>, owns_wait_mutex=0x1) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:2407

#4  0x000055ab94e70875 in lock_release_try (trx=trx@entry=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4355

#5  0x000055ab9542ecbb in lock_release (trx=trx@entry=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4402

#6  0x000055ab94e74088 in trx_t::release_locks (this=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:485

#7  trx_t::commit_in_memory (this=0x7fe4811ffb80, mtr=0x7fe4804816b0) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1431

#8  trx_t::commit_low (this=this@entry=0x7fe4811ffb80, mtr=0x7fe4804816b0) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1573

#9  0x000055ab954c5972 in trx_t::commit_persist (this=this@entry=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1587

#10 0x000055ab954c59b8 in trx_t::commit (this=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1596

#11 0x000055ab954bf8bd in trx_t::rollback_finish (this=0x7fe4811ffb80) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:64

#12 0x000055ab954c0228 in trx_t::rollback_low (this=0x7fe4811ffb80, savept=savept@entry=0x0) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:125

#13 0x000055ab954c043a in trx_rollback_for_mysql (trx=<optimized out>) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:249

#14 0x000055ab953e069c in innobase_rollback_by_xid (xid=<optimized out>) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:3015

#15 0x000055ab95178510 in xarollback_handlerton (unused1=<optimized out>, plugin=<optimized out>, arg=0x7fe480481c40) at /mariadb/10.6/sql/handler.cc:2432

#16 0x000055ab94f57f37 in plugin_foreach_with_mask (thd=thd@entry=0x0, func=0x55ab951784f0 <xarollback_handlerton(THD*, plugin_ref, void*)>, type=type@entry=0x1, state_mask=state_mask@entry=0x8, 

    arg=arg@entry=0x7fe480481c40) at /mariadb/10.6/sql/sql_plugin.cc:2559

#17 0x000055ab9517d9a9 in ha_commit_or_rollback_by_xid (xid=<optimized out>, commit=commit@entry=0x0) at /mariadb/10.6/sql/handler.cc:2454

#18 0x000055ab951089b1 in trans_xa_rollback (thd=thd@entry=0x7fe45c000cd8) at /mariadb/10.6/sql/xa.cc:843

#19 0x000055ab94f4d9fc in mysql_execute_command (thd=thd@entry=0x7fe45c000cd8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=0x0) at /mariadb/10.6/sql/sql_parse.cc:6045

#20 0x000055ab94f50209 in mysql_parse (thd=0x7fe45c000cd8, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /mariadb/10.6/sql/sql_parse.cc:8201

#21 0x000055ab94f51da8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fe45c000cd8, packet=packet@entry=0x7fe45c016c09 "XA ROLLBACK 'x'", packet_length=packet_length@entry=0xf, 

    blocking=blocking@entry=0x1) at /mariadb/10.6/sql/sql_parse.cc:1911

In 10.11 or later the thread that is associated with the disconnected client will remain blocked for innodb_lock_wait_timeout seconds, adding to the test execution time. I will file a separate bug for the changed behaviour of the XA ROLLBACK 'x' between 10.6 and 10.11, once I have diagnosed it.