Performance regression has encountered when comparing snapshots
- 5.0.1.1416-ad0e5ce (13.06.2024 20:14)
== vs==
- 5.0.1.1416-b4b3559 (17.06.2024 10:21) (and further 5.x up to fresh 5.0.3).
These two snapshots and demo database are uploaded to:
https://drive.google.com/drive/folders/19PiXH3MJWU7dw9Vm4uFh0ZznaKZ4aOpY?usp=sharing
(database was encrypted, password will be sent privately to firebird2 at yandex.ru)
To reproduce:
- unpack DB (this is .fbk) and restore it in any 5.0.1 build;
- Unpack snapshot 5.0.1.1416-ad0e5ce (13.06.2024 20:14)
- run trace with config:
database =
{
enabled = true
log_initfini = false
log_errors = true
include_filter = "%(from clrefdet)%"
time_threshold = 0
log_statement_finish = true
explain_plan = true
print_plan = true
print_perf = true
max_sql_length = 32000
max_arg_length = 32000
max_arg_count = 10
}
- set in firebird.conf:
OuterJoinConversion = false
- run query:
set list on;
select * from rdb$config where rdb$config_name = 'OuterJoinConversion';
set count on;
select r.ctdid
from clrefdet r
left join get_usl_struct(iif (r.fact_schid > 0,r.fact_schid, r.schid), '01.01.2026') gs on 1=1
inner join wschema w on w.schid = gs.schid and w.structid = 1
left join clreferrals r2 on r.refid = r2.refid
where
r.refid = 123804997
and (r.notuse is null or r.notuse =0)
order by r.rowcode
;
Output will appear almost instantly and will contain 12 records.
On this snapshot (5.0.1.1416-ad0e5ce) trace shows:
Select Expression
-> Sort (record length: 164, key length: 12)
-> Filter
-> Nested Loop Join (outer)
-> Nested Loop Join (inner)
-> Filter
-> Nested Loop Join (outer)
-> Filter
-> Table "CLREFDET" as "R" Access By ID
-> Bitmap
-> Index "CLREFDET_REFID" Range Scan (full match)
-> Procedure "GET_USL_STRUCT" as "GS" Scan
-> Filter
-> Table "WSCHEMA" as "W" Access By ID
-> Bitmap
-> Index "PK_WSCHEMA" Unique Scan
-> Filter
-> Table "CLREFERRALS" as "R2" Access By ID
-> Bitmap
-> Index "PK_CLREFERRALS" Unique Scan
12 records fetched
7 ms, 9 read(s), 114 fetch(es)
Table Natural Index Update Insert Delete Back
*****************************************************************************************
WSCHEMA 12
CLREFERRALS 12
CLREFDET 12
Now let's change in firebird.conf OuterJoinConversion = true (i.e. set it to default value)
Output also will appear very fast, and trace will show:
Select Expression
-> Filter
-> Nested Loop Join (outer)
-> Filter (preliminary)
-> Sort (record length: 140, key length: 12)
-> Nested Loop Join (inner)
-> Filter
-> Table "CLREFDET" as "R" Access By ID
-> Bitmap
-> Index "CLREFDET_REFID" Range Scan (full match)
-> Nested Loop Join (inner)
-> Procedure "GET_USL_STRUCT" as "GS" Scan
-> Filter
-> Table "WSCHEMA" as "W" Access By ID
-> Bitmap
-> Index "PK_WSCHEMA" Unique Scan
-> Filter
-> Table "CLREFERRALS" as "R2" Access By ID
-> Bitmap
-> Index "PK_CLREFERRALS" Unique Scan
12 records fetched
7 ms, 9 read(s), 114 fetch(es)
Table Natural Index Update Insert Delete
*************************************************************************************
WSCHEMA 12
CLREFERRALS 12
CLREFDET 12
####################################################################
Now stop FB and unpack next snapshot, 5.0.1.1416-b4b3559 (17.06.2024 10:21) and repeat above mentioned steps.
- for
OuterJoinConversion = false query runs instantly and trace will show:
Select Expression
-> Sort (record length: 164, key length: 12)
-> Filter
-> Nested Loop Join (outer)
-> Nested Loop Join (inner)
-> Filter
-> Nested Loop Join (outer)
-> Filter
-> Table "CLREFDET" as "R" Access By ID
-> Bitmap
-> Index "CLREFDET_REFID" Range Scan (full match)
-> Procedure "GET_USL_STRUCT" as "GS" Scan
-> Filter
-> Table "WSCHEMA" as "W" Access By ID
-> Bitmap
-> Index "PK_WSCHEMA" Unique Scan
-> Filter
-> Table "CLREFERRALS" as "R2" Access By ID
-> Bitmap
-> Index "PK_CLREFERRALS" Unique Scan
12 records fetched
7 ms, 9 read(s), 114 fetch(es)
Table Natural Index Update Insert Delete Back
*****************************************************************************************
WSCHEMA 12
CLREFERRALS 12
CLREFDET 12
- set
OuterJoinConversion = true (default!); performance now become very poor:
Select Expression
-> Filter
-> Nested Loop Join (outer)
-> Filter (preliminary)
-> Sort (record length: 140, key length: 12)
-> Filter
-> Nested Loop Join (inner)
-> Filter
-> Table "CLREFDET" as "R" Access By ID
-> Bitmap
-> Index "CLREFDET_REFID" Range Scan (full match)
-> Filter
-> Table "WSCHEMA" as "W" Access By ID
-> Bitmap
-> Index "WSCHEMA_STRUCT" Range Scan (full match)
-> Procedure "GET_USL_STRUCT" as "GS" Scan
-> Filter
-> Table "CLREFERRALS" as "R2" Access By ID
-> Bitmap
-> Index "PK_CLREFERRALS" Unique Scan
12 records fetched
14744 ms, 182 read(s), 134897 fetch(es)
Table Natural Index Update Insert Delete Back
*****************************************************************************************
WSCHEMA 132696
CLREFERRALS 12
CLREFDET 12
This is comparison of explained plans before and after slowdown when OuterJoinConversion = true:
(left part = "good"; right part = "poor")
Regression can be seen also on 5.0.2.1613 and 5.0.3.1649.
PS.
Database and query are published with the kind permission of persons who provided them to IBSurgeon.
Performance regression has encountered when comparing snapshots
== vs==
These two snapshots and demo database are uploaded to:
https://drive.google.com/drive/folders/19PiXH3MJWU7dw9Vm4uFh0ZznaKZ4aOpY?usp=sharing
(database was encrypted, password will be sent privately to firebird2 at yandex.ru)
To reproduce:
OuterJoinConversion = falseOutput will appear almost instantly and will contain 12 records.
On this snapshot (5.0.1.1416-ad0e5ce) trace shows:
Now let's change in firebird.conf
OuterJoinConversion = true(i.e. set it to default value)Output also will appear very fast, and trace will show:
####################################################################
Now stop FB and unpack next snapshot, 5.0.1.1416-b4b3559 (17.06.2024 10:21) and repeat above mentioned steps.
OuterJoinConversion = falsequery runs instantly and trace will show:OuterJoinConversion = true(default!); performance now become very poor:This is comparison of explained plans before and after slowdown when
OuterJoinConversion = true:(left part = "good"; right part = "poor")
Regression can be seen also on 5.0.2.1613 and 5.0.3.1649.
PS.
Database and query are published with the kind permission of persons who provided them to IBSurgeon.