Данные о SWEEP в логе трейса: нет backout'ов, которые должны быть

Таблоид
Дата: 12.08.2012 12:56:09
hi all. WI-V2.5.2.26520

Дано: пустая база с FW = OFF, в которой созданы две таблички:
recreate global temporary table ttmp(id int, s01 varchar(1000)) on commit preserve rows;
recreate table tfix(id int, s01 varchar(1000));
commit;


Сценарий_1.
Подключаюсь к этой базе, ввожу 200 тыс строк в обе таблицы и делаю rollback:
+
commit;
set transaction read committed;
set term ^;
execute block as
declare n int = 200000;
declare k int;
begin
while (n>0) do begin
insert into ttmp(id,s01) values(:n, rpad('',1000,'x'));
insert into tfix(id,s01) values(:n, rpad('',1000,'x'));
n=n-1;
end
end^
set term ;^
rollback;
Затем запускаю трейс, и возвращаясь в isql, делаю:
SQL> select count(*) from tfix;

COUNT
============
0

SQL> select count(*) from ttmp;

COUNT
============
0
В трейсе при этом вижу вполне ожидаемые ненулевые backout's как для TFIX, так и для TTMP:
+
select count(*) from tfix

1 records fetched

3336 ms, 3227 read(s), 3225 write(s), 2212906 fetch(es), 409677 mark(s)



Table Natural Index Update Insert Delete Backout Purge Expunge

***************************************************************************************************************

TFIX 200000
...
select count(*) from ttmp

1 records fetched

3749 ms, 3228 read(s), 3225 write(s), 2212906 fetch(es), 409677 mark(s)



Table Natural Index Update Insert Delete Backout Purge Expunge

***************************************************************************************************************

TTMP 200000
По этому сценарию вопросов нет, всё понятно.

Сценарий_2. Создаем ситуацию, при которой должен стартовать sweep.

session #1. Также вводим 200 тыс строк:
commit;
set transaction read committed;
set term ^;
execute block as
declare n int = 200000;
declare k int;
begin
while (n>0) do begin
insert into ttmp(id,s01) values(:n, rpad('',1000,'x'));
insert into tfix(id,s01) values(:n, rpad('',1000,'x'));
n=n-1;
end
end^
set term ;^
-- NB: rollback пока не делаем!

session #2 Стартуем 21 тыс автономных транзакций:
commit;
set transaction read committed;
set term ^;
execute block as
declare n int = 21000;
declare k int;
begin
while (n>0) do begin
in autonomous transaction do select 1 from rdb$database into :k;
n=n-1;
end
end^
set term ;^
commit;

session #1
rollback;

В результате этих действий gstat -h покажет:
C:\1INSTALL\FIREBIRD\Data>gstat -h T1.FDB
<...>
ODS version 11.2
Oldest transaction 10
Oldest active 11
Oldest snapshot 11
Next transaction 21013
<...>
Sweep interval: 20000
Далее запускаю трейс и в первом isql-окне ввожу:
SQL> select 1 from rdb$database;

CONSTANT
============
1

SQL> select count(*) from tfix;

COUNT
============
0

SQL> select count(*) from ttmp;

COUNT
============
0
В логе трейса после этого вижу:
1) SWEEP_START (строка 112) и его прогресс для всех RDB$-таблиц (строки 132...418) - эти строки появились сразу после ввода "select 1 from rdb$database"
2) SWEEP_FINISH (строка 422) и бравурный итог этого:
Transaction counters:
Oldest interesting 21013
Oldest active 11
Oldest snapshot 11
Next transaction 21015
3202 ms, 3840 read(s), 3238 write(s), 2216343 fetch(es), 409796 mark(s)
(дальше коннект от свипа отсоединяется от базы)
3) нулевое время вып-я для select count(*) from tfix (строка 534)
select count(*) from tfix

1 records fetched

0 ms, 4 fetch(es)
4) НЕнулевое время вып-я для select count(*) from ttmp (это GTT'шка) и ненулевые backout'ы:
+
 select count(*) from ttmp

1 records fetched

3833 ms, 3227 read(s), 2704 write(s), 2212906 fetch(es), 409677 mark(s)



Table Natural Index Update Insert Delete Backout Purge Expunge

***************************************************************************************************************

TTMP 200000


ВОПРОС.
Статистика по writes & fetches в сценарии_2 (строка 422) явно совпадает с тем, что было в сценарии_1 для tfix. Где в трейсе вывод работы SWEEP'a по таблице tfix ?

В аттаче - лог трейса для сценария 2.
hvlad
Дата: 12.08.2012 20:07:42
А ты сделай так, чтобы в tfix оставалась хотя бы 1 запись

PS вообще - забавный пример, спасибо :)
Таблоид
Дата: 12.08.2012 22:27:18
hvlad
А ты сделай так, чтобы в tfix оставалась хотя бы 1 запись
да, так всё получилось. Правда, таблица tfix была обработана почему-то "вместе" с rdb$formats:
<...>
2012-08-12T22:31:32.8120 (500:0212B258) SWEEP_PROGRESS

C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_4, SWEEPER:NONE, NONE, <internal>)

3751 ms, 3733 read(s), 2208 write(s), 2212918 fetch(es), 409675 mark(s)



Table Natural Index Update Insert Delete Backout Purge Expunge

***************************************************************************************************************

RDB$FORMATS 1

TFIX 1 200000



2012-08-12T22:31:33.4060 (500:0212B258) SWEEP_FINISH

C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_4, SWEEPER:NONE, NONE, <internal>)


Transaction counters:
Oldest interesting 21009
Oldest active 7
Oldest snapshot 7
Next transaction 21011
4367 ms, 3841 read(s), 3235 write(s), 2216007 fetch(es), 409679 mark(s)
hvlad
Дата: 12.08.2012 22:33:03
Таблоид
Правда, таблица tfix была обработана почему-то "вместе" с rdb$formats
И об этом сказано в трекере
Таблоид
Дата: 12.08.2012 23:34:48
Сломал я всё-таки что-то там... :-[
Может, оно не серьёзно (параметр конфига BugcheckAbort = 1), приведу протокол действий (трейс - в аттаче)

session #1
recreate table tfix1(id int primary key, s01 varchar(1000));
recreate table tfix2(id int primary key, s01 varchar(1000));
commit;
insert into tfix1 values(-1,'tfix1');
insert into tfix2 values(-2,'tfix2');
commit;

set transaction read committed;
set term ^;
execute block as
declare n int = 200000;
declare k int;
begin
while (n>0) do begin
--insert into ttmp(id,s01) values(:n, rpad('',1000,'x'));
insert into tfix1(id,s01) values(:n, rpad('',1000,'x'));
insert into tfix2(id,s01) values(:n, rpad('',1000,'x'));
n=n-1;
end
end^
set term ;^

session #2 -- запустил только после того, как в первом окне управление вернулось к подсказке isql
commit;
set transaction read committed;
set term ^;
execute block as
declare n int = 21000;
declare k int;
begin
while (n>0) do begin
in autonomous transaction do select 1 from rdb$database into :k;
n=n-1;
end
end^
set term ;^
commit;

session #1 -- дождался завершения EB и появления подсказки isql во втором окне
rollback;

Дальше запускаю трейс и снова в первом окне:

session #1
update tfix2 set s01='' where id<0; -- стартует sweep, в трейсе по нему появляется туча сообщений 

session #2
SQL> select count(*) from tfix1;

COUNT
============
1

После этого в трейсе еще что-то мелькает, затем всё заканчивается печалькой:
2012-08-12T23:28:24.4840 (1948:0223D1F4) EXECUTE_STATEMENT_FINISH
C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1940
(TRA_21011, CONCURRENCY | WAIT | READ_WRITE)

Statement 165:
-------------------------------------------------------------------------------
select count(*) from tfix1
1 records fetched
807 ms, 924 read(s), 367029 fetch(es), 79808 mark(s)

Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
TFIX1 1 26064

2012-08-12T23:28:24.5000 (1948:0223D1F4) CLOSE_CURSOR
C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_3, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1940

Statement 165:
-------------------------------------------------------------------------------
select count(*) from tfix1

connection lost to database
- и окно трейса завершает усилия.

В логе ФБ при этом:
BALAHA	Sun Aug 12 23:27:58 2012
Sweep is started by SWEEPER
Database "C:\1INSTALL\FIREBIRD\DATA\T1.FDB"
OIT 5, OAT 6, OST 6, Next 21009


BALAHA Sun Aug 12 23:28:23 2012
Database: C:\1INSTALL\FIREBIRD\DATA\T1.FDB
internal Firebird consistency check (record disappeared (186), file: vio.cpp line: 408)


BALAHA (Client) Sun Aug 12 23:28:32 2012
XNET error: Server shutdown detected

Таблоид
Дата: 12.08.2012 23:43:39
PS по предыдущему посту.
Воспроизводится устойчиво. Более того, когда ввожу во втором окне фатальное "select count(*) from tfix1", то сначала появляется мессага о критической рантайм-ошибке (см аттач), а в конечном итоге отваливается коннект именно этого окна_2 (а не только окна с трейсом).
Таблоид
Дата: 13.08.2012 00:34:43
И еще вопрос.

Если не полениться и сложить данные трейса по каждой таблице в секциях SWEEP_PROGRESS с тем, что выведено в итоге в секции SWEEP_FINISH, то арифметика... врёт.
Вот что у мну получилось в одном из примеров:
Имена таблиц в секциях трейса
Таблица(-ы)NAT_READSIDX_READSTIMEREADSWRITESFETCHESMARKS
RDB$PAGES, RDB$DATABASE79, 12239221712
RDB$FIELDS1240402550
RDB$INDEX_SEGMENTS590301230
RDB$INDICES510301070
RDB$RELATION_FIELDS34701107150
RDB$RELATIONS44000930
RDB$FORMATS203080
RDB$SECURITY_CLASSES10020230
RDB$TRIGGERS35000810
RDB$FUNCTIONS203080
RDB$FUNCTION_ARGUMENTS7020170
RDB$TRIGGER_MESSAGES36030760
RDB$USER_PRIVILEGES28020590
RDB$GENERATORS9030220
RDB$RELATION_CONSTRAINTS4010120
RDB$CHECK_CONSTRAINTS201080
RDB$CHARACTER_SETS520301100
RDB$COLLATIONS1480203030
RDB$ROLES101060
TFIX1, RDB$FORMATS1125572427332372911937612158
TFIX2, RDB$FORMATS1126668427537142911937612158
ИТОГО:544798597695358260711224318


А вот что выдал трейс в секции SWEEP_FINISH:
2012-08-12T23:58:45.1400 (540:0223B260) SWEEP_FINISH

C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_4, SWEEPER:NONE, NONE, <internal>)


Transaction counters:
Oldest interesting 21008
Oldest active 6
Oldest snapshot 6
Next transaction 21011
58087 ms, 8662 read(s), 7233 write(s), 5826999 fetch(es), 1224320 mark(s)
- как видим, были потрачены ресурсы на что-то еще. На что ?

В аттаче - трейс, по которому составлена вышеприведенная таблица и выполнено сопоставление.

ЗЫ. Интересно, как можно было потратить 2239 ms на RDB$PAGES+RDB$DATABASE, где в сумме было 79 натурал-чтений...
Таблоид
Дата: 13.08.2012 08:18:40
А вот еще нарылось. Оказывается, свип может и не стартовать, если один из коннектов заботливо делает select ... from ... for update with lock.

session #1
C:\1INSTALL\FIREBIRD\Data>isql localhost:C:\1INSTALL\FIREBIRD\Data\t1.fdb -n
Database: localhost:C:\1INSTALL\FIREBIRD\Data\t1.fdb
SQL> show database;
Database: localhost:C:\1INSTALL\FIREBIRD\Data\t1.fdb
Owner: SYSDBA
PAGE_SIZE 4096
Number of DB pages allocated = 196
Sweep interval = 20000
Forced Writes are OFF
Transaction - oldest = 3
Transaction - oldest active = 4
Transaction - oldest snapshot = 4
Transaction - Next = 6
ODS = 11.2
Default Character set: NONE

recreate table tfix1(id int primary key, s01 varchar(1000));
recreate table tfix2(id int primary key, s01 varchar(1000));
recreate table tfix3(id int primary key, s01 varchar(1000));
commit;
insert into tfix1 values(-1,'tfix1');
insert into tfix2 values(-2,'tfix2');
insert into tfix3 values(-2,'tfix2');
commit;

set transaction read committed;
set term ^;
execute block as
declare n int = 200000;
declare k int;
begin
while (n>0) do begin
insert into tfix1(id,s01) values(:n, rpad('',1000,'x'));
insert into tfix2(id,s01) values(:n, rpad('',1000,'x'));
insert into tfix3(id,s01) values(:n, rpad('',1000,'x'));
n=n-1;
end
end^
set term ;^
-- ждём пару минут, пока не завершится...
session #2
C:\1INSTALL\FIREBIRD\Data>isql localhost:C:\1INSTALL\FIREBIRD\Data\t1.fdb -n
Database: localhost:C:\1INSTALL\FIREBIRD\Data\t1.fdb
commit;
set transaction read committed;
set term ^;
execute block as
declare n int = 21000;
declare k int;
begin
while (n>0) do begin
in autonomous transaction do select 1 from rdb$database into :k;
n=n-1;
end
end^
set term ;^
commit;
--update tfix1 set id=id where id=-1;
set list on;
select * from tfix1 where id<0 for update with lock;
set list off;
-- ждём-с, пока не получим:
ID -1
S01 tfix1

Дальше запускаем трейс:
C:\1INSTALL\FIREBIRD\FB25HEAD>bin\fbtracemgr -sta -c zaudit.conf -se service_mgr|mtee trcx.txt
- и возвращаемся в окно_1

session #1
SQL> rollback;
SQL> show database;
Database: localhost:C:\1INSTALL\FIREBIRD\Data\t1.fdb
Owner: SYSDBA
PAGE_SIZE 4096
Number of DB pages allocated = 11810
Sweep interval = 20000
Forced Writes are OFF
Transaction - oldest = 5
Transaction - oldest active = 21009

Transaction - oldest snapshot = 6
Transaction - Next = 21011
ODS = 11.2
Default Character set: NONE
SQL> select 1 from rdb$database;

CONSTANT
============
1

session #3 // new
SQL> select 3 from rdb$database;

CONSTANT
============
3

SQL> commit;
SQL> select 3 from rdb$database;

CONSTANT
============
3

Никаких намёков на то, что стартует свип, в трейсе при этом нету (см аттач).

И только если вернуться в окно_2, которое удерживает блокировку строки таблицы tfix1, и выполнить там commit + еще раз тот же select for update, то начнётся sweep:

session #2
SQL> commit;
SQL> set list on;
SQL> select * from tfix1 where id<0 for update with lock; -- sweep стартует только теперь

ID -1
S01 tfix1

SQL> set list off;
Таблоид
Дата: 11.09.2012 09:25:07
В общем, пока этот топег совсем не утонул: всё вышеприведенное воспроизводится, устойчиво.
А посему - CORE-3921, CORE-3922

PS. 2 hvlad: помнишь, ты говорил мну недавно, что свип в ФБ 2.5 стартует при зазоре OST - OIT >= sweep_gap ? (и говорил именно про OST, а не OAT - т.к. в доке там вроде как что-то напутано было у Борманов).
Не получается. Свип стартует (если ему позволят :)) при OAT=21009, OIT=5. А значение OST при этом равно 6 (см предыдущий пост)
kdv
Дата: 11.09.2012 11:27:27
Таблоид
(и говорил именно про OST, а не OAT - т.к. в доке там вроде как что-то напутано было у Борманов).

раньше так и было. Потом в IB поменяли на OAT-OIT. Значит и в ФБ тоже поменяли. Хотя у меня везде для ФБ написано про OST-OIT, а Влад ничего не сказал. :-)