Logo MurCode
Firebird, InterBase Новое сообщение

Вставка в 100 тыс строк в таблицу с PK=id bigint: ужасный кошмар при buffers <= 195

Таблоид
Дата: 30.06.2012 16:00:23
hi all

Дано: WI-V2.5.2.26501 Firebird 2.5, SuperClassic, изменённые параметры конфига:
1) TempCacheLimit = 268435456
2) DummyPacketInterval = 120

В новой базе с FW=ON и PAGESIZE = 4096 создаю две таблички с 100 тыс строками каждая и единственным столбцом: id bigint.
Одна табличка заполняется монотонно возрастающими значениями, вторая получается из первой, выборкой с order by rand().
DDL:
SQL> recreate table src1(id bigint); commit;
SQL> recreate table src2(id bigint); commit;
SQL> set term ^;
SQL> execute block as
CON> declare n bigint = 100000;
CON> declare i bigint = 1;
CON> begin
CON>   while (i<=n) do insert into src1(id) values(:i) returning :i+1 into :i;
CON> end^
SQL> set term ;^
SQL> commit;
SQL>
SQL> insert into src2(id) select id from src1 order by rand();
SQL> commit;
SQL> select (select count(*) from src1) cnt1, (select count(*) from src2) cnt2 from rdb$database; commit;

        CNT1         CNT2
============ ============
      100000       100000

Далее выполняю подключения isql c разным кол-вом буферов и запускаю там один и тот же скрипт (file = 'run.sql'):
recreate table rcv1(id bigint primary key); commit;
recreate table rcv2(id bigint primary key); commit;
-- recreate table rcv2(id bigint); commit;
create index rcv2_id on rcv2(id); commit;
set stat on; 
insert into rcv1(id) select id from src1; commit; 
insert into rcv2(id) select id from src2; commit; 
set stat off;
(то есть, делаю заливку данных из табличек-источников в аналогичные им таблички-приёмники, но только на этих приемниках уже включены индексы первичного ключа)

Вижу удивительнейший результат: при указании числа буферов <= 195 заливка данных из src2 в rcv2 становится... невозможной!
Трейс показывает, что завершается insert-стейтмент, до *не* показывает commit_transaction. Управление в isql так и не возвращается в подсказку "SQL>", активность коннекта полностью затихает сразу после того, как в трейсе появится "EXECUTE_STATEMENT_FINISH" - см приаттаченный скрин.

Двукратный запрос к mon$io_stat (с commit'ом, ес-сно) подтверждает, что коннект больше ничего не делает:
+
MON$STAT_ID                     6
MON$STAT_GROUP                  1
MON$RECORD_SEQ_READS            200270
MON$RECORD_IDX_READS            405
MON$RECORD_INSERTS              200038
MON$RECORD_UPDATES              20
MON$RECORD_DELETES              28
MON$RECORD_BACKOUTS             8
MON$RECORD_PURGES               2
MON$RECORD_EXPUNGES             20

MON$STAT_ID                     7
MON$STAT_GROUP                  2
MON$RECORD_SEQ_READS            100000
MON$RECORD_IDX_READS            10
MON$RECORD_INSERTS              100000
MON$RECORD_UPDATES              0
MON$RECORD_DELETES              0
MON$RECORD_BACKOUTS             0
MON$RECORD_PURGES               0
MON$RECORD_EXPUNGES             2

MON$STAT_ID                     8
MON$STAT_GROUP                  3
MON$RECORD_SEQ_READS            100000
MON$RECORD_IDX_READS            0
MON$RECORD_INSERTS              100001
MON$RECORD_UPDATES              0
MON$RECORD_DELETES              0
MON$RECORD_BACKOUTS             0
MON$RECORD_PURGES               0
MON$RECORD_EXPUNGES             0
--------------------------------------
--- commit;
--------------------------------------

MON$STAT_ID                     6
MON$STAT_GROUP                  1
MON$RECORD_SEQ_READS            200270
MON$RECORD_IDX_READS            405
MON$RECORD_INSERTS              200038
MON$RECORD_UPDATES              20
MON$RECORD_DELETES              28
MON$RECORD_BACKOUTS             8
MON$RECORD_PURGES               2
MON$RECORD_EXPUNGES             20

MON$STAT_ID                     7
MON$STAT_GROUP                  2
MON$RECORD_SEQ_READS            100000
MON$RECORD_IDX_READS            10
MON$RECORD_INSERTS              100000
MON$RECORD_UPDATES              0
MON$RECORD_DELETES              0
MON$RECORD_BACKOUTS             0
MON$RECORD_PURGES               0
MON$RECORD_EXPUNGES             2

MON$STAT_ID                     8
MON$STAT_GROUP                  3
MON$RECORD_SEQ_READS            100000
MON$RECORD_IDX_READS            0
MON$RECORD_INSERTS              100001
MON$RECORD_UPDATES              0
MON$RECORD_DELETES              0
MON$RECORD_BACKOUTS             0
MON$RECORD_PURGES               0
MON$RECORD_EXPUNGES             0


netstat, однако, показывает, что какой-то обмен с сервером всё-таки ведётся:
+
netstat -a -n 5 | find "3050"|mtee /t netstat_log.txt
<... ждём 20-30 сек ...>
type netstat_log.txt
15:31:31.765   TCP    0.0.0.0:3050           0.0.0.0:0              LISTENING
15:31:31.765   TCP    127.0.0.1:2648         127.0.0.1:3050         ESTABLISHED
15:31:31.765   TCP    127.0.0.1:2649         127.0.0.1:3050         ESTABLISHED
15:31:31.765   TCP    127.0.0.1:3050         127.0.0.1:2648         ESTABLISHED
15:31:31.765   TCP    127.0.0.1:3050         127.0.0.1:2649         ESTABLISHED
15:31:31.765   TCP    0.0.0.0:3050           0.0.0.0:0              LISTENING
15:31:36.765   TCP    127.0.0.1:2648         127.0.0.1:3050         ESTABLISHED
15:31:36.765   TCP    127.0.0.1:2649         127.0.0.1:3050         ESTABLISHED
15:31:36.765   TCP    127.0.0.1:3050         127.0.0.1:2648         ESTABLISHED
15:31:36.765   TCP    127.0.0.1:3050         127.0.0.1:2649         ESTABLISHED
15:31:36.765   TCP    0.0.0.0:3050           0.0.0.0:0              LISTENING
15:31:36.765   TCP    127.0.0.1:2648         127.0.0.1:3050         ESTABLISHED
15:31:36.765   TCP    127.0.0.1:2649         127.0.0.1:3050         ESTABLISHED
15:31:36.765   TCP    127.0.0.1:3050         127.0.0.1:2648         ESTABLISHED
15:31:36.765   TCP    127.0.0.1:3050         127.0.0.1:2649         ESTABLISHED
15:31:46.765   TCP    0.0.0.0:3050           0.0.0.0:0              LISTENING
15:31:46.765   TCP    127.0.0.1:2648         127.0.0.1:3050         ESTABLISHED
15:31:46.765   TCP    127.0.0.1:2649         127.0.0.1:3050         ESTABLISHED
15:31:46.765   TCP    127.0.0.1:3050         127.0.0.1:2648         ESTABLISHED
15:31:46.765   TCP    127.0.0.1:3050         127.0.0.1:2649         ESTABLISHED

Данные трейса:
+
bin\fbtracemgr -sta -c zaudit.conf -se localhost/3050:service_mgr|mtee trc_ins_sort_rand_cache_195d.txt

Trace session ID 21 started
2012-06-30T13:39:34.0150 (504:0212C08C) TRACE_INIT

	SESSION_21  

	



2012-06-30T13:39:34.0150 (504:0212C08C) ATTACH_DATABASE

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684



2012-06-30T13:39:34.0150 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_135, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T13:39:39.1250 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_135, CONCURRENCY | WAIT | READ_WRITE)



-------------------------------------------------------------------------------

recreate table rcv1(id bigint primary key)

0 records fetched

      0 ms



2012-06-30T13:39:39.6250 (504:0212C08C) COMMIT_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_135, CONCURRENCY | WAIT | READ_WRITE)

    512 ms, 292 read(s), 51 write(s), 2277 fetch(es), 1551 mark(s)



2012-06-30T13:39:39.6400 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_136, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T13:39:39.6400 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_136, CONCURRENCY | WAIT | READ_WRITE)



-------------------------------------------------------------------------------

recreate table rcv2(id bigint primary key)

0 records fetched

      0 ms



2012-06-30T13:39:39.7030 (504:0212C08C) COMMIT_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_136, CONCURRENCY | WAIT | READ_WRITE)

     64 ms, 423 read(s), 50 write(s), 2387 fetch(es), 1688 mark(s)



2012-06-30T13:39:39.7030 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_137, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T13:39:45.0780 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_137, CONCURRENCY | WAIT | READ_WRITE)



Statement 159:

-------------------------------------------------------------------------------

insert into rcv1(id) select id from src1

0 records fetched

   5371 ms, 1239 read(s), 2003 write(s), 813202 fetch(es), 208256 mark(s)



Table                             Natural     Index    Update    Insert    Delete   Backout     Purge   Expunge

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

RDB$PAGES                                                             1                                        

SRC1                               100000                                                                      

RCV1                                                             100000                                        



2012-06-30T13:39:45.3900 (504:0212C08C) COMMIT_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_137, CONCURRENCY | WAIT | READ_WRITE)

    305 ms, 1 read(s), 91 write(s), 1 fetch(es), 1 mark(s)



2012-06-30T13:39:45.3900 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_138, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T13:41:46.6250 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_19, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1684

		(TRA_138, CONCURRENCY | WAIT | READ_WRITE)



Statement 160:

-------------------------------------------------------------------------------

insert into rcv2(id) select id from src2

0 records fetched

 121228 ms, 20668 read(s), 21990 write(s), 844789 fetch(es), 209072 mark(s)



Table                             Natural     Index    Update    Insert    Delete   Backout     Purge   Expunge

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

RDB$PAGES                                                             1                                        

SRC2                               100000                                                                      

RCV2                                                             100000                                        
                                       
-- дальше здесь не появится уже ничего... :'(

При задании кеша коннекта N>=196 и выше (isql -c N ...) - заливка в rcv2 всё-таки завершается коммитом, хотя и с огромным проигрышем по времени по сравнению с заливкой из src1 в rcv1:
+
Elapsed time= 5.71 sec -- insert into rcv1 select * from src1;
Elapsed time= 0.23 sec -- commit;
vs
Elapsed time= 117.57 sec -- insert into rcv2 select * from src2;
Elapsed time= 1.13 sec    -- commit;

При задании кеша = 256 ситуация улучшается, но ненамного:
Elapsed time= 4.64 sec
Elapsed time= 0.25 sec
vs
Elapsed time= 70.00 sec
Elapsed time= 1.35 sec

При кеше = 512...1024 соотношение заливки и коммита становится таким:
Elapsed time= 5.95 sec
Elapsed time= 0.57 sec
vs
Elapsed time= 8.98 sec
Elapsed time= 2.19 sec

И только при кеше=4096 время общее заливки и коммита становится почти одинаковым:
Elapsed time= 3.59 sec
Elapsed time= 3.62 sec
vs
Elapsed time= 6.70 sec
Elapsed time= 1.30 sec
ВОПРОС 1. Что происходит при buffers <= 195 ? почему активность коннекта становится нулевой после insert'a, почему не стартует commit ?
ВОПРОС 2. Откуда вообще такая дикая разница на значениях buffers <= 1024 ? Я понимаю, что при вставке random-чисел будут расщепления страниц индекса, но ведь и при добавлении монотонно возрастающих ID'шников крайняя правая страница индекса также должна всё время расщепляться. Там число расщеплений разве не одинаковое будет, по вышеприведенным вариантам ?
Таблоид
Дата: 30.06.2012 16:03:32
PS. Скриншот из ProcessExplorer'a для случая, когда коннект тихо прекращает свою деятельность, не начав commit, - не приаттачился почему-то к предыдущему посту. Выложил его сюда:
http://narod.ru/disk/54757860001.8b91cc4fb1c74263507deb6cc2533ac9/ins_sort_vs_rand_cache_up_to_195.jpg.html
Таблоид
Дата: 30.06.2012 16:39:35
методом тыка понял: проблема в FW = ON.
Как только снимаю forced writes, вставка 100 тыс rand-чисел в индексный bigint-столбец сразу же взлетает:
+ isql -c 196
C:\1INSTALL\FIREBIRD\Data>isql -n -c 196 localhost/3050:C:\1INSTALL\FIREBIRD\Data\T1.FDB
Database:  localhost/3050:C:\1INSTALL\FIREBIRD\Data\T1.FDB
SQL> in run.sql;
Current memory = 1640300
Delta memory = 12784
Max memory = 1772828
Elapsed time= 2.28 sec
Buffers = 196
Reads = 1241
Writes 2000
Fetches = 813323
Current memory = 1632928
Delta memory = -7372
Max memory = 1772828
Elapsed time= 0.00 sec
Buffers = 196
Reads = 1
Writes 92
Fetches = 1
Current memory = 1642408
Delta memory = 8776
Max memory = 1772828
Elapsed time= 3.22 sec
Buffers = 196
Reads = 20498
Writes 21788
Fetches = 844880
Current memory = 1635364
Delta memory = -7044
Max memory = 1772828
Elapsed time= 0.00 sec
Buffers = 196
Reads = 1
Writes 190
Fetches = 1
Трейс:
+
Trace session ID 29 started
2012-06-30T16:35:42.0460 (504:0212C08C) TRACE_INIT

	SESSION_29  

	



2012-06-30T16:35:42.0460 (504:0212C08C) ATTACH_DATABASE

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956



2012-06-30T16:35:42.0460 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_49, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T16:35:45.4060 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_49, CONCURRENCY | WAIT | READ_WRITE)



-------------------------------------------------------------------------------

recreate table rcv1(id bigint primary key)

0 records fetched

      0 ms



2012-06-30T16:35:45.4210 (504:0212C08C) COMMIT_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_49, CONCURRENCY | WAIT | READ_WRITE)

     15 ms, 292 read(s), 52 write(s), 2283 fetch(es), 1555 mark(s)



2012-06-30T16:35:45.4210 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_50, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T16:35:45.4210 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_50, CONCURRENCY | WAIT | READ_WRITE)



-------------------------------------------------------------------------------

recreate table rcv2(id bigint)

0 records fetched

      0 ms



2012-06-30T16:35:45.4210 (504:0212C08C) COMMIT_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_50, CONCURRENCY | WAIT | READ_WRITE)

      3 ms, 6 read(s), 32 write(s), 214 fetch(es), 30 mark(s)



2012-06-30T16:35:45.4210 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_51, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T16:35:45.4370 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_51, CONCURRENCY | WAIT | READ_WRITE)



-------------------------------------------------------------------------------

create index rcv2_id on rcv2(id)

0 records fetched

      0 ms



2012-06-30T16:35:45.4370 (504:0212C08C) COMMIT_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_51, CONCURRENCY | WAIT | READ_WRITE)

      1 ms, 1 read(s), 21 write(s), 80 fetch(es), 10 mark(s)



2012-06-30T16:35:45.4370 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_52, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T16:35:47.7180 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_52, CONCURRENCY | WAIT | READ_WRITE)



Statement 159:

-------------------------------------------------------------------------------

insert into rcv1(id) select id from src1

0 records fetched

   2276 ms, 1238 read(s), 2000 write(s), 813198 fetch(es), 208254 mark(s)



Table                             Natural     Index    Update    Insert    Delete   Backout     Purge   Expunge

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

RDB$PAGES                                                             1                                        

SRC1                               100000                                                                      

RCV1                                                             100000                                        



2012-06-30T16:35:47.7180 (504:0212C08C) COMMIT_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_52, CONCURRENCY | WAIT | READ_WRITE)

      1 ms, 1 read(s), 92 write(s), 1 fetch(es), 1 mark(s)



2012-06-30T16:35:47.7180 (504:0212C08C) START_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_53, CONCURRENCY | WAIT | READ_WRITE)



2012-06-30T16:35:50.9370 (504:0212C08C) EXECUTE_STATEMENT_FINISH

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_53, CONCURRENCY | WAIT | READ_WRITE)



Statement 160:

-------------------------------------------------------------------------------

insert into rcv2(id) select id from src2

0 records fetched

   3209 ms, 20472 read(s), 21788 write(s), 844793 fetch(es), 209074 mark(s)



Table                             Natural     Index    Update    Insert    Delete   Backout     Purge   Expunge

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

RDB$PAGES                                                             1                                        

SRC2                               100000                                                                      

RCV2                                                             100000                                        



2012-06-30T16:35:50.9370 (504:0212C08C) COMMIT_TRANSACTION

	C:\1INSTALL\FIREBIRD\DATA\T1.FDB (ATT_16, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

	C:\1INSTALL\FIREBIRD\FB25HEAD\bin\isql.exe:1956

		(TRA_53, CONCURRENCY | WAIT | READ_WRITE)

      2 ms, 1 read(s), 190 write(s), 1 fetch(es), 1 mark(s)
Таблоид
Дата: 30.06.2012 16:51:36
Вот, к примеру, результат при FW = ON / OFF для buffers=256.
buffersFWStatementelapsed time, msreadswritesfetchesmarks
256ONinsert into rcv2 select * from src2803831146912778844793209074
256ONcommit1638124911
256OFFinsert into rcv2 select * from src238481146712775844789209072
256OFFcommit1508124911

Данные в строках 1 и 3 одинаковы почти во всём, кроме графы elapsed time. В которой разница более чем в 20 раз. В трейсе, к сож-ю, это различие ничем не "объясняется". Опять от нас что-то тщательно скрывают :-)
Dimitry Sibiryakov
Дата: 30.06.2012 18:16:47

Таблоид
Опять от нас что-то тщательно скрывают :-)

У вас там опять жара, мозг усох? 20 раз это разница между скоростью работы твоего диска и
оперативной памяти. При FW=OFF данные на диск вообще не попадают, копясь в кэше ОСи.

А по поводу 195 буферов... Ты gstat запусти, посмотри размер индекса в страницах. Может,
тогда дойдёт...

Posted via ActualForum NNTP Server 1.5

Таблоид
Дата: 30.06.2012 20:14:51
Dimitry Sibiryakov
Таблоид
Опять от нас что-то тщательно скрывают :-)

У вас там опять жара, мозг усох? 20 раз это разница между скоростью работы твоего диска и
оперативной памяти. При FW=OFF данные на диск вообще не попадают, копясь в кэше ОСи.

А по поводу 195 буферов... Ты gstat запусти, посмотри размер индекса в страницах. Может,
тогда дойдёт...
не, погодь!
Когда я запускал коннект с buffers = 196, то пусть через 4 минуты, но commit всё-таки завершался. Как только число буферов стало меньше этого числа (пробовал сначала 192, затем эмпирически дошел до "волшебных" 195), то после завершения insert'a ВСЯ деятельность коннекта прекращалась. Вообще - ВСЯ, в том числе и дисковый IO.
Как так ?
Что касается gstat -r, то запустил, и чё ? в где тут видно "размер индекса в страницах" ?
+ gstat -r
bash-3.2$ gstat -r t1.fdb >gstat_r.txt
bash-3.2$ cat gstat_r.txt

Database "t1.fdb"
Database header page information:
        Flags                   0
        Checksum                12345
        Generation              20
        Page size               4096
        ODS version             11.2
        Oldest transaction      14
        Oldest active           15
        Oldest snapshot         15
        Next transaction        16
        Bumped transaction      1
        Sequence number         0
        Next attachment ID      3
        Implementation ID       24
        Shadow count            0
        Page buffers            0
        Next header page        0
        Database dialect        3
        Creation date           Jun 30, 2012 19:42:21
        Attributes              force write

    Variable header data:
        *END*


Database file sequence:
File t1.fdb is the only file

Analyzing database pages ...
RCV1 (132)
    Primary pointer page: 2653, Index root page: 2654
    Average record length: 9.34, total records: 100000
    Average version length: 0.00, total versions: 0, max versions: 0
    Data pages: 1235, data page slots: 1235, average fill: 52%
    Fill distribution:
         0 - 19% = 0
        20 - 39% = 1
        40 - 59% = 1234
        60 - 79% = 0
        80 - 99% = 0

    Index RDB$PRIMARY3 (0)
        Depth: 2, leaf buckets: 281, nodes: 100000
        Average data length: 6.23, total dup: 0, max dup: 0
        Fill distribution:
             0 - 19% = 1
            20 - 39% = 0
            40 - 59% = 0
            60 - 79% = 0
            80 - 99% = 280

RCV2 (133)
    Primary pointer page: 168, Index root page: 169
    Average record length: 9.34, total records: 100000
    Average version length: 0.00, total versions: 0, max versions: 0
    Data pages: 1235, data page slots: 1235, average fill: 52%
    Fill distribution:
         0 - 19% = 0
        20 - 39% = 1
        40 - 59% = 1234
        60 - 79% = 0
        80 - 99% = 0

    Index RDB$PRIMARY4 (0)
        Depth: 3, leaf buckets: 415, nodes: 100000
        Average data length: 6.24, total dup: 0, max dup: 0
        Fill distribution:
             0 - 19% = 5
            20 - 39% = 0
            40 - 59% = 143
            60 - 79% = 171
            80 - 99% = 96

ЗЫ. Сейчас проверил на линуховом серваке, LI-V2.5.2.26448, SuperClassic. Выполняет ОК для любого кол-ва буферов, в том числе и для 75. Разница во времени - в шесть раз, но также видны сильные различия по всем остальным параметрам: reads, writes, fetches, marks.
+ (trace)
Statement 164:
-------------------------------------------------------------------------------
insert into rcv1(id) select id from src1
0 records fetched
    710 ms, 1241 read(s), 2056 write(s), 813198 fetch(es), 208254 mark(s)

Table                             Natural     Index    Update    Insert    Delete   Backout     Purge   Expunge
***************************************************************************************************************
RDB$PAGES                                                             1                                       
SRC1                               100000                                                                     
RCV1                                                             100000                                       

2012-06-30T19:50:53.5000 (21607:0x2aaaab258af8) COMMIT_TRANSACTION
        /var/db/firebird/t1.fdb (ATT_6, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
        /opt/firebird/bin/isql:22242
                (TRA_62, CONCURRENCY | WAIT | READ_WRITE)
      0 ms, 1 read(s), 37 write(s), 1 fetch(es), 1 mark(s)

< ... >

Statement 165:
-------------------------------------------------------------------------------
insert into rcv2(id) select id from src2
0 records fetched
   4720 ms, 145948 read(s), 147719 write(s), 1179932 fetch(es), 310668 mark(s)

Table                             Natural     Index    Update    Insert    Delete   Backout     Purge   Expunge
***************************************************************************************************************
RDB$PAGES                                                             1                                       
SRC2                               100000                                                                     
RCV2                                                             100000                                       

2012-06-30T19:51:04.1940 (21607:0x2aaaab258af8) COMMIT_TRANSACTION
        /var/db/firebird/t1.fdb (ATT_6, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
        /opt/firebird/bin/isql:22242
                (TRA_63, CONCURRENCY | WAIT | READ_WRITE)
      0 ms, 1 read(s), 74 write(s), 1 fetch(es), 1 mark(s)

Что-то здесь не так!
Таблоид
Дата: 30.06.2012 20:19:58
Поправка: зачёркнутый текст в исх. скрипте НЕ был, я его после добавил, когда решил проверить, влияет ли как-то уникальность PK (см выше еще одну зачеркнутую строку; вторую я забыл вычеркнуть в исходном посте):
Таблоид
Далее выполняю подключения isql c разным кол-вом буферов и запускаю там один и тот же скрипт (file = 'run.sql'):
recreate table rcv1(id bigint primary key); commit;
recreate table rcv2(id bigint primary key); commit;
-- recreate table rcv2(id bigint); commit;
create index rcv2_id on rcv2(id); commit;
set stat on; 
insert into rcv1(id) select id from src1; commit; 
insert into rcv2(id) select id from src2; commit; 
set stat off;
Таблоид
Дата: 30.06.2012 20:35:44
пфф... бесовщина какая-то... сейчас проверил еще на одной виндовой тачке, WI-V2.5.2.26496, тоже SC, с минимальным числом буферов. Отработало ОК.
+
C:\MIX\firebird\fb25>isql localhost/3050:C:\MIX\firebird\fb25\T1.FDB -n -c 75
Database:  localhost/3050:C:\MIX\firebird\fb25\T1.FDB
SQL> in run;
Current memory = 1111600
Delta memory = 10944
Max memory = 1497836
Elapsed time= 2.25 sec
Buffers = 75
Reads = 1244
Writes 2056
Fetches = 813318

Current memory = 1104236
Delta memory = -7364
Max memory = 1497836
Elapsed time= 0.00 sec
Buffers = 75
Reads = 1
Writes 37
Fetches = 1
Current memory = 1113980
Delta memory = 9044
Max memory = 1497836
Elapsed time= 131.67 sec
Buffers = 75
Reads = 56144
Writes 57267
Fetches = 846926

Current memory = 1106608
Delta memory = -7372
Max memory = 1497836
Elapsed time= 0.50 sec
Buffers = 75
Reads = 1
Writes 73
Fetches = 1
Таблоид
Дата: 30.06.2012 20:56:11
Dimitry Sibiryakov
А по поводу 195 буферов... Ты gstat запусти, посмотри размер индекса в страницах. Может, тогда дойдёт...
Вот скрин из IBA по таблице RCV2, к которой был вопрос.
Что тут особенного ты видишь, из чего можно сделать вывод про "волшебность" числа буферов = 195 ?
Dimitry Sibiryakov
Дата: 30.06.2012 21:10:47

Таблоид
Что тут особенного ты видишь, из чего можно сделать вывод про "волшебность"
числа буферов = 195 ?

Я вижу глубину индекса = 3 и количество страниц в нём - 415. При количестве буферов 195, в
кэше перестаёт помещаться даже второй его уровень и начинается дикое вытеснение. Скорее всего.

Почему вся активность прекращается - понятия не имею, тут тебе fb_lock_print в руки.

Posted via ActualForum NNTP Server 1.5