Server spins at 100% CPU in get_buffer() after disk full and doesn't recover when space is freed #9269

Firebird 5.0.4.1812 x64 (also 5.0.3.1683), official zip kits, SuperServer started with firebird -a. Only RemoteServicePort, RemoteBindAddress and IpcName changed in firebird.conf, no plugins. Windows 11 Pro 64-bit, NTFS.

When the volume holding the database runs full while a few connections are inserting, the server sometimes doesn't come back. The inserting statements never return and one or more threads sit at 100% CPU in get_buffer(). Freeing disk space doesn't change anything, even though the comment in write_page() says these errors should go away by themselves once someone frees space. Only a restart helps. After the restart the database validates clean and the committed data is there.

How to reproduce

The attached script (Repro-FbDiskFullHang.ps1, needs an elevated PowerShell because of diskpart) does this in a loop:

1. creates a 1 GB VHDX with diskpart, formats it NTFS and mounts it on a folder
2. creates a database on it with page_size 32768 and

create table t (id integer not null primary key, grp integer, s varchar(400));
create index t_s on t (s);

optionally with 300000 rows inserted first (-BaseRows 300000)
3. fills the volume with a file so only 20 MB is left
4. starts 4 isql sessions, each running this about 200 times with different ids. No SET BAIL, so isql keeps going after errors:

set term ^ ;
execute block as declare i integer = 0; begin
  while (i < 1000) do begin
    insert into t values (<unique id>, 1, lpad('', 400, uuid_to_char(gen_uuid())));
    i = i + 1;
  end
end^
set term ; ^
commit;

All 4 sessions get I/O error during "WriteFile" operation ... There is not enough space on the disk. Normally they finish right after that. Sometimes they don't.

What I got with 10 rounds per run:

5.0.4.1812  empty table     1 hang
5.0.4.1812  300000 rows     3 hangs
5.0.3.1683  empty table     1 hang
5.0.3.1683  300000 rows     4 hangs

With the pre-filled table usually all 4 writer threads spin (about 400% CPU). I first ran into this with a different schema on 5.0.3, where it hung 13 times in 30 rounds. In one 5.0.4 round the statements also got stuck for 3 minutes but with the engine idle. I didn't look into that one.

After deleting the filler file nothing changes: same CPU, statements still stuck, database file doesn't grow. I left one 5.0.4 hang running for 45 minutes after freeing the space. It stayed at about 400% CPU the whole time with all 4 statements stuck and the file size unchanged to the byte, then I killed it. Connecting to another database on the same server works. Connecting to the hung database and selecting from rdb$database only worked in 3 of 10 hangs, the other 7 times it didn't return within 30 s.

I couldn't run the 5.0.5.1950 snapshot here (our endpoint protection blocks the unsigned exes), but its cch.cpp only differs from 5.0.4 by the CDS_UNAVAILABLE ifdef, and get_buffer() in master only differs in the stats calls.

Where it spins

No debugger on that machine, so this is from sampling the hot thread's RIP and scanning its stack for return addresses, resolved with engine13.pdb from the kits. The outer frames may not be exact. There are two different loops in get_buffer(), both seen on 5.0.3 and 5.0.4.

a) cch.cpp 3840-3898, most of the hangs. find(page) finds nothing, the empty list is empty, get_oldest_buffer() returns nullptr, Thread::yield(), and around again. In the 45 minute one most samples are inside get_oldest_buffer() at 3702-3722: the candidates are dirty, so it sets BCB_free_pending, pokes the cache writer and moves on. The cache writer never writes them, which would fit DBB_suspend_bgio still being set (see below).

SyncObject::lock / unlock      SyncObject.cpp:51 / 232
MichaelList ...                michael_list.h:1173 / 1187
get_buffer                     cch.cpp:3847
get_oldest_buffer              cch.cpp:3668 / 3775
CCH_fetch_lock                 cch.cpp:872
CCH_fetch_page                 cch.cpp:1068
BTR_insert                     btr.cpp:1446
add_node                       btr.cpp:2708

b) cch.cpp 3914-3963. emplace(bdb, page, ...) returns bdb2, addRef() succeeds, but bdb2->bdb_page != page, so it releases it and continues, and emplace() hands back the same bdb2 again. So the hash has an entry for page P pointing to a BufferDesc that holds another page.

MichaelList::update_at         michael_list.h:994-1024
get_buffer                     cch.cpp:3922 / 3957 / 3961
CCH_fetch_lock                 cch.cpp:872
CCH_fetch                      cch.cpp:802
add_node / BTR_evaluate        btr.cpp

Two things I noticed in cch.cpp while looking at this, not sure if they are related. After the write error write_page() sets DBB_suspend_bgio, which parks the cache writer, and it's only cleared when a later write of a BDB_io_error buffer succeeds or in CCH_forget_page(). And CCH_forget_page() (the out of disk space path) removes the buffer from the CDS hash with list.erase(bdb->bdb_page), so by key only, without checking that the entry still points to that bdb.

With -BaseRows 300000 the script usually hits it within 10 rounds, about 5 minutes per hang. It can also write a memory dump of firebird.exe at the first hang (-DumpOnHang) if that's useful.

Repro-FbDiskFullHang.zip