FirebirdSQL
Firebird 4 disk IO regression on Windows
Testing ETL I noticed that a simple
select count(*) from <tbl>
can take much longer with Firebird 4 in comparison to the same operation with Firebird 259. "Much longer" meaning a factor! of 2 to 7. It only occurs when the engine needs to read from disk and fill the FS-cache. This seems to be a Windows only issue. I have run dozens of tests during recent months and can provide a test case to reproduce the behaviour. The Windows OS does not matter, I could reproduce the effect on Win10, Win11, WinServer 2019, WinServer 2016 Datacenter and so on. It also doesn't seem to matter if a system is virtualized or not, although that's hard to tell and depends on the configuration of the VM. It does not matter if one of the Firebirds is 32-Bit and the other 64-Bit. The type of disk might play a role, although most of the machines (around 20) I have tested with used SSDs / NVMes. CPU does not seem to matter, I have tested mainly on XEON CPUs, some faster Intel desktop CPUs and some Ryzen CPUs, desktop and server ones. RAM varied from 8 to 32 GB, but the effect can be observed regardless of RAM size, since the test case takes that into account - it has to, see below.
Unfortunately, the effect does not occur on every system. There were machines, perhaps one out of three, where Firebird 4 and 2.5.9 had the same (+/-10%) good performance when they started reading with a cold cache. Cold cache is important here.
The test case, 1-3 is optional, just to make sure it is not the configuration:
- fresh manual install of Firebird 2.5.9 and Firebird 4
- no changes to the firebird.conf files except for a different port 3054 for Firebird 4
- register the Firebirds as services using instvc
- create a new directory "temp" on drive D (or C, adapt scripts in that case)
- copy the attached sql scripts to temp
- adjust counttest-scripts if the test machine has more than 8 GB RAM
- run the counttest_n-scripts with isql, each with its Firebird, to create the test databases
- run the countquery_n-scripts with isql, each with its Firebird, to query the databases. Strictly alternating, otherwise you won't see the effect!
The counttest-scripts create databases consisting of two tables, "bigone", with 15 M recs, and "test" with 1 M recs. The resulting database is about 3.5 GB in size. This is the configuration for a system with 8 GB RAM. If you are testing on a machine with 16 GB RAM, you need to adjust the number of generated recs in table bigone to 30 M recs. Or 22 M recs if you got 12 GB RAM. Table test always stays the same, with 1 M.
The test assumes that the Firebirds both use the FS-cache default of 30% of RAM as described in firebird.conf.
The countquery-scripts each first query table bigone by
select count(*) from bigone
Then they each query table test twice, by
select count(*) from test
query procedure:
- stop both Firebird services
- start Firebird 4 service
- run isql -q -i d:\temp\countquery4.sql
- watch windows taskmanager and write down disk rate (MB/sec) and cpu rate (%)
- evaluate query stats returned by isql
- stop Firebird 4 service
- start Firebird 25 service
- run isql -q -i d:\temp\countquery25.sql
- watch windows taskmanager and write down disk rate (MB/sec) and cpu rate (%)
- evaluate query stats returned by isql
- stop Firebird 25 service
- repeat from step 2
Running that query test on an average laptop, I got, timing in seconds,
FB4 CPU 19% disk read 200 MB/sec, disk load 29% bigone 14,67 (15 M) test 0.6 / 0,5
FB25 CPU 24% disk 480 MB/sec, disk load 36% bigone 6,64 (15M) test 0,45 / 0,47
read rate 200 MB/sec vs 480 MB/sec, both constantly, on a SSD drive. Firebird 4 takes more than twice as long for bigone.
Then, surprise, on the other drive, a HDD:
FB4 CPU 11% disk 90 MB/sec, disk load 61% bigone 37,6 (15 M) test 2,6 / 0,6
FB25 CPU 7-8% disk 93-99 MB/sek, disk load 95% bigone 33,19 (15M) test 2,7 / 0,49
Not much difference, something like this (5-10%) would be no big deal, since Firebird 4 performs better than 259 in many other areas.
the test machine of the run above:
Win11 Pro CPU i5-8265U 8 GB RAM C (SSD) Samsung SSD 970 Evo 250 GB D (HDD) WDC WD10SPZX-08Z10 1TB
but as I wrote, the effect occurs on a wide variety of machines. Not on every one, that's the catch.
Volker
can't attach the scripts even as .txt, so here they are, inline. Observe empty last line for isql:
--- counttest4.sql ---
create database 'D:\temp\counttest4.fdb' page_size 16384 user 'sysdba' password 'masterke' default character set ISO8859_1;
create table bigone ( F1 VARCHAR (1000), F2 VARCHAR (1000), F3 VARCHAR (1000), F4 VARCHAR (1000), F5 VARCHAR (1000), F6 VARCHAR (1000), F7 VARCHAR (1000), F8 VARCHAR (1000) );
commit;
create table test ( F1 VARCHAR (1000), F2 VARCHAR (1000), F3 VARCHAR (1000), F4 VARCHAR (1000), F5 VARCHAR (1000), F6 VARCHAR (1000), F7 VARCHAR (1000), F8 VARCHAR (1000) );
commit;
set term #; execute block as declare i int = 0; declare n int = 15000000; begin while (i < n) do begin insert into bigone values ('XXXX', 'XXXX', 'XXXX', 'XXXX', 'XXXX', 'XXXX', 'XXXX', 'XXXX'); i = i + 1; end end# set term ;#
commit;
set term #; execute block as declare i int = 0; declare n int = 1000000; begin while (i < n) do begin insert into test values ('XXXX', 'XXXX', 'XXXX', 'XXXX', 'XXXX', 'XXXX', 'XXXX', 'XXXX'); i = i + 1; end end# set term ;#
commit;
--- counttest25.sql ---
just copy counttest4.sql and rename the copy to counttest25.sql, then in there change the name of the database to counttest25.fdb
--- countquery4.sql ---
connect 'D:\temp\counttest4.fdb' user 'sysdba' password 'masterke';
set stats on;
select count(*) total from bigone; commit;
select count(*) total1 from test; commit;
select count(*) total2 from test;
commit;
--- countquery25.sql ---
connect 'D:\temp\counttest25.fdb' user 'sysdba' password 'masterke';
set stats on;
select count(*) total from bigone; commit;
select count(*) total1 from test; commit;
select count(*) total2 from test;
commit;
Thanks for the report.
I currently investigating it and below what I was found so far:
- I can't reproduce it on my primary working Win7 machine
- I reproduced it on my Win10 notebook
- it is definitely related with overlapped IO used by Firebird since v4, and with Windows file system prefetching. By not clear to me reasons Win10 not uses prefetching when file is opened with FILE_FLAG_OVERLAPPED.
Looking for more info about behaviour changes and what can be done.
Can it be due to encryption?
https://docs.microsoft.com/en-us/troubleshoot/windows/win32/asynchronous-disk-io-synchronous
NTFS encryption
Similar to compression, file encryption causes the system driver to convert asynchronous I/O to synchronous. If the files are decrypted, the I/O requests will be asynchronous.
It is due to FILE_FLAG_OVERLAPPED - without it fb4 works almost as fast as fb25. And - no - I don't use NTFS encryption.
Vlad, glad you can confirm this.
set statistics is also affected by this IO behaviour, according to our tests. Reading Adrianos Link, it looks like to use cache and async IO is counterproductive here, since there might not be enough workers - or they stand on each other's toes.
set statistics is also affected by this IO behaviour, according to our tests
Could you clarify - what do you mean here ?
Reading Adrianos Link, it looks like to use cache and async IO is counterproductive here, since there might not be enough workers - or they stand on each other's toes.
I can proof with trace by ProcMon that Win10 doesn't readahead when file is opend in async mode. Win7 does. I still can't find anything about this change of behaviour. I've tried to VirtualLock memory of page cashe - no changes. I've counted numbers of TRUE\FALSE returns by ReadFile to see if IO was sync\async - it is 100% async. So, that article about different things and not applicable here. BTW, I see no correlation with file size - even with small DB of 428MB there is no readahead.
I can disable async IO in fb4 when file caching is used but this will make it slower in many more cases.
PS I have separate branch with prefetching implemented by Firebird itself, would you like to test it ?
set statistics takes longer, best noticable with big tables, and the factor seems to correspond with the test case measurement for a particular machine. It seems both operations have the same root cause - reading from disk and/or filling the FS cache is slowed down a lot.
Re file size - there is no correlation. It is just more noticeable with the big files. Please compare the numbers of table "test" in my test case. If the machine is fast enough, you would not notice that the operation is slower than with FB25.
disable async IO? not sure about this. We tested FB4 with larger ETL runs and performance was better throughout compared to FB25. Only when larger amounts of data had to be requested from disk, disk read rate was much slower than with FB25. Cant we have both? ;) But actually I don't know if FB4 performs better because of async IO. A switch in firebird.conf would quickly tell us.
You implemented prefetching yourself in a separate branch? My pleasure to test that one Volker
set statistics takes longer, best noticable with big tables, and the factor seems to correspond with the test case measurement for a particular machine. It seems both operations have the same root cause - reading from disk and/or filling the FS cache is slowed down a lot.
Now I get it - SET STATS sql statement :) Sure, it is executed similar to SELECT COUNT(*) query.
disable async IO? not sure about this. We tested FB4 with larger ETL runs and performance was better throughout compared to FB25. Only when larger amounts of data had to be requested from disk, disk read rate was much slower than with FB25. Cant we have both? ;)
Afraid, no - at least not at the same time :)
A switch in firebird.conf would quickly tell us.
It is possible for evaluation purposes, not sure it should be at permanent basis.
You implemented prefetching yourself in a separate branch? My pleasure to test that one
Yes. Contact me privately and I'll prepare a build and instructions for you.