Repository navigation
Thread blocking problem with "firebird-driver" #62
Description
Activity
Can't replicate. Firebird 5.
--- Begin dsbench measuring cycle 1/10 ---
2025-12-12 19:19:34,427 -- [INFO] (Worker-05 ): cycle=1, scale=1, dbsize=0.019745, done=89, errors=0, residence=59.38, elapsed=59.39, tpsR=1.50, tpsE=1.50, tpsD=1.48
2025-12-12 19:19:34,463 -- [INFO] (Worker-02 ): cycle=1, scale=1, dbsize=0.019745, done=81, errors=0, residence=59.42, elapsed=59.43, tpsR=1.36, tpsE=1.36, tpsD=1.35
2025-12-12 19:19:34,495 -- [INFO] (Worker-10 ): cycle=1, scale=1, dbsize=0.019745, done=80, errors=0, residence=59.45, elapsed=59.46, tpsR=1.35, tpsE=1.35, tpsD=1.33
2025-12-12 19:19:34,550 -- [INFO] (Worker-14 ): cycle=1, scale=1, dbsize=0.019745, done=86, errors=0, residence=59.74, elapsed=59.75, tpsR=1.44, tpsE=1.44, tpsD=1.43
2025-12-12 19:19:34,576 -- [INFO] (Worker-11 ): cycle=1, scale=1, dbsize=0.019745, done=96, errors=0, residence=57.88, elapsed=57.90, tpsR=1.66, tpsE=1.66, tpsD=1.60
2025-12-12 19:19:34,608 -- [INFO] (Worker-08 ): cycle=1, scale=1, dbsize=0.019745, done=87, errors=0, residence=59.91, elapsed=59.93, tpsR=1.45, tpsE=1.45, tpsD=1.45
2025-12-12 19:19:34,644 -- [INFO] (Worker-09 ): cycle=1, scale=1, dbsize=0.019745, done=82, errors=0, residence=59.81, elapsed=59.82, tpsR=1.37, tpsE=1.37, tpsD=1.37
2025-12-12 19:19:34,676 -- [INFO] (Worker-13 ): cycle=1, scale=1, dbsize=0.019745, done=79, errors=0, residence=59.54, elapsed=59.55, tpsR=1.33, tpsE=1.33, tpsD=1.32
2025-12-12 19:19:34,709 -- [INFO] (Worker-12 ): cycle=1, scale=1, dbsize=0.019745, done=87, errors=0, residence=57.96, elapsed=57.97, tpsR=1.50, tpsE=1.50, tpsD=1.45
2025-12-12 19:19:34,735 -- [INFO] (Worker-03 ): cycle=1, scale=1, dbsize=0.019745, done=86, errors=0, residence=59.51, elapsed=59.52, tpsR=1.45, tpsE=1.44, tpsD=1.43
2025-12-12 19:19:34,767 -- [INFO] (Worker-01 ): cycle=1, scale=1, dbsize=0.019745, done=82, errors=0, residence=59.83, elapsed=59.85, tpsR=1.37, tpsE=1.37, tpsD=1.37
2025-12-12 19:19:34,804 -- [INFO] (Worker-16 ): cycle=1, scale=1, dbsize=0.019745, done=102, errors=0, residence=59.66, elapsed=59.68, tpsR=1.71, tpsE=1.71, tpsD=1.70
2025-12-12 19:19:34,837 -- [INFO] (Worker-04 ): cycle=1, scale=1, dbsize=0.019745, done=101, errors=0, residence=59.77, elapsed=59.78, tpsR=1.69, tpsE=1.69, tpsD=1.68
2025-12-12 19:19:34,867 -- [INFO] (Worker-15 ): cycle=1, scale=1, dbsize=0.019745, done=102, errors=0, residence=59.87, elapsed=59.89, tpsR=1.70, tpsE=1.70, tpsD=1.70
2025-12-12 19:19:34,892 -- [INFO] (Worker-07 ): cycle=1, scale=1, dbsize=0.019745, done=77, errors=0, residence=59.96, elapsed=59.97, tpsR=1.28, tpsE=1.28, tpsD=1.28
2025-12-12 19:19:34,932 -- [INFO] (Worker-06 ): cycle=1, scale=1, dbsize=0.019745, done=89, errors=0, residence=59.30, elapsed=59.31, tpsR=1.50, tpsE=1.50, tpsD=1.48
2025-12-12 19:19:34,939 -- [INFO] (MainThread): System load:
[CPU] user=28.79s, nice=0.00s, system=24.80s, idle=620.53s, iowait=45.46s, irq=0.00s, softirq=0.48s, steal=0.00s, guest=0.00s, guest_nice=0.00s
[CPU] cpu_load=7.50%Could it be that your Firebird database is operating in transaction isolation level "read committed" instead of "repeatable read". We use the latter (which is default for Firebird 3 - my tests were with this so far) to force data consistency if several threads try to change same rows at the same time. Your test shows all error-counters equal to 0, my not. These are the transactions which were rolled back due to same row change trials. In "repeatable read" level this should not be zero at database scale 1.
I followed your instructions. And looking at
tpcbFdr.py, thecon.default_tpbis set to REPEATABLE READ, which is kind of pointless as it's the default for new driver. However,tpcbFdb.pydoes not set thedefault_tpb(as it's commented out), which means READ_COMMITTED as it's the default for FDB.Tested with latest stable Firebird 5.
Last days, I was trying many tests with Firebird 3, 4 and 5 on multiple Linux and Windows systems.
All tests using firebird-driver are showing the same expected behaviour with errors!=0 in the log.
Transaction isolation is REPEATABLE READ.
I added the test code once again and made a configuration fdr.conf with a small test using 3 small database sizes
instead of the full program which lasts hours.
Make sure, that "gnuplot" is installed, that the app can finish properly.
It will create an archive with results including some system parameters.
Please, try and send this archive.
Maybe, results can give an idea what is running different in your case.I wonder why you think it's the driver problem, and not problem in your configuration or usage? There are differences between FDB and firebird-driver in default TPBs, but the core logic for transaction handling is basically the same, it just uses OO API instead legacy (that is now thin wrapper around OO API anyway). If you still see differences, I would suggest to look closely at transaction parameters for each case. Probably best would be to use user trace session that will capture attachment and transaction events.
I can't exclude mistakes in usage in general. But the same code works fine (as expected) with PostgreSQL and Firebird 3 (when using FDB). That was the reason why I came here to find an answer. Today I reduced my code to the very basics: Create a database, open it with different default TPB's and try to read the current transaction isolation level. Finally database is dropped. Code (single file) is appended.
Output I got is:
Register server...
Register database configuration...
Transaction isolation level: tl=-1 => 2
Transaction isolation level: tl=4 => 2
Transaction isolation level: tl=3 => 2
Transaction isolation level: tl=2 => 2I expected a match of demanded and read transaction levels, or at least a change of it. But I always got the same.
If there is a mistake in usage, please let me know.Database configuration (means firebird.conf) only contains a single change to restrict access
to one system folder.You have wrong assumption how
default_tpbat connection level works. This parameter is passed toTransactionManagercreated forConnection.main_transaction, which is created in constructor__init__. So, changing it later has no effect. Instead, you need to set it up oncon.main_transaction.default_tpbintestfdr.pyline 40. Or, alternatively, you can pass the different tpb as parameter tocon.begindirectly.Also, the
default_tpbat connection level is passed asdefault_tpbto allTransactionManagerinstances created viaConnection.transaction_manager()calls.After holidays (have a belated nice new year) I resumed to make tests
to encircle the threading problem I mentioned in this ticket. Considering
your note that I have to set "con.main_transaction.default_tpb" instead
of "con.default_tpb" I repeated tests on multiple systems and for
Firebird 3, 4 and 5 using fdb and firebird-driver and as comparison
PostgreSQL (using psycopg2 and repeatable read as database configuration
default). Results you will find in the attached LibreOffice table.My original suspect that only firebird-driver is affected was wrong.
The driver fdb also shows this behaviour. Both drivers for Firebird show
the threading problem in all systems and all Firebird versions I tried
as soon as "repeatable read" is set to "con.main_transaction.default_tpb".Additionally, Firebird Server version 3 shows an unexpected behavior for
"read committed". Threads generate database errors due to collisions
(trying to change same rows at the same time) but they should not as you
can see it in versions 4 and 5 as well as in PostgreSQL attempts.I also attached fixed dsbench code and please you to repeat the test
as I described in the beginning of this ticket. I hope, you can replicate
the issue now.What about different behavior of read committed transactions on FB3 vs 4&5 - that's expected behavior. In fb4 there was a big fix related to read committed transactions which is not planned to be backported to fb3. I.e just use fresh versions if you dislike old behavior.
I don't want to proceed using FB3, I opened this issue because I encountered
an unexpected threading problem while migrating from "fdb" to "firebird-driver"
to be able to migrate to newer database versions 4 and 5. The tests I presented
in the table in my last post show me that the threading problem isn't a question
of "fdb" or "firebird-driver" its generic. I always encounter this problem
as soon as "repeatable read" is set to con.main_transaction.default_tpb.We developed database applications which are heavily using threads to connect
a database for concurring transactions - dsbench is one of these applications.
By design we decided to use "repeatable read" as default transaction isolation.
Transactions which collide with others are stopped and rolled back and repeated
by the applications until success.Due to a mistake so far (we set con.default_tpb instead of con.main_transaction.default_tpb
which has no effect to the main transaction according to P.Cisar) we did not really
set that isolation appropriately and had apparently no threading problem with FB3.
But we got aborted transaction due to collisions as we expected. Hence, we mistakenly
assumed that transaction isolation setting is fine.Now, with "repeatable read" set as required we encounter the problem, thats threads
are blocking each other so that some threads are doing the whole work and other
are more or less waiting all the time. For dsbench it does not really matter
because all threads are doing the same to measure the overall transaction performance.
Our other applications is using threads for different jobs which are equally important,
and in this case some jobs are blocked even for minutes.I also run dsbench with PostgreSQL with "repeatable read" level to show,
what I mean: There are also transaction aborts due to collisions ("Errors" in the
table in my last post) but the number of successful or aborted transactions is similar for all
threads. In other words: All threads have the same chance to do something no matter
if successful or not. In Firebird case some threads are doing nothing if the probability
of a collision is high. Somehow they are blocked while a few other threads steal
all time talking to the database.Are the threads using the same or different attachments?
If you mean connections to the database, then yes.
Each thread should open its own one for transactions.Can't reproduce
We are developing a database application based on Firebird and Python
which highly uses threads to run many jobs in parallel. Originally, we
decided to use the "fdb" module to connect to the database. Unfortunately,
fdb's support for Firebird versions bigger than 3 is limited, so a switch
to "firebird-driver" is recommended.
To ensure data consistency the database is operating "repeatable read",
this means if transactions of different threads touch the same data, the
transaction is throwing an exception and the application tries to repeat.
Unfortunately, "firebird-driver" tend to block some threads much more than
others so much that they exceed the tolerance of repetitions and give up.
But this nearly never happened with "fdb".
To demonstrate this, I can recommend a Python software we developed nearly
a decade ago to make database benchmarks with PostgreSQL and Firebird.
For PostgreSQL we used "psycopg2" module, for Firebird originally "fdb" and
"firebirdsql". In the last days I also added "firebird-driver" support.
The name of this benchmark software is "dsbench". It makes TPC-B transactions
to measure the database performance in a way like pgbench is doing it.
This means, dsbench generates databases of logarithmically rising sizes up to
about 150GB and is carrying out transactions then. Finally, the software
is creating several diagrams with results and calculates a performance
factor (we called that DSI - dsbench index) to give a single comparable
number.
One "transaction block" lasts about 1 minute. In this minute many threads
(default 16) connects to the database and try to execute as many transactions
as possible. If the database is small, the probability of a collision is high
and transactions must be rolled back. Each block gives you a table of results,
especially numbers of successful and failed transactions for each thread.
If "fdb" is used all threads show comparable numbers of successful and failed
transactions. Otherwise, if "firebird-driver" is used, mainly one thread
is doing all transactions and all the others are more or less blocked
and can't do anything. Let me show this with the dsbench log itself:
First: "fdb" - as expected
Number of "done" (successful transactions) and "errors" (rolled back due to collision) done by different threads is comparable.
--- Begin dsbench measuring cycle 1/10 ---
2025-12-11 21:42:33,477 -- [INFO] (Worker-03 ): cycle=1, scale=1, dbsize=0.017670, done=408, errors=1009, residence=4.58, elapsed=60.00, tpsR=88.99, tpsE=6.80, tpsD=6.80
2025-12-11 21:42:33,479 -- [INFO] (Worker-05 ): cycle=1, scale=1, dbsize=0.017670, done=565, errors=1338, residence=6.07, elapsed=59.99, tpsR=93.14, tpsE=9.42, tpsD=9.42
2025-12-11 21:42:33,483 -- [INFO] (Worker-11 ): cycle=1, scale=1, dbsize=0.017670, done=481, errors=1452, residence=4.92, elapsed=59.96, tpsR=97.75, tpsE=8.02, tpsD=8.02
2025-12-11 21:42:33,485 -- [INFO] (Worker-09 ): cycle=1, scale=1, dbsize=0.017670, done=459, errors=1495, residence=5.47, elapsed=60.00, tpsR=83.93, tpsE=7.65, tpsD=7.65
2025-12-11 21:42:33,488 -- [INFO] (Worker-14 ): cycle=1, scale=1, dbsize=0.017670, done=705, errors=1806, residence=7.66, elapsed=59.79, tpsR=92.09, tpsE=11.79, tpsD=11.75
2025-12-11 21:42:33,490 -- [INFO] (Worker-12 ): cycle=1, scale=1, dbsize=0.017670, done=374, errors=1283, residence=4.39, elapsed=59.68, tpsR=85.13, tpsE=6.27, tpsD=6.23
2025-12-11 21:42:33,492 -- [INFO] (Worker-16 ): cycle=1, scale=1, dbsize=0.017670, done=396, errors=1058, residence=4.04, elapsed=59.73, tpsR=98.03, tpsE=6.63, tpsD=6.60
2025-12-11 21:42:33,492 -- [INFO] (Worker-04 ): cycle=1, scale=1, dbsize=0.017670, done=597, errors=1412, residence=5.90, elapsed=59.73, tpsR=101.24, tpsE=9.99, tpsD=9.95
2025-12-11 21:42:33,496 -- [INFO] (Worker-13 ): cycle=1, scale=1, dbsize=0.017670, done=593, errors=1592, residence=6.64, elapsed=59.61, tpsR=89.37, tpsE=9.95, tpsD=9.88
2025-12-11 21:42:33,496 -- [INFO] (Worker-01 ): cycle=1, scale=1, dbsize=0.017670, done=498, errors=1770, residence=5.78, elapsed=59.69, tpsR=86.20, tpsE=8.34, tpsD=8.30
2025-12-11 21:42:33,516 -- [INFO] (Worker-15 ): cycle=1, scale=1, dbsize=0.017670, done=696, errors=2122, residence=7.18, elapsed=58.92, tpsR=96.90, tpsE=11.81, tpsD=11.60
2025-12-11 21:42:33,520 -- [INFO] (Worker-08 ): cycle=1, scale=1, dbsize=0.017670, done=484, errors=1634, residence=5.80, elapsed=58.55, tpsR=83.49, tpsE=8.27, tpsD=8.07
2025-12-11 21:42:33,520 -- [INFO] (Worker-10 ): cycle=1, scale=1, dbsize=0.017670, done=440, errors=1235, residence=5.05, elapsed=58.91, tpsR=87.16, tpsE=7.47, tpsD=7.33
2025-12-11 21:42:34,486 -- [INFO] (Worker-02 ): cycle=1, scale=1, dbsize=0.017670, done=727, errors=1759, residence=7.07, elapsed=60.00, tpsR=102.89, tpsE=12.12, tpsD=12.12
2025-12-11 21:42:34,486 -- [INFO] (Worker-07 ): cycle=1, scale=1, dbsize=0.017670, done=468, errors=1226, residence=4.79, elapsed=59.99, tpsR=97.68, tpsE=7.80, tpsD=7.80
2025-12-11 21:42:34,487 -- [INFO] (Worker-06 ): cycle=1, scale=1, dbsize=0.017670, done=599, errors=1639, residence=6.53, elapsed=59.99, tpsR=91.66, tpsE=9.98, tpsD=9.98
Second: "firebird-driver" - some threads blocked
For instance, Worker-15 did not try any transaction (successful or failed) within one minute!
--- Begin dsbench measuring cycle 1/10 ---
2025-12-11 21:45:49,128 -- [INFO] (Worker-07 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=10324, residence=0.00, elapsed=60.00, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,134 -- [INFO] (Worker-08 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=3, residence=0.00, elapsed=0.02, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,135 -- [INFO] (Worker-03 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=4, residence=0.00, elapsed=0.03, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,137 -- [INFO] (Worker-11 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=14, residence=0.00, elapsed=60.00, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,141 -- [INFO] (Worker-05 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=7, residence=0.00, elapsed=0.04, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,142 -- [INFO] (Worker-13 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=1766, residence=0.00, elapsed=32.10, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,146 -- [INFO] (Worker-14 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=3, residence=0.00, elapsed=0.02, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,146 -- [INFO] (Worker-16 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=7, residence=0.00, elapsed=0.03, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,146 -- [INFO] (Worker-09 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=4, residence=0.00, elapsed=0.03, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,147 -- [INFO] (Worker-02 ): cycle=1, scale=1, dbsize=0.014465, done=4029, errors=0, residence=26.45, elapsed=26.61, tpsR=152.34, tpsE=151.39, tpsD=67.15
2025-12-11 21:45:49,149 -- [INFO] (Worker-10 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=2028, residence=0.00, elapsed=44.95, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,152 -- [INFO] (Worker-12 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=0, residence=0.00, elapsed=0.00, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,152 -- [INFO] (Worker-04 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=2, residence=0.00, elapsed=0.02, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:49,152 -- [INFO] (Worker-15 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=0, residence=0.00, elapsed=0.00, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:50,126 -- [INFO] (Worker-06 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=12669, residence=0.00, elapsed=60.00, tpsR=0.00, tpsE=0.00, tpsD=0.00
2025-12-11 21:45:50,132 -- [INFO] (Worker-01 ): cycle=1, scale=1, dbsize=0.014465, done=0, errors=2, residence=0.00, elapsed=0.02, tpsR=0.00, tpsE=0.00, tpsD=0.00
To reproduce:
instead of installing system packages
python dsbench.py -f fdr.conf
self.job.fbdriver = "fdr"
to:
self.job.fbdriver = "fdb"
Regards
Mathias
dsbench.tar.gz