В общем, докладаю.
Затыки идут
не только от ожидания сброса файлового кеша на диск (как я понимаю, linux-процессами flush и jdb2).
Они возникают при любом MaxUnfluhedWrites, при передаче данных из кеша ФБ в кеш операционки:
так показывает iotop .
Логи iostat'a и vmstat'a для периодов, когда шли затыки, часто не содержат никаких "особых" значений, указывающих на повышенный IO, поэтому они тут не приводятся.
Тест был такой (для maxUnflushedWrites=10):
1. в окнах 1..3 запускаются линух-мониторные утилиты с логированием вывода в соотв. файлы:
iostat, vmstat, iotop
1.
2.
3.
4.
5.
6.
7.
8.
supertee -tn iostat_x_huge_fil_muf_010_$(date +'%Y%m%d_%H%M').log iostat -x -t 1
supertee -tn vmstat_huge_fil_muf_010_$(date +'%Y%m%d_%H%M').log vmstat -t 1
// ключик -o логирует только те потоки процессов, которые создают сейчас IO
// (вместо вывода всех потоков вообще, что по дефолту);
// ключик -t заставляет выводить штамп времени;
// ключик -d 1 задаёт паузу в выводе = 1 сек;
supertee -tn iotop_o_huge_fil_muf_010_$(date +'%Y%m%d_%H%M').log iotop -o -t -d 1 -b
2. В окне 4 запускается скрипт
huge_fil_at.sh (
'_at' = 'autonomous transaction': добавляет пачки записей в автономной транзакции), вызывающий isql и натравливающий на него .sql с заполнением данными. Особенность .sh в том, что по окончании работы isql он будет убивать мониторные процессы, запущенные в окнах 1...3.
А сам же isql прекратится по эксепшену, как только время, затраченное на ввод 1'000 записей в TMAIN и 100'000 записей в TDETL, превысит порог = 15'000 ms (переменная 'MS_FOR_STOP'):
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
$ cat huge_fil_at.sh
rm -f huge_noext_at.fdb
cp huge_noext.fd0 huge_noext_at.fdb
chown -R firebird:firebird huge_noext_at.fdb
supertee -tn isql_huge_fil_$(date +'%Y%m%d_%H%M').log \
/opt/fb30trnk/bin/isql localhost/3333:/var/db/fb30/huge_noext_at.fdb \
-pag 0 -i huge_fil_at.sql
killall -9 iostat
killall -9 vmstat
killall -9 iotop
Ну, и собственно .sql-скрипт:
huge_fil_at.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.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.
73.
74.
75.
76.
77.
78.
79.
80.
81.
82.
83.
84.
85.
86.
87.
88.
89.
90.
91.
92.
93.
94.
95.
96.
97.
98.
99.
100.
101.
102.
103.
104.
105.
106.
107.
108.
109.
110.
111.
112.
113.
114.
115.
116.
117.
118.
119.
120.
121.
122.
123.
124.
125.
126.
127.
128.
129.
130.
131.
132.
133.
134.
135.
136.
137.
138.
139.
140.
141.
142.
143.
144.
145.
-- huge_fil_at.sql
set autoddl on;
show version;
commit;
set term ^;create or alter procedure sp_huge_ext as begin end^set term ;^
commit;
create exception ex_too_long_time 'too long insert detected, DML was cancelled';
commit;
recreate table tdetl(id int); commit;
recreate table tmain(id int); commit;
recreate table tlog(id int); commit;
recreate sequence gmain;
recreate sequence gdetl;
recreate sequence glog;
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( id int primary key using index tlog_pk_idx,
gmain bigint,
gdetl bigint,
dt_cur timestamp,
ms_cur int,
dt_max timestamp,
ms_max int,
dt_min timestamp,
ms_min int,
tx int
);
commit;
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 term ^;
create or alter procedure sp_huge_ext returns(msg varchar(100)) as
declare MS_FOR_STOP int = 15000 ;
declare n_main int = 2000000;
declare n_detl int = 100; -- child records in tdetl per each parent row in tmain
declare n_insa int = 1000; -- number of rows inserted int tmain in each auton trn
declare verbose_step int=100; -- step of gdetl for detailed log
declare v_id bigint;
declare i int;
declare j int;
declare k int;
declare tx timestamp;
declare tc timestamp;
declare ms_cur int;
declare ms_min int = 999999999;
declare ms_max int = -1;
declare v_dt_min timestamp;
declare v_dt_max timestamp;
declare v_log_id int = 0;
declare v_last_id int = 0;
begin
tx=cast('now' as timestamp);
while(n_main>0) do begin
in autonomous transaction do
begin
k=n_insa / verbose_step;
while ( k > 0) do begin
msg='';
j=verbose_step;
while(j>0) do begin
n_main = n_main-1; -- main counter
insert into tmain(id, s01, s02)
values( gen_id(gmain,1), uuid_to_char(gen_uuid()), uuid_to_char(gen_uuid()) )
returning id into v_id;
i=n_detl;
while (i>0) do
insert into tdetl(id, pid, s01,s02)
values( gen_id(gdetl,1), :v_id, uuid_to_char(gen_uuid()), uuid_to_char(gen_uuid()) )
returning :i-1 into i;
j=j-1;
end -- j=verbose_step downto 1
tc=cast('now' as timestamp);
ms_cur=datediff(millisecond from :tx to :tc);
if ( ms_min > ms_cur ) then begin
ms_min=ms_cur;
v_dt_min = tc;
end
if ( ms_max < ms_cur ) then begin
ms_max=ms_cur;
v_dt_max=tc;
end
insert into tlog(
id,
gmain, gdetl,
dt_cur, ms_cur,
dt_max, ms_max,
dt_min, ms_min,
tx)
values( gen_id(glog, 1),
gen_id(gmain,0), gen_id(gdetl,0),
:tc, :ms_cur,
:v_dt_max, :ms_max,
:v_dt_min, :ms_min,
current_transaction
)
returning id into v_log_id;
if (ms_cur > MS_FOR_STOP ) then k=-1 ; -- ==> exit immediatelly with exception
tx=cast('now' as timestamp);
k=k-1;
end -- while k>0
end -- in autonomous tran
for
select left(right(dt_cur,13),8)
||': gdetl='||right(cast(1000000000+gdetl as varchar(10)),9)
||' min_ms='||ms_min||' at '||left(right(dt_min,13),8)
||' cur_ms='||ms_cur
||' max_ms='||ms_max||' at '||left(right(dt_max,13),8)
--||' tx='||tx
from tlog
where id>:v_last_id
into :msg
do suspend;
if (k <= -1) then
exception ex_too_long_time ;
v_last_id = v_log_id;
end -- while (n_main>0)
end
^set term ;^
commit;
set transaction read write read committed record_version no wait;
select * from sp_huge_ext for update;
commit;
В итоге всех прогонов (при ЛЮБОМ maxUnflushedWrites), всё заканчивалось примерно вот так:
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
08:43:47: gdetl=005180000 min_ms=476 at 08:36:12 cur_ms=728 max_ms=12216 at 08:42:12
08:43:47: gdetl=005190000 min_ms=476 at 08:36:12 cur_ms=725 max_ms=12216 at 08:42:12
08:43:48: gdetl=005200000 min_ms=476 at 08:36:12 cur_ms=731 max_ms=12216 at 08:42:12
08:44:04: gdetl=005210000 min_ms=476 at 08:36:12 cur_ms=16045 max_ms=16045 at 08:44:04
Statement failed, SQLSTATE = 42000
exception 1
-EX_TOO_LONG_TIME
-too long insert detected, DML was cancelled
-At procedure 'SP_HUGE_EXT' line: 96, col: 7
After line 144 in file huge_fil_at.sql
Как видим, последние два затыка были = 12 и 16 сек.
Для затыка-1 лог iotop'a:
iotop -o, 08:42:00...08:42:12
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.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.
73.
74.
75.
76.
77.
78.
79.
80.
81.
82.
08:41:58 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:41:58 2014: 08:41:58 26261 be/4 firebird 0.00 B/s 3.70 M/s 0.00 % 0.00 % firebird
08:41:58 2014: 08:41:58 26263 be/4 firebird 0.00 B/s 5.12 M/s 0.00 % 0.00 % firebird
08:41:59 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 19.68 K/s
08:41:59 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:41:59 2014: 08:41:59 447 be/3 root 0.00 B/s 3.94 K/s 0.00 % 0.02 % [jbd2/sda4-8]
08:41:59 2014: 08:41:59 26261 be/4 firebird 0.00 B/s 3.45 M/s 0.00 % 0.00 % firebird
08:41:59 2014: 08:41:59 26263 be/4 firebird 0.00 B/s 4.06 M/s 0.00 % 0.00 % firebird
08:42:00 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 80.59 M/s
08:42:00 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:00 2014: 08:42:00 26261 be/4 firebird 0.00 B/s 3.32 M/s 0.00 % 6.65 % firebird
08:42:00 2014: 08:42:00 26263 be/4 firebird 0.00 B/s 2.98 M/s 0.00 % 0.00 % firebird
08:42:01 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 55.60 M/s
08:42:01 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:01 2014: 08:42:01 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 95.57 % firebird
08:42:01 2014: 08:42:01 26266 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iostat_x
08:42:02 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 29.79 M/s
08:42:02 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:02 2014: 08:42:02 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 98.00 % firebird
08:42:02 2014: 08:42:02 26281 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iotop_o_
08:42:03 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 30.37 M/s
08:42:03 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:03 2014: 08:42:03 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 97.58 % firebird
08:42:04 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 31.18 M/s
08:42:04 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:04 2014: 08:42:04 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 97.96 % firebird
08:42:04 2014: 08:42:04 447 be/3 root 0.00 B/s 11.82 K/s 0.00 % 5.77 % [jbd2/sda4-8]
08:42:04 2014: 08:42:04 26266 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iostat_x
08:42:04 2014: 08:42:04 26281 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iotop_o_
08:42:05 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 32.35 M/s
08:42:05 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:05 2014: 08:42:05 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 97.64 % firebird
08:42:05 2014: 08:42:05 26266 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iostat_x
08:42:05 2014: 08:42:05 26281 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iotop_o_
08:42:06 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 28.74 M/s
08:42:06 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:06 2014: 08:42:06 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 98.24 % firebird
08:42:06 2014: 08:42:06 26266 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iostat_x
08:42:07 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 29.20 M/s
08:42:07 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:07 2014: 08:42:07 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 97.75 % firebird
08:42:08 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 69.09 M/s
08:42:08 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:08 2014: 08:42:08 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 70.70 % firebird
08:42:08 2014: 08:42:08 1639 be/4 root 0.00 B/s 0.00 B/s 0.00 % 33.96 % [flush-8:0]
08:42:09 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 28.05 M/s
08:42:09 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:09 2014: 08:42:09 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.99 % firebird
08:42:09 2014: 08:42:09 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 96.08 % [jbd2/sda4-8]
08:42:10 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 27.42 M/s
08:42:10 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:10 2014: 08:42:10 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.10 % [jbd2/sda4-8]
08:42:10 2014: 08:42:10 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 98.48 % firebird
08:42:11 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 29.84 M/s
08:42:11 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:11 2014: 08:42:11 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.78 % [jbd2/sda4-8]
08:42:11 2014: 08:42:11 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.36 % firebird
08:42:11 2014: 08:42:11 1380 be/3 root 0.00 B/s 3.94 K/s 0.00 % 1.02 % [jbd2/sdb1-8]
08:42:11 2014: 08:42:11 26281 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iotop_o_hu
08:42:12 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 4.71 M/s
08:42:12 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:12 2014: 08:42:12 447 be/3 root 0.00 B/s 19.70 K/s 0.00 % 19.26 % [jbd2/sda4-8]
08:42:12 2014: 08:42:12 26261 be/4 firebird 0.00 B/s 4.18 M/s 0.00 % 18.08 % firebird
08:42:12 2014: 08:42:12 26257 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn isql_huge_
08:42:12 2014: 08:42:12 26263 be/4 firebird 0.00 B/s 78.30 M/s 0.00 % 0.00 % firebird
08:42:13 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 34.91 K/s
08:42:13 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:13 2014: 08:42:13 447 be/3 root 0.00 B/s 11.64 K/s 0.00 % 0.01 % [jbd2/sda4-8]
08:42:13 2014: 08:42:13 2654 be/4 oracle 0.00 B/s 3.88 K/s 0.00 % 0.00 % java -Xmx128M -XX:MaxPe
08:42:13 2014: core/12.1.0.3.0/sysman/jlib/emagentSDK-intg.jar:/u01/app/oracle/oms/core/12.1.0.3.0/sysman/j
08:42:13 2014: 08:42:13 23573 be/4 oracle 0.00 B/s 0.00 B/s 0.00 % 0.00 % java -Xmx128M -XX:MaxPe
08:42:13 2014: core/12.1.0.3.0/sysman/jlib/emagentSDK-intg.jar:/u01/app/oracle/oms/core/12.1.0.3.0/sysman/j
08:42:13 2014: 08:42:13 26261 be/4 firebird 0.00 B/s 4.75 M/s 0.00 % 0.00 % firebird
08:42:13 2014: 08:42:13 26263 be/4 firebird 0.00 B/s 77.70 M/s 0.00 % 0.00 % firebird
08:42:13 2014: 08:42:13 26266 be/4 root 0.00 B/s 3.88 K/s 0.00 % 0.00 % supertee -tn iostat_x_h
08:42:13 2014: 08:42:13 2961 be/4 root 0.00 B/s 7.76 K/s 0.00 % 0.00 % ../jre/bin/java -classp
08:42:14 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 0.00 B/s
08:42:14 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:42:14 2014: 08:42:14 26261 be/4 firebird 0.00 B/s 4.38 M/s 0.00 % 0.00 % firebird
08:42:14 2014: 08:42:14 26263 be/4 firebird 0.00 B/s 61.16 M/s 0.00 % 0.00 % firebird
08:42:14 2014: 08:42:14 26281 be/4 root 0.00 B/s 3.92 K/s 0.00 % 0.00 % supertee -tn iotop_o_hu
08:42:14 2014: 08:42:14 2639 be/4 oracle 0.00 B/s 3.92 K/s 0.00 % 0.00 % java -Xmx128M -XX:MaxPe
08:42:14 2014: core/12.1.0.3.0/sysman/jlib/emagentSDK-intg.jar:/u01/app/oracle/oms/core/12.1.0.3.0/sysman/j
Для затыка-2 лог iotop'a:
iotop -o, 08:43:48...08:44:04
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.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.
73.
74.
75.
76.
77.
78.
79.
80.
81.
82.
83.
84.
85.
86.
87.
88.
89.
90.
91.
92.
93.
94.
08:43:45 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:45 2014: 08:43:45 26261 be/4 firebird 0.00 B/s 3.71 M/s 0.00 % 0.00 % firebird
08:43:45 2014: 08:43:45 26263 be/4 firebird 0.00 B/s 8.50 M/s 0.00 % 0.00 % firebird
08:43:45 2014: 08:43:45 26281 be/4 root 0.00 B/s 3.93 K/s 0.00 % 0.00 % supertee -tn iotop
08:43:46 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 23.61 K/s
08:43:46 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:46 2014: 08:43:46 26261 be/4 firebird 0.00 B/s 3.70 M/s 0.00 % 0.00 % firebird
08:43:46 2014: 08:43:46 26263 be/4 firebird 0.00 B/s 6.97 M/s 0.00 % 0.00 % firebird
08:43:46 2014: 08:43:46 26266 be/4 root 0.00 B/s 3.93 K/s 0.00 % 0.00 % supertee -tn iosta
08:43:47 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 27.55 K/s
08:43:47 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:47 2014: 08:43:47 447 be/3 root 0.00 B/s 3.94 K/s 0.00 % 0.01 % [jbd2/sda4-8]
08:43:47 2014: 08:43:47 26261 be/4 firebird 0.00 B/s 3.46 M/s 0.00 % 0.00 % firebird
08:43:47 2014: 08:43:47 26263 be/4 firebird 0.00 B/s 6.05 M/s 0.00 % 0.00 % firebird
08:43:47 2014: 08:43:47 26266 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iosta
08:43:48 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 0.00 B/s
08:43:48 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:48 2014: 08:43:48 26261 be/4 firebird 0.00 B/s 3.70 M/s 0.00 % 0.00 % firebird
08:43:48 2014: 08:43:48 26263 be/4 firebird 0.00 B/s 4.95 M/s 0.00 % 0.00 % firebird
08:43:48 2014: 08:43:48 26276 be/4 root 0.00 B/s 7.87 K/s 0.00 % 0.00 % supertee -tn vmsta
08:43:49 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 127.71 M/s
08:43:49 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:49 2014: 08:43:49 26261 be/4 firebird 0.00 B/s 995.65 K/s 0.00 % 71.22 % firebird
08:43:49 2014: 08:43:49 1380 be/3 root 0.00 B/s 3.94 K/s 0.00 % 0.02 % [jbd2/sdb1-8]
08:43:49 2014: 08:43:49 26263 be/4 firebird 0.00 B/s 787.08 K/s 0.00 % 0.00 % firebird
08:43:49 2014: 08:43:49 26281 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iotop
08:43:50 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 31.22 M/s
08:43:50 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:50 2014: 08:43:50 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 97.24 % firebird
08:43:51 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 93.57 M/s
08:43:51 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:51 2014: 08:43:51 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 97.16 % firebird
08:43:51 2014: 08:43:51 1639 be/4 root 0.00 B/s 0.00 B/s 0.00 % 60.82 % [flush-8:0]
08:43:52 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 14.20 M/s
08:43:52 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:52 2014: 08:43:52 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.99 % firebird
08:43:52 2014: 08:43:52 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 54.26 % [jbd2/sda4-8]
08:43:52 2014: 08:43:52 26266 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iosta
08:43:53 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 31.29 M/s
08:43:53 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:53 2014: 08:43:53 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 98.72 % [jbd2/sda4-8]
08:43:53 2014: 08:43:53 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 98.16 % firebird
08:43:54 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 30.24 M/s
08:43:54 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:54 2014: 08:43:54 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.61 % [jbd2/sda4-8]
08:43:54 2014: 08:43:54 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 98.88 % firebird
08:43:55 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 29.70 M/s
08:43:55 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:55 2014: 08:43:55 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.54 % [jbd2/sda4-8]
08:43:55 2014: 08:43:55 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.15 % firebird
08:43:56 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 29.59 M/s
08:43:56 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:56 2014: 08:43:56 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.99 % [jbd2/sda4-8]
08:43:56 2014: 08:43:56 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.00 % firebird
08:43:56 2014: 08:43:56 2961 be/4 root 0.00 B/s 7.88 K/s 0.00 % 1.97 % ../jre/bin/java -class
08:43:56 2014: 08:43:56 28793 be/4 root 0.00 B/s 19.70 K/s 0.00 % 0.00 % mc -P /tmp/mc-root/mc.
08:43:57 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 29.90 M/s
08:43:57 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:57 2014: 08:43:57 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.17 % firebird
08:43:57 2014: 08:43:57 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.08 % [jbd2/sda4-8]
08:43:57 2014: 08:43:57 26281 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iotop_o_h
08:43:58 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 29.76 M/s
08:43:58 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:58 2014: 08:43:58 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.05 % [jbd2/sda4-8]
08:43:58 2014: 08:43:58 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 98.21 % firebird
08:43:59 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 29.71 M/s
08:43:59 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:43:59 2014: 08:43:59 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.98 % [jbd2/sda4-8]
08:43:59 2014: 08:43:59 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.29 % firebird
08:43:59 2014: 08:43:59 26266 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iostat_x_
08:44:00 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 28.51 M/s
08:44:00 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:44:00 2014: 08:44:00 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.94 % [jbd2/sda4-8]
08:44:00 2014: 08:44:00 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.26 % firebird
08:44:00 2014: 08:44:00 1380 be/3 root 0.00 B/s 43.33 K/s 0.00 % 0.94 % [jbd2/sdb1-8]
08:44:01 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 27.21 M/s
08:44:01 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:44:01 2014: 08:44:01 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.10 % [jbd2/sda4-8]
08:44:01 2014: 08:44:01 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 98.63 % firebird
08:44:01 2014: 08:44:01 2662 be/4 oracle 0.00 B/s 11.82 K/s 0.00 % 0.00 % java -Xmx128M -XX:MaxP
08:44:01 2014: core/12.1.0.3.0/sysman/jlib/emagentSDK-intg.jar:/u01/app/oracle/oms/core/12.1.0.3.0/sysman/
08:44:02 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 25.24 M/s
08:44:02 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:44:02 2014: 08:44:02 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.71 % [jbd2/sda4-8]
08:44:02 2014: 08:44:02 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.35 % firebird
08:44:03 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 27.61 M/s
08:44:03 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:44:03 2014: 08:44:03 447 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.87 % [jbd2/sda4-8]
08:44:03 2014: 08:44:03 26261 be/4 firebird 0.00 B/s 0.00 B/s 0.00 % 99.09 % firebird
08:44:03 2014: 08:44:03 26281 be/4 root 0.00 B/s 3.94 K/s 0.00 % 0.00 % supertee -tn iot
08:44:04 2014: Total DISK READ: 0.00 B/s | Total DISK WRITE: 10.33 M/s
08:44:04 2014: TIME TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
08:44:04 2014: 08:44:04 447 be/3 root 0.00 B/s 55.15 K/s 0.00 % 26.08 % [jbd2/sda4-8]
08:44:04 2014: 08:44:04 26261 be/4 firebird 0.00 B/s 7.27 M/s 0.00 % 25.69 % firebird
08:44:04 2014: 08:44:04 26263 be/4 firebird 0.00 B/s 69.94 M/s 0.00 % 0.00 % firebird
Как видно по логам, при затыках
1)
всегда что-то делалось потоком 26261 процесса firebird (это CACHE_WRITER ?)
2)
иногда включался процесс jbd2/sda4-8.
Для информации снял три бактрассы с ФБ (с интервалом ~45 сек) - они в аттаче.
ЗЫ. файл базы при последнем затыке имел размер = 1.3 Гб. Его копирование занимает:
1) сразу после теста, когда база торчит в файловом кеше:
1.
2.
3.
4.
time cp huge_noext_at.fdb huge_noext_at.tmp
real 0m1.239s
user 0m0.009s
sys 0m1.227s
2) при очистке файлового кеша:
1.
2.
3.
real 0m21.227s
user 0m0.003s
sys 0m1.871s
