Sweep can unnecessary start 2nd time just after after 1st sweep process finished (seems that this occures only when FB instance is just restarted); on Classic this leads to "Error during sweep: connection shutdown" in firebird.log [CORE5091] #5376
CSPROG Sat Jan 30 01:40:11 2016
Sweep is started by SWEEPER
Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB"
OIT 3, OAT 4, OST 4, Next 11566350
CSPROG Sat Jan 30 01:40:12 2016
Sweep is finished
Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB"
OIT 11566350, OAT 11566351, OST 11566351, Next 11566352
CSPROG Sat Jan 30 01:40:12 2016
Sweep is started by SWEEPER
Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB"
OIT 11566350, OAT 11566352, OST 11566352, Next 11566353
CSPROG Sat Jan 30 01:40:12 2016
Sweep is finished
Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB"
OIT 11566353, OAT 11566352, OST 11566352, Next 11566354
6) Wait (if SS) about 60-70 seconds until database file will be closed by FB engine
7) copy ready-for-sweep-auto-start.fdb.000 ready-for-sweep-auto-start.fdb (but do NOT restart FB)
8) Run: again:
CSPROG Sat Jan 30 01:41:16 2016
Sweep is started by SWEEPER
Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB"
OIT 3, OAT 11566350, OST 11566350, Next 11566351
CSPROG Sat Jan 30 01:41:16 2016
Sweep is finished
Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB"
OIT 11566351, OAT 11566350, OST 11566350, Next 11566352
Above mentioned was checked on WI-V3.0.0.32294, SuperServer.
On SuperClassic only one pair of messages appear in firebird.log.
On Classic command like echo quit; | C:\MIX\firebird\fb30\isql /3333:C:\MIX\firebird\QA\fbt-repo\tmp\ready-for-sweep-auto-start.fdb
leads to:
CSPROG Sat Jan 30 01:53:03 2016
Sweep is started by SWEEPER
Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB"
OIT 3, OAT 4, OST 4, Next 11566350
CSPROG Sat Jan 30 01:53:03 2016
Shutting down the server with 1 active connection(s) to 1 database(s), 0 active service(s)
CSPROG Sat Jan 30 01:53:06 2016
Error during sweep:
connection shutdown
and gstat -h (after this) will show:
...
Oldest transaction 3
Oldest active 11566352
Oldest snapshot 11566352
Next transaction 11566353
...
PS. Database Tx counters in the file from .zip:
Oldest transaction 3
Oldest active 4
Oldest snapshot 4
Next transaction 11566349
Submitted by: @pavel-zotov
Attachments: unnecessary-sweep-subsequent-start-after-1st-sweep-finishes.zip
1) unpack database from attached .zip (this is 'raw' .fdb with Next - OIT > 11'000'000); 2) copy ready-for-sweep-auto-start.fdb.000 ready-for-sweep-auto-start.fdb 3) restart FB; 4) Run:
echo quit; | C:\MIX\firebird\fb30\isql /3333:C:\MIX\firebird\QA\fbt-repo\tmp\ready-for-sweep-auto-start.fdb
5) check firebird.log:
CSPROG Sat Jan 30 01:40:11 2016 Sweep is started by SWEEPER Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB" OIT 3, OAT 4, OST 4, Next 11566350
CSPROG Sat Jan 30 01:40:12 2016 Sweep is finished Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB" OIT 11566350, OAT 11566351, OST 11566351, Next 11566352
CSPROG Sat Jan 30 01:40:12 2016 Sweep is started by SWEEPER Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB" OIT 11566350, OAT 11566352, OST 11566352, Next 11566353
CSPROG Sat Jan 30 01:40:12 2016 Sweep is finished Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB" OIT 11566353, OAT 11566352, OST 11566352, Next 11566354
6) Wait (if SS) about 60-70 seconds until database file will be closed by FB engine 7) copy ready-for-sweep-auto-start.fdb.000 ready-for-sweep-auto-start.fdb (but do NOT restart FB) 8) Run: again:
echo quit; | C:\MIX\firebird\fb30\isql /3333:C:\MIX\firebird\QA\fbt-repo\tmp\ready-for-sweep-auto-start.fdb
9) check firebird.log:
CSPROG Sat Jan 30 01:41:16 2016 Sweep is started by SWEEPER Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB" OIT 3, OAT 11566350, OST 11566350, Next 11566351
CSPROG Sat Jan 30 01:41:16 2016 Sweep is finished Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB" OIT 11566351, OAT 11566350, OST 11566350, Next 11566352
Above mentioned was checked on WI-V3.0.0.32294, SuperServer.
On SuperClassic only one pair of messages appear in firebird.log.
On Classic command like echo quit; | C:\MIX\firebird\fb30\isql /3333:C:\MIX\firebird\QA\fbt-repo\tmp\ready-for-sweep-auto-start.fdb leads to:
CSPROG Sat Jan 30 01:53:03 2016 Sweep is started by SWEEPER Database "C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\READY-FOR-SWEEP-AUTO-START.FDB" OIT 3, OAT 4, OST 4, Next 11566350
CSPROG Sat Jan 30 01:53:03 2016 Shutting down the server with 1 active connection(s) to 1 database(s), 0 active service(s)
CSPROG Sat Jan 30 01:53:06 2016 Error during sweep: connection shutdown
and gstat -h (after this) will show: ... Oldest transaction 3 Oldest active 11566352 Oldest snapshot 11566352 Next transaction 11566353 ...
PS. Database Tx counters in the file from .zip:
Oldest transaction 3 Oldest active 4 Oldest snapshot 4 Next transaction 11566349