18 hours for updating 172M records?

[gsbelarus]

1. The server is Firebird 5.0.3, running in the classic mode.
2. The machine has 128 GB RAM, 16 cores and SSD drive.
3. The database is in FORCED WRITES = OFF state.
4. The table has no indexes, no FKs, no triggers. Just sole PK.
5. There are three BIGINT fields being updated as such:

update gd_document
set aview64=-1, achag64=627345276345,afull64=0

The performance is just depressing. 18 hours....

PLAN (GD_DOCUMENT NATURAL)

172274304 record(s) was(were) updated in GD_DOCUMENT

------ Performance info ------
Prepare time = 3s 500ms
Execute time = 18h 16m 52s 875ms
Current memory = 50 824 608
Max memory = 138 111 456
Memory buffers = 2 000
Reads from disk to cache = 4 944 686
Writes from cache to disk = 6 671 672
Fetches from cache = 2 031 699 146

[EPluribusUnum]

@gsbelarus , write speed is affected by many factors. Please check this thread.

#8551 (comment)

[EPluribusUnum]

Some Windows +performance related articles:

https://ib-aid.com/en/articles/how-to-make-firebird-work-20-faster-at-windows-server-2016-in-less-than-1-minute/

http://www.firebirdnews.org/?p=5463

http://dyemanov.blogspot.com.br/2012/03/firebird-vs-windows-file-system-caching.html
http://dyemanov.blogspot.hu/2012/03/firebird-vs-windows-file-system-caching.html?showComment=1342194083132#c1637827408911776301

What is the update speed after backup-restore? Maybe you have long version chains (too many record versions).
Or maybe you have a long life transaction.

[EPluribusUnum]

3 seconds for prepare definitely not related to I/O. Something must be very wrong with either database or server.

Is this the first action after the connection is established? Or repeated prepare is still 3 sec?
(The first action takes time, there a bunch of cacheing and preread happens.)

[hvlad]

3 seconds for prepare definitely not related to I/O. Something must be very wrong with either database or server.

Cold filesystem cache and a lot of PP's

[hvlad]

Maybe you have long version chains (too many record versions).

Zero purges and expunges in stats - there was no garbage collection done by UPDATE

[aafemt]

Still almost 12 fetches per record is somehow too much for a table with sole PK.
@gsbelarus What is result of gstat suggested below?

[hvlad]

Please, show table stats (gstat -r -t GD_DOCUMENT) for the start.

Also, it is interesting to know how many random writes IOPS by 1-thread with queue depth 1 is possible to reach on this system.
Test file should be on the same drive as DB and should not fit into drive internal cache.
Block size == database page size.

[gsbelarus]

[hvlad]

Execute time = 18h 16m 52s 875ms
Reads from disk to cache = 4 944 686
Writes from cache to disk = 6 671 672

11616358 IOs / 65812 sec = 177 iops, looks like HDD

[gsbelarus]

No, it is NVMe with maximal performance settings:

[EPluribusUnum]

Google : samsung nvme ssd windows performance issue

[EPluribusUnum]

Also see : #6940 (comment)

[mrotteveel]

@EPluribusUnum All the results I see for those are - as far as I can tell - issues in early Windows 11 releases that have long since been solved by updates in Windows 11.

[gsbelarus]

Right now, I have run a stored procedure where there same updates are executed in blocks by 1000 records. Each update is run with parametrized statement in autonomous transaction. I'll come with the results.

[mrotteveel]

What is the output of winsat disk run on an administrator command prompt?

[gsbelarus]

11:50:33,96 G:\>winsat disk -drive g:
Windows System Assessment Tool
> Running: Feature Enumeration ''
> Run Time 00:00:00.00
> Running: Storage Assessment '-drive g: -ran -read'
> Run Time 00:00:00.34
> Running: Storage Assessment '-drive g: -seq -read'
> Run Time 00:00:02.47
> Running: Storage Assessment '-drive g: -seq -write'
Error: Failed to properly assess the disk.
Incorrect function.
> Run Time 00:00:00.01
> Dshow Video Encode Time                      0.00000 s
> Dshow Video Decode Time                      0.00000 s
> Media Foundation Decode Time                 0.00000 s
> Disk  Random 16.0 Read                       473.43 MB/s          8.3
> Disk  Sequential 64.0 Read                   1601.75 MB/s          8.9
> Total Run Time 00:00:03.11

[mrotteveel]

Interesting that it failed to perform -seq -write (and didn't even try -flush -drive G: -seq and -flush -drive G: -ran). I'm not sure what that means.

Is it possible that your drive is nearly full?

[gsbelarus]

No,

[mrotteveel]

According to the specs, the drive should support 7,000MB/s Seq. reads (5,000MB/s Seq. writes), so 1601.75 MB/s reads is substantially below that. Or was it under load when you ran winsat?

[aafemt]

Cheap notebook:

> Disk  Random 16.0 Read                       336.03 MB/s          8.1
> Disk  Sequential 64.0 Read                   2195.33 MB/s          9.1
> Disk  Sequential 64.0 Write                  1966.65 MB/s          9.0
> Average Read Time with Sequential Writes     0.085 ms          8.8
> Latency: 95th Percentile                     0.246 ms          8.8
> Latency: Maximum                             4.740 ms          8.5
> Average Read Time with Random Writes         0.083 ms          8.9

[gsbelarus]

yes, the update is running right now, so the winsat call is made in parallel

[gsbelarus]

So, I have started over. I did complete backup-restore and now going to execute update on the fresh database. The stats before start are as follows:

Database header page information:
        Flags                   0
        Generation              16932
        System Change Number    0
        Page size               8192
        ODS version             13.1
        Oldest transaction      16872
        Oldest active           16873
        Oldest snapshot         16873
        Next transaction        16873
        Sequence number         0
        Next attachment ID      50
        Implementation          HW=AMD/Intel/x64 little-endian OS=Windows CC=MSVC
        Shadow count            0
        Page buffers            4000
        Next header page        0
        Database dialect        3
        Creation date           Jun 11, 2025 10:42:03
        Attributes

    Variable header data:
        Database GUID:  {0114E3DA-B9D9-4FB5-9B57-276719A0F4DF}
        Sweep interval:         0
        *END*

Analyzing database pages ...
GD_DOCUMENT (202)
    Primary pointer page: 1669, Index root page: 1670
    Total formats: 2, used formats: 1
    Average record length: 108.74, total records: 172274304
    Average version length: 0.00, total versions: 0, max versions: 0
    Average fragment length: 0.00, total fragments: 0, max fragments: 0
    Average unpacked length: 408.00, compression ratio: 3.75
    Pointer pages: 2023, data page slots: 3300208
    Data pages: 3300208, average fill: 80%
    Primary pages: 3300208, secondary pages: 0, swept pages: 0
    Empty pages: 5, full pages: 3300191
    Table size: 27051876352 bytes
    Fill distribution:
         0 - 19% = 8
        20 - 39% = 3
        40 - 59% = 2
        60 - 79% = 1080653
        80 - 99% = 2219542

    Index RDB$PRIMARY109 (0)
        Root page: 26088830, depth: 3, leaf buckets: 159927, nodes: 172274304
        Average node length: 7.49, total dup: 0, max dup: 0
        Average key length: 3.53, compression ratio: 1.56
        Average prefix length: 4.24, average data length: 1.27
        Clustering factor: 44492180, ratio: 0.26
        Fill distribution:
             0 - 19% = 0
            20 - 39% = 0
            40 - 59% = 1
            60 - 79% = 0
            80 - 99% = 159926

BTW, the database restoration time is 4:10:00, which is not bad for a database file of 390 GB.

I will come with the results tomorrow.

[aafemt]

    60 - 79% = 1080653
    80 - 99% = 2219542

Have you used only gbak for the restore or do you have some complicated procedure? It looks like your database was created with flag "no reserve" and then this flag was erased. It is not normal to have such fill ratio and definitely it will lead to an awful fragmentation and slowdown on update.

[gsbelarus]

Here is the command:

gbak -r "xxxx.bk" "xxxx.FDB" -pas ******* -user sysdba -se localhost/3056:service_mgr -page 8192 -buffers 4000 -par 12

I think 80-99% includes 80% -- the default percentage of the page's filling at the restoration

[gsbelarus]

as the process is going on, here is a typical disk activity:

[gsbelarus]

and here is CPU activity:

[gsbelarus]

So,

1. Freshly restarted Windows 2009 Server
2. FB updated to FB 5.0.3
3. No windows folder indexing activated
4. The folder is excluded from the Windows Defender control

Now, the update operation even slower, nearing 20h.

PLAN (GD_DOCUMENT NATURAL)

172274304 record(s) was(were) updated in GD_DOCUMENT

------ Performance info ------
Prepare time = 4s 360ms
Execute time = 19h 38m 11s 453ms
Current memory = 68 464 096
Max memory = 162 062 208
Memory buffers = 4 000
Reads from disk to cache = 3 305 653
Writes from cache to disk = 3 367 641
Fetches from cache = 1 427 716 480

gstat output:

Database header page information:
        Flags                   0
        Generation              17027
        System Change Number    0
        Page size               8192
        ODS version             13.1
        Oldest transaction      16961
        Oldest active           16962
        Oldest snapshot         16962
        Next transaction        16962
        Sequence number         0
        Next attachment ID      53
        Implementation          HW=AMD/Intel/x64 little-endian OS=Windows CC=MSVC
        Shadow count            0
        Page buffers            4000
        Next header page        0
        Database dialect        3
        Creation date           Jun 11, 2025 10:42:03
        Attributes

    Variable header data:
        Database GUID:  {0114E3DA-B9D9-4FB5-9B57-276719A0F4DF}
        Sweep interval:         0
        *END*
        
Analyzing database pages ...
GD_DOCUMENT (202)
    Primary pointer page: 1669, Index root page: 1670
    Total formats: 2, used formats: 1
    Average record length: 108.74, total records: 172274304
    Average version length: 14.00, total versions: 172274304, max versions: 1
    Average fragment length: 0.00, total fragments: 0, max fragments: 0
    Average unpacked length: 408.00, compression ratio: 3.75
    Pointer pages: 2066, data page slots: 3370560
    Data pages: 3370560, average fill: 98%
    Primary pages: 3300204, secondary pages: 70356, swept pages: 0
    Empty pages: 1, full pages: 3370546
    Table size: 27628552192 bytes
    Fill distribution:
         0 - 19% = 5
        20 - 39% = 3
        40 - 59% = 1
        60 - 79% = 2
        80 - 99% = 3370549

    Index RDB$PRIMARY109 (0)
        Root page: 26088830, depth: 3, leaf buckets: 159927, nodes: 172274304
        Average node length: 7.49, total dup: 0, max dup: 0
        Average key length: 3.53, compression ratio: 1.56
        Average prefix length: 4.24, average data length: 1.27
        Clustering factor: 44492180, ratio: 0.26
        Fill distribution:
             0 - 19% = 0
            20 - 39% = 0
            40 - 59% = 1
            60 - 79% = 0
            80 - 99% = 159926        

By all means this machine is performant, but this update... how is it possible to be so slow?

[gsbelarus]

here is disk's performance for different scenarios

[gsbelarus]

I'm asking for the solution because our customer gives us a 4-hour window to update the production database. I never thought that just assigning values to 3 fields could take so long. So, now I'm wondering what trick would be applied here to get the task done.

And I'm confused because the restoration of the whole database takes just 4:10:00. Well, it is multithreaded, but even under FB3 it took 10 hours, twice as less... On the same server, on the same file. Weird.

[gsbelarus]

It seems we're on the verge of a massive server acceleration ))

[hvlad]

should these triggers be never fired as the IDs of the records aren't changed?

The check for the field (ID) change is inside trigger, so its fired always.

[gsbelarus]

So, there are 172 000 000 * 1 385 = 238 000 000 000 trigger calls.

19 hours is equivalent to 68 400 000 ms.

It gets us 0.0003 ms per trigger call.

And with CPU frequency of 2.1 GHz, there are only 630 CPU cycles per 0.0003 ms.

And the server does a lot of other tasks besides firing triggers. Roughly estimate as 2/3 for others
and 1/3 for triggers. It gives us ~200 CPU cycles or around 50-100 CPU instructions., Well, seems
reasonable.

So, the main task is to get rid of unnecessary trigger calls when there are no changes to the record's ID.

Or, significantly optimize trigger's call itself....

[gsbelarus]

I assume these triggers are meant to enforce referential integrity or implement CASCADE/SET NULL logic. However, both are unnecessary if the ID doesn't change. Simply moving the check for whether the ID has changed outside the trigger body reduces the number of operations (in our case) by an order of magnitude—about threefold. This will result in significant performance gains.

[hvlad]

I'll look what can be done in this direction.

[gsbelarus]

13 minutes instead of 18 hours. Wow! Amazing work by Vlad! Huge thanks — the donation's on me!

PLAN (GD_DOCUMENT NATURAL)

172274304 record(s) was(were) updated in GD_DOCUMENT

------ Performance info ------
Prepare time = 844ms
Execute time = 13m 30s 406ms
Current memory = 62 035 504
Max memory = 155 639 184
Memory buffers = 4 000
Reads from disk to cache = 3 308 448
Writes from cache to disk = 3 299 537
Fetches from cache = 1 392 584 970

[hvlad]

Thanks!

[TommiPrami]

13 minutes instead of 18 hours. Wow! Amazing work by Vlad! Huge thanks — the donation's on me!

PLAN (GD_DOCUMENT NATURAL)

172274304 record(s) was(were) updated in GD_DOCUMENT

------ Performance info ------
Prepare time = 844ms
Execute time = 13m 30s 406ms
Current memory = 62 035 504
Max memory = 155 639 184
Memory buffers = 4 000
Reads from disk to cache = 3 308 448
Writes from cache to disk = 3 299 537
Fetches from cache = 1 392 584 970

I missed the actual solution from this long thread.

Could you give a summary, how the problem was fixed?

-tee-

[aafemt]

#8598