Гость
Войти | Профиль | Очистить
Целевая тема:
Создать новую тему:
Автор:
Действия ...
Форумы / Firebird, InterBase [игнор отключен] [закрыт для гостей] / Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ? / 14 сообщений из 14, страница 1 из 1
08.01.2014, 21:28:16
    #38519877
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
hi all.

Вот есть такой скриптик, заполняющий несколько маленьких табличек:
 
Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
set autoddl on;
commit;
recreate sequence gmain;
recreate sequence gdetl;
recreate table tdetl(id bigint primary key using index tdetl_pk_idx, pid bigint, s01 varchar(36), s02 varchar(36));
recreate table tmain(id bigint primary key using index tmain_pk_idx, s01 varchar(36), s02 varchar(36));
recreate table tlog( gmain bigint, gdetl bigint, dts_before timestamp, dts_after timestamp, elapsed_ms computed by(datediff(millisecond from dts_before to dts_after)) );

alter table tdetl add constraint tdetl_fk foreign key(pid) references tmain using index tdetl_fk_idx;
create index tmain_s01 on tmain(s01);
create index tmain_s02 on tmain(s02);
create index tdetl_s01 on tdetl(s01);
create index tdetl_s02 on tdetl(s02);
commit;
set transaction read write read committed record_version no wait;
set term ^;
execute block returns(msg varchar(100)) as
  declare n_main int = 2000000;
  declare n_detl int = 100; -- child records in tdetl per each parent row in tmain
  declare i int;
  declare j int;
  declare verbose_step int=100;
  declare tx timestamp;
begin
  tx=cast('now' as timestamp);
  while(n_main>0) do begin
    insert into tmain(id, s01, s02)
    values( gen_id(gmain,1), uuid_to_char(gen_uuid()), uuid_to_char(gen_uuid()) );

    i=n_detl;
    while (i>0) do
      insert into tdetl(id, s01,s02)
      values( gen_id(gdetl,1), uuid_to_char(gen_uuid()), uuid_to_char(gen_uuid()) )
      returning :i-1 into i;
    n_main = n_main-1;
    if ( mod(n_main, verbose_step)= 0) then begin
      msg=left(right(cast('now' as timestamp),13),8)||': inserted '||gen_id(gmain,0)||' rows in tmain, '||gen_id(gdetl,0)||' rows in tdetl';
      suspend;
      in autonomous transaction do
        insert into tlog(gmain, gdetl, dts_before, dts_after)
        values( gen_id(gmain,0), gen_id(gdetl,0), :tx, cast('now' as timestamp) );

      tx=cast('now' as timestamp);
    end
  end
end
^set term ;^
commit;

Чтобы видеть в том же окне, где запущен isql, "прогресс" его работы, в скрипте есть вот это:
Код: sql
1.
2.
3.
4.
5.
    if ( mod(n_main, verbose_step)= 0) then begin
      msg=left(right(cast('now' as timestamp),13),8)||': inserted '||gen_id(gmain,0)||' rows in tmain, '||gen_id(gdetl,0)||' rows in tdetl';
      suspend;
      . . .
    end


Но вот гляжу я на isql-окошко, и вижу, что данные там появляются "пачками" примерно по 8 Кб (логирование времени вывода строк с помощью supertee показывает это наглядно):
Код: plaintext
1.
2.
3.
4.
Wed Jan  8  20:56:42  2014: 20:55:40: inserted 19900 rows in tmain, 1990000 rows in tdetl
Wed Jan  8 20:56:42 2014: 20:55:40: inserted 20000 rows in tmain, 2000000 rows in tdetl
. . . дальше еще 100500 строк с тем же временем в первой графе . . .
Wed Jan  8 20:56:42 2014: 20:56:40: inserted 29400 rows in tmain, 2940000 rows in tdetl
Wed Jan  8  20:56:42  2014: 20:56:41: inserted 29500 rows in tmain, 2950000 rows in tdetl
Несколько копипастов строк, относящихся к одному и тому же времени, в отдельные файлы, показали, что суммарный их размер действительно близок к TcpRemoteBufferSize = 8192 (у мну он дефолтный).

Но! Через некоторое время вывод в isql заткнулся на 10 минут. После чего он выплюнул сразу ~40 Кб строк за один присест (см аттач). Возможно, что на самом деле это было 5 пакетов по 8192 байта, не знаю. Но выглядит всё как-то странно.

Это чем/как отрегулировать можно, чтобы suspend строки приводил к немедленному её посылу клиенту ?
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
08.01.2014, 21:30:50
    #38519884
Dimitry Sibiryakov
Dimitry Sibiryakov
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
select for update
Posted via ActualForum NNTP Server 1.5
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
08.01.2014, 21:35:13
    #38519890
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
Dimitry Sibiryakovselect for updateне понял я чё-то... в вышеприведенном скрипте - что именно "селект фор апдейт" ?
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
08.01.2014, 21:37:18
    #38519892
Dimitry Sibiryakov
Dimitry Sibiryakov
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
Твою процедуру. For update отключает буферизацию результата.
Posted via ActualForum NNTP Server 1.5
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
08.01.2014, 21:40:50
    #38519897
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
Dimitry SibiryakovТвою процедуру. For update отключает буферизацию результата.там execute block; ты предлагаешь затолкать его содержимое в отдельную ХП и выполнить селект из неё - правильно я понимаю ?
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
08.01.2014, 23:57:00
    #38519984
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
Dimitry SibiryakovFor update отключает буферизацию результата.Помогло, спс.
Затыки теперь обусловлены только работой записи в базу (т.е. время выдачи строки на консоль совпадает до +/- 1 сек со временем, которое включено в строку возврата из процедуры). Хотя fw = OFF - т.е. ФБ вроде бы не должен ждать ответа "записано".
 
iostat -t -d 2 -m sda4
Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
01/08/2014 11:55:17 PM
Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sda4           5522.50         0.00        26.53          0         53

01/08/2014 11:55:19 PM
Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sda4           4576.50         0.00        22.20          0         44

01/08/2014 11:55:21 PM
Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sda4           3271.50         0.00        15.64          0         31

01/08/2014 11:55:23 PM
Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sda4           2798.50         0.00        12.89          0         25

01/08/2014 11:55:25 PM
Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sda4           2866.00         0.00        13.31          0         26

01/08/2014 11:55:27 PM
Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sda4           3083.50         0.00        14.36          0         28

01/08/2014 11:55:29 PM
Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sda4           2844.00         0.00        13.18          0         26
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
09.01.2014, 00:21:14
    #38520001
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
"Забавно", но когда в базу таким вот макаром пишут два isql'я и возникает очередной затык, то невозможно запросить мониторинг: он тоже висит в раздумье.
В одну из таких "музыкальных пауз", длившихся несколько минут, были сделаны снимки бактрассы процесса ФБ и лок-таблицы базы (повторялись с интервалом 10 сек, пока "не попустило").
2 dimitr: выслал тебе в мыло, если не трудно - погляди, плз.

Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
top - 00:04:19 up 7 days,  6:52,  7 users,  load average: 7.26, 5.74, 4.79
Tasks: 188 total,   1 running, 182 sleeping,   4 stopped,   1 zombie
Cpu0  : 17.6%us,  0.8%sy,  0.0%ni, 40.4%id, 40.6%wa,  0.0%hi,  0.6%si,  0.0%st
Cpu1  : 66.8%us,  1.7%sy,  0.0%ni, 31.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  : 98.7%us,  1.0%sy,  0.0%ni,  0.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu4  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu5  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu6  :  0.0%us,  0.5%sy,  0.0%ni, 76.3%id, 23.2%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu7  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu8  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu9  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu10 :  0.3%us,  0.3%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu11 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  32988060k total, 32757692k used,   230368k free,   175112k buffers
Swap: 32767996k total,    57880k used, 32710116k free, 28392188k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
10380 firebird  20   0 3164m 2.4g 8348 S 198.7  7.5 369:48.47 /opt/fb30/bin/firebird
 1639 root      20   0     0    0    0 D  1.0  0.0  18:32.60 [flush-8:0]
   83 root      20   0     0    0    0 S  0.3  0.0   1:43.35 [kworker/9:1]
  447 root      20   0     0    0    0 D  0.3  0.0  21:12.48 [jbd2/sda4-8]
21059 root      20   0 15084 1232  880 R  0.3  0.0   0:00.02 top
    1 root      20   0 19408  972  792 S  0.0  0.0   0:03.53 /sbin/init
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
09.01.2014, 07:30:00
    #38520149
dimitr
dimitr
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
Таблоид,

во всех дампах вижу параллельный сброс кеша на диск в результате коммита автономной транзакции в обоих isql-ях. А мониторинг ждет окончания этого безобразия.
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
09.01.2014, 08:46:41
    #38520162
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
dimitrТаблоид,

во всех дампах вижу параллельный сброс кеша на диск в результате коммита автономной транзакции в обоих isql-ях. А мониторинг ждет окончания этого безобразия.в автономной транзакции всего 1 инсерт:
Код: sql
1.
2.
3.
in autonomous transaction do
        insert into tlog(gmain, gdetl, dts_before, dts_after)
        values( gen_id(gmain,0), gen_id(gdetl,0), :tx, cast('now' as timestamp) );


Значения maxunflushed у меня в конфиге не менялись:

Код: plaintext
1.
2.
3.
$ grep -i maxunflushed firebird.conf
#MaxUnflushedWrites = 100
#MaxUnflushedWriteTime = 5

- но для non-win32 платформы про эти параметры говорится, что они = "-1 (Disabled)".
Что это означает ("Disabled") - линух сам решает, когда сбрасывать кеш ?
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
09.01.2014, 08:54:49
    #38520165
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
ЗЫ. я правильно понимать, что если выкинуть вообще из скрипта автономную транзакцию и довольствоваться только выводом msg по саспенду, то всё должно идти гораздо быстрее ?
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
09.01.2014, 08:55:39
    #38520166
dimitr
dimitr
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
Таблоид,

да, система сама решает
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
09.01.2014, 12:25:15
    #38520343
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
dimitrда, система сама решаета еще вопрос: если 300 коннектов намолотили DML, так что writes стало >> 100, но не коммитят их, а 301-й коннект взял да и выполнил холостой commit - что тогда, будет ли ФБ выдавать команду операционке записать на диск изменения этих 300 коннектов ?
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
09.01.2014, 12:44:08
    #38520360
dimitr
dimitr
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
Таблоид,

не будет, насколько я помню
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
09.01.2014, 13:57:09
    #38520436
Таблоид
Таблоид
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ?
Автономок нет, а затыки всё равно идут
Например, вот, трёхминутный период "молчания":

Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
13:46:39: inserted 1371900 rows in tmain, 137190000 rows in tdetl
13:46:40: inserted 1372000 rows in tmain, 137200000 rows in tdetl
13:46:41: inserted 1372100 rows in tmain, 137210000 rows in tdetl
13:46:42: inserted 1372200 rows in tmain, 137220000 rows in tdetl
13:46:43: inserted 1372300 rows in tmain, 137230000 rows in tdetl
 13:46:44 : inserted 1372400 rows in tmain, 137240000 rows in tdetl
 13:49:31 : inserted 1372500 rows in tmain, 137250000 rows in tdetl
13:49:32: inserted 1372600 rows in tmain, 137260000 rows in tdetl
13:49:33: inserted 1372700 rows in tmain, 137270000 rows in tdetl
13:49:34: inserted 1372800 rows in tmain, 137280000 rows in tdetl
13:49:35: inserted 1372900 rows in tmain, 137290000 rows in tdetl

При этом top для процессов, которые (как мне показалось) отвечают за IO, показывает практически одно и тоже:

Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
top -b -d 1 -p$(pgrep jbd2/sda4),$(pgrep flush-8:0),$(pgrep irqbalce),$(pgrep kworker/8:1) 

top -  13:48:37  up 7 days, 20:36,  8 users,  load average: 5.31, 5.22, 5.32
Tasks:   4 total,   0 running,   4 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.0%us,  0.0%sy,  0.0%ni, 50.0%id, 50.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  0.0%us,  1.0%sy,  0.0%ni, 49.5%id, 49.5%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu4  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu5  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu6  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu7  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu8  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu9  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu10 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu11 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  32988060k total, 32761368k used,   226692k free,     9508k buffers
Swap: 32767996k total,    97384k used, 32670612k free, 28614616k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 1639 root      20   0     0    0    0 D  1.0  0.0  26:48.09 [flush-8:0]
  447 root      20   0     0    0    0 D  0.0  0.0  27:03.58 [jbd2/sda4-8]
 1986 root      20   0 10864  520  404 S  0.0  0.0   0:53.94 irqbalance
   86 root      20   0     0    0    0 S  0.0  0.0   1:06.59 [kworker/8:1]

Утешает пока одно: надо дождаться "2'000'000 rows in tmain", после чего можно будет посмотреть в базу и вытащить из лога "пиковые флуктуации" длительности записи.
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
Форумы / Firebird, InterBase [игнор отключен] [закрыт для гостей] / Отсылка буфера строк клиенту: время от suspend до показа в окне isql = 10 минут. Why ? / 14 сообщений из 14, страница 1 из 1
Найденые пользователи ...
Разблокировать пользователей ...
Читали тему (0):
Читали форум (0):
Пользователи онлайн (0):
Польз. соглашение  
Полит. конфиден.  
созд. / загр.: 405ms
Закрыть
start [/forum/topic.php?fid=40&tablet=1&tid=1564001]:
 0ms
get settings:
 8ms
get forum list:
 14ms
check forum access:
 4ms
check topic access:
 4ms
track hit:
 87ms
get topic data:
 9ms
get forum data:
 2ms
get page messages:
 51ms
get tp. blocked users:
 1ms
others: 225ms
total:  405ms
x
x
Закрыть


Просмотр
0 / 0
Close
Debug Console [Select Text]