Hello,

After spending more than a week trying to resolve the following issue we hope someone has an answer on this.

We have a database with about 230 tables and 200 stored procedures which is being used by our customers.
Each customer have a dedicated installation with it's own database varying in size from 50MB up to 2GB.
At the moment they use Firebird 2.5.1.26351 Super-Classic Win32 on different platforms (Win 7 Pro, Win 10 Pro, Windows server 2012 R2).

The issue occurs when we execute a complex (recursive) stored procedure after the database engine has been idle for about 20 minutes.
Executing the stored procedure after those 20 minutes can take around 18-20 seconds to complete, while it normally takes around 0,1 seconds.
Even after restarting the Firebird service executing the stored procedure immediately never takes longer then 3-4 seconds (unless the 20 minutes are passed).

Things we tried:

* Restarting the Firebird service.
Even if we restart the Firebird service between those 20 minutes, once the 20 minute mark is reached it simply takes around 20 seconds again.
* Installed firebird and the database on an SSD (Samsung Evo 500GB) under Windows 10 Pro (Fall Creators update) with default configuration.
- No difference.
* Turned off inactivity settings in Windows for the HDD, so Windows doesn't turn off the HDD.
- No difference.
* Upgraded Firebird to version 2.5.7.27050.
- No difference.
* Upgraded Firebird to version 3.0.2 using the migration guide (backup/restore, etc.).
- No difference.

When we insert a record into a random table within the same connection and transaction before executing the stored procedure,
after those 20 minutes the insert is fast and executing the stored procedure takes around 20 seconds again.

This is the trace of what happens when we execute the stored procedure after 20 minutes (watch the prepare of statement 70).

2017-12-05T09:57:19.4580 (8628:0395DB90) TRACE_INIT
SESSION_17 User Trace 1

2017-12-05T09:57:19.4580 (8628:0395DB90) ATTACH_DATABASE
COACH3 (ATT_10442, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\Users\Marcel\documents\visual studio 2017\Projects\FirebirdTest\FirebirdTest\bin\Debug\FirebirdTest.exe:20176

2017-12-05T09:57:19.4600 (8628:0395DB90) START_TRANSACTION
COACH3 (ATT_10442, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\Users\Marcel\documents\visual studio 2017\Projects\FirebirdTest\FirebirdTest\bin\Debug\FirebirdTest.exe:20176
(TRA_27500, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

2017-12-05T09:57:19.4670 (8628:0395DB90) PREPARE_STATEMENT
COACH3 (ATT_10442, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\Users\Marcel\documents\visual studio 2017\Projects\FirebirdTest\FirebirdTest\bin\Debug\FirebirdTest.exe:20176
(TRA_27500, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Statement 55:
-------------------------------------------------------------------------------
execute procedure SP_CHECK_TOEGANGSPROFIEL(?,?)
4 ms

2017-12-05T09:57:19.4690 (8628:0395DB90) EXECUTE_PROCEDURE_START
COACH3 (ATT_10442, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\Users\Marcel\documents\visual studio 2017\Projects\FirebirdTest\FirebirdTest\bin\Debug\FirebirdTest.exe:20176
(TRA_27500, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Procedure SP_CHECK_TOEGANGSPROFIEL:
param0 = varchar(20), "AAJQ2295384"
param1 = varchar(20), "AAJQ1796287"


2017-12-05T09:57:37.5380 (8628:0395DB90) PREPARE_STATEMENT
COACH3 (ATT_10442, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\Users\Marcel\documents\visual studio 2017\Projects\FirebirdTest\FirebirdTest\bin\Debug\FirebirdTest.exe:20176
(TRA_27500, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Statement 70:
-------------------------------------------------------------------------------
EXECUTE PROCEDURE SP_CHECK_PROFIELEXPRESSIETREE('AAJQ1796287', 'AAJQ2295385', NULL, 1)
18068 ms

2017-12-05T09:57:37.5390 (8628:0395DB90) EXECUTE_PROCEDURE_START
COACH3 (ATT_10442, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\Users\Marcel\documents\visual studio 2017\Projects\FirebirdTest\FirebirdTest\bin\Debug\FirebirdTest.exe:20176
(TRA_27500, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Procedure SP_CHECK_PROFIELEXPRESSIETREE:
param0 = varchar(20), "AAJQ1796287"
param1 = varchar(20), "AAJQ2295385"
param2 = varchar(20), "<NULL>"
param3 = integer, "1"


2017-12-05T09:57:37.5670 (8628:0395DB90) PREPARE_STATEMENT
COACH3 (ATT_10442, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\Users\Marcel\documents\visual studio 2017\Projects\FirebirdTest\FirebirdTest\bin\Debug\FirebirdTest.exe:20176
(TRA_27500, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Statement 87:
-------------------------------------------------------------------------------
EXECUTE PROCEDURE SP_CHECK_PROFIELEXPRESSIE('AAJQ1796287', 'AAJQ2295385', NULL)
28 ms

2017-12-05T09:57:37.5670 (8628:0395DB90) EXECUTE_PROCEDURE_START
COACH3 (ATT_10442, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\Users\Marcel\documents\visual studio 2017\Projects\FirebirdTest\FirebirdTest\bin\Debug\FirebirdTest.exe:20176
(TRA_27500, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Procedure SP_CHECK_PROFIELEXPRESSIE:
param0 = varchar(20), "AAJQ1796287"
param1 = varchar(20), "AAJQ2295385"
param2 = varchar(20), "<NULL>"


Using Firebird SQL Studio to compile the stored procedure also takes around 20 seconds after the 20 minutes idle time.

Does anyone have an idea why this happens only after around 20 minutes and not every time ?

Thanks in advance,

Marcel Brink

[cid:image001.png@01D1D8FF.6BD77F00]



[Non-text portions of this message have been removed]