Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Firebird's internal timer incorrectly resets existing timer entries [CORE6182] #6427

Closed
firebird-issue-importer opened this issue Nov 3, 2019 · 12 comments

Comments

@firebird-issue-importer
Copy link

firebird-issue-importer commented Nov 3, 2019

Submitted by: @pavel-zotov

Attachments:
c6182-check.png

According to %FB4_HOME%\doc\sql.extensions\README.external_connections_pool, parameter ExtConnPoolLifeTime is "idle connection lifetime, seconds".
It seems that if 'main' database performs PSQL which uses EDS to several (>=2) different databases then value of ExtConnPoolLifeTime is applied to the LAST moment when activity was, regardless to some concrete database.
Connection(s) to some DB that was handled before any others will exist until *all* activity will gone, rather than to *this* ("earliest") DB.

Steps to reproduce:
1) prepare firebird.conf:

Servermode = Super #⁠ or SuperClassic
ExtConnPoolSize = 10
ExtConnPoolLifeTime = 10

2) restart FB if it is running as service;

3) run following script (change path and names of temp databases if needed):

set bail on;

shell del c:\\temp\\tmp4eds\_01\.fdb 2\>nul;
shell del c:\\temp\\tmp4eds\_02\.fdb 2\>nul;
shell del c:\\temp\\tmp4eds\_03\.fdb 2\>nul;
shell del c:\\temp\\tmp4eds\_04\.fdb 2\>nul;
shell del c:\\temp\\tmpmain\.fdb 2\>nul;

create database 'localhost:c:\\temp\\tmp4eds\_01\.fdb' user SYSDBA password 'masterkey';
commit;
create database 'localhost:c:\\temp\\tmp4eds\_02\.fdb' user SYSDBA password 'masterkey';
commit;
create database 'localhost:c:\\temp\\tmp4eds\_03\.fdb' user SYSDBA password 'masterkey';
commit;
create database 'localhost:c:\\temp\\tmp4eds\_04\.fdb' user SYSDBA password 'masterkey';
commit;

create database 'localhost:c:\\temp\\tmpmain\.fdb' user SYSDBA password 'masterkey';
commit;

create table tdelay\(id int primary key\);
commit;
create sequence g;
commit;

set term ^;
create procedure sp\_delay returns\( dts1 timestamp, dts2 timestamp, elap\_ms int \) as
    declare v\_id int;
begin
    v\_id = gen\_id\(g,1\);
    dts1 = cast\('now' as timestamp\);
    insert into tdelay\(id\) values\( :v\_id \);
    in autonomous transaction do
    begin
        insert into tdelay\(id\) values\( :v\_id \);
        when any do
        begin
        end
    end
    delete from tdelay where id = :v\_id;
    dts2 = cast\('now' as timestamp\);
    elap\_ms = datediff\( millisecond from dts1 to dts2\);
    suspend;
end
^

create procedure sp\_do\_eds \( a\_target\_db varchar\(128\) \) returns\( source\_dts timestamp, source\_db varchar\(128\), target\_db varchar\(128\), target\_dts timestamp \) as
begin
    source\_dts = cast\('now' as timestamp\);
    for 
        execute statement 
            \('select cast\(? as varchar\(128\)\) as connect\_from\_db, mon$database\_name as connect\_to\_db, cast\(''now'' as timestamp\) from mon$database'\)
            \( rdb$get\_context\('SYSTEM', 'DB\_NAME'\)  \)
            on external
                'localhost:' \|\| a\_target\_db
            as
                user 'sysdba'
                password' masterkey'
        into source\_db, target\_db,  target\_dts
   do
       suspend;
end
^

set term ;^
commit;
\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

set list on;

set transaction lock timeout 8;
select \* from sp\_do\_eds\( 'c:\\temp\\tmp4eds\_01\.fdb' \);
select p\.\* from sp\_delay p;
commit;

set transaction lock timeout 8;
select \* from sp\_do\_eds\( 'c:\\temp\\tmp4eds\_02\.fdb' \);
select p\.\* from sp\_delay p;
commit;

set transaction lock timeout 8;
select \* from sp\_do\_eds\( 'c:\\temp\\tmp4eds\_03\.fdb' \);
select p\.\* from sp\_delay p;
commit;

set transaction lock timeout 8;
select \* from sp\_do\_eds\( 'c:\\temp\\tmp4eds\_04\.fdb' \);
select p\.\* from sp\_delay p;
commit;

set heading off;

set bail off;

drop database; \-\-\-\-\-\-\-\-\-\- tmpmain

\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

rollback;
connect 'localhost:c:\\temp\\tmp4eds\_01\.fdb';
select 'Point before DROP ' \|\| rdb$get\_context\('SYSTEM', 'DB\_NAME'\) \|\| ': ' \|\| cast\('now' as timestamp\) from rdb$database;

set echo on;
drop database;
set echo off;

\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

rollback;
connect 'localhost:c:\\temp\\tmp4eds\_02\.fdb';
select 'Point before DROP ' \|\| rdb$get\_context\('SYSTEM', 'DB\_NAME'\) \|\| ': ' \|\| cast\('now' as timestamp\) from rdb$database;

set echo on;
drop database;
set echo off;

\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

rollback;
connect 'localhost:c:\\temp\\tmp4eds\_03\.fdb';
select 'Point before DROP ' \|\| rdb$get\_context\('SYSTEM', 'DB\_NAME'\) \|\| ': ' \|\| cast\('now' as timestamp\) from rdb$database;

set echo on;
drop database;
set echo off;

\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

rollback;
connect 'localhost:c:\\temp\\tmp4eds\_04\.fdb';
select 'Point before DROP ' \|\| rdb$get\_context\('SYSTEM', 'DB\_NAME'\) \|\| ': ' \|\| cast\('now' as timestamp\) from rdb$database;

set echo on;
drop database;
set echo off;

=======

Console will be filled with messages

SOURCE_DTS 2019-11-03 14:28:41.4960
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_01.FDB
TARGET_DTS 2019-11-03 14:28:41.9100 -------------------------------------------------------- [ 1 ]
. . .
SOURCE_DTS 2019-11-03 14:29:06.5020
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_04.FDB
TARGET_DTS 2019-11-03 14:29:06.7940

-- and after this:

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_01.FDB: 2019-11-03 14:29:14.8240 --------------------- [ 2 ]

drop database;
Statement failed, SQLSTATE = 40001
lock time-out on wait transaction
-object C:\TEMP\TMP4EDS_01.FDB is in use

So, we can see here that:
1) last ctivity in TMP4EDS_01.FDB was at "2019-11-03 14:28:41.9100" (see line marked as "[ 1 ]" )
2) attempt to drop this DB was at 2019-11-03 14:29:14.8240 ( line "[ 2 ]" )

datediff() between these values is ~33 seconds. This is much more than 10 seconds which was assigned to ExtConnPoolLifeTime.

Commits: 1c13dbb 0d33f4e

====== Test Details ======

Currently test is only for FB 4.0. One need to found other test case for FB 3.x because ExpPool feature not accessible there.

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 3, 2019

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 5, 2019

Commented by: @hvlad

I can't reproduce the issue.

This is what i see

====================================================================

SOURCE_DTS 2019-11-05 20:40:21.9130
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_01.FDB
TARGET_DTS 2019-11-05 20:40:22.0720

DTS1 2019-11-05 20:40:22.0740
DTS2 2019-11-05 20:40:30.0770
ELAP_MS 8003

SOURCE_DTS 2019-11-05 20:40:30.0790
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_02.FDB
TARGET_DTS 2019-11-05 20:40:30.2140

DTS1 2019-11-05 20:40:30.2150
DTS2 2019-11-05 20:40:38.2160
ELAP_MS 8001

SOURCE_DTS 2019-11-05 20:40:38.2190
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_03.FDB
TARGET_DTS 2019-11-05 20:40:38.3590

DTS1 2019-11-05 20:40:38.3600
DTS2 2019-11-05 20:40:46.3610
ELAP_MS 8001

SOURCE_DTS 2019-11-05 20:40:46.3640
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_04.FDB
TARGET_DTS 2019-11-05 20:40:46.5040

DTS1 2019-11-05 20:40:46.5130
DTS2 2019-11-05 20:40:54.5130
ELAP_MS 8000

Use CONNECT or CREATE DATABASE to specify a database

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_01.FDB: 2019-11-05 20:40:54.6610

drop database;
set echo off;
Use CONNECT or CREATE DATABASE to specify a database

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_02.FDB: 2019-11-05 20:40:54.7970

drop database;
set echo off;
Use CONNECT or CREATE DATABASE to specify a database

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_03.FDB: 2019-11-05 20:40:54.8930

drop database;
Statement failed, SQLSTATE = 40001
lock time-out on wait transaction
-object C:\TEMP\TMP4EDS_03.FDB is in use
After line 123 in file C:\Temp\core-6182.sql
set echo off;

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_04.FDB: 2019-11-05 20:40:55.0910

drop database;
Statement failed, SQLSTATE = 40001
lock time-out on wait transaction
-object C:\TEMP\TMP4EDS_04.FDB is in use
After line 133 in file C:\Temp\core-6182.sql
set echo off;

====================================================================

i.e. databases 01 and 02 was dropped succesfully and 03 and 04 failed to drop due to presence of (idle) external connections to it.

Note, external connection become idle not when its statement is executed but when local transaction is finished.
Thus, when script start to drop databases, there are two idle external connections in pool : db03 (2 seconds to expire) and db04 (10 seconds to expire).

All works as expected.

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 6, 2019

Commented by: @pavel-zotov

In your result I see that there was no error when script did this:

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_01.FDB: 2019-11-05 20:40:54.6610

drop database;
set echo off;
Use CONNECT or CREATE DATABASE to specify a database

It's strange! Please look in the sreen that i've created just now for actual FB 4.x.

PS. Used config:

BugCheckAbort = 1
RemoteServicePort = 3400
FileSystemCacheThreshold = 65536K
IpcName = fb40_SS
ServerMode = Super
DefaultDbCachePages = 20000
TempBlockSize = 2M
TempCacheLimit = 2147483647
LockHashSlots = 22111
LockMemSize = 5M
ExtConnPoolSize = 10
ExtConnPoolLifeTime = 10
ReadConsistency = 0
TempDirectories=C:\TEMP\firebird
MaxUnflushedWrites = -1
MaxUnflushedWriteTime = -1
AuthServer = Legacy_Auth, Srp, Win_Sspi
UserManager = Legacy_UserManager, Srp
AuthClient = Legacy_Auth, Srp, Srp256, Win_Sspi
ExternalFileAccess = Full
WireCrypt = Enabled
KeyHolderPlugin = KeyHolder

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 6, 2019

Modified by: @pavel-zotov

Attachment: c6182-check.png [ 13398 ]

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 6, 2019

Commented by: @pavel-zotov

PS. WI-T4.0.0.1639 Firebird 4.0 Beta 1

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 6, 2019

Commented by: @hvlad

The issue is reproducidble with Legacy_Auth plugin.

The real problem is inside TimerControl implementation in Firebird.
It incorrectly resets existing timer entries and because of this some events could happen much later then it should be.

Legacy_Auth plugin creates own timer to release cached connection to the security database.
Due to test case nature this timer resets every 8 seconds (when external connection is authenticated) and prevents firing of EDS connection pool timer.

Looks like the same issue was described at CORE6082

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 6, 2019

Commented by: @hvlad

The issue with timers should be present in v3 also.
Of course it should be reproduced in some other way.

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 6, 2019

Modified by: @hvlad

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

Fix Version: 3.0.5 [ 10885 ]

Fix Version: 4.0 Beta 2 [ 10888 ]

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 9, 2019

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Resolved [ 5 ]

QA Status: No test => Done successfully

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 9, 2019

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Closed [ 6 ]

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Nov 9, 2019

Modified by: @pavel-zotov

status: Closed [ 6 ] => Closed [ 6 ]

QA Status: Done successfully => Done with caveats

Test Details: Currently test is only for FB 4.0. One need to found other test case for FB 3.x because ExpPool feature not accessible there.

@firebird-issue-importer
Copy link
Author

firebird-issue-importer commented Dec 13, 2019

Modified by: @dyemanov

summary: ExtConnPoolLifeTime acts as countdown for activity in MOST RECENT database (of several) rather then separate for each of used databases => Firebird's internal timer incorrectly resets existing timer entries

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants