ReSQL.ru
     
powered by simpleCommunicator - 2.0.61     © 2026 Programmizd 02
Мобильная версия    Контакт    Правила    FAQ    Помощь
Целевая тема:
Создать новую тему:
Автор:
Закрыть
Цитировать
Доб. в избранное | Игнор. тему | Прикреп. тему | Пометить прочит. / непрочит. | Фильтр
Форумы / Firebird, InterBase [игнор отключен] [закрыт для гостей] / Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
9 сообщений из 9, страница 1 из 1
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38374910
Таблоид
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Таблоид
Участник
hi all

В новой базе (имя = TRNUNDO.FDB) с pagesize = 4K создаю таблицу и заталкиваю в неё 40 тыс строк:
Код: sql
1.
2.
3.
4.
create sequence g; commit;
recreate table tfix1(id int primary key, s01 varchar(1000)); commit;
insert into tfix1 select gen_id(g,1), rpad('',1000, gen_uuid()) from rdb$types,rdb$types,rdb$types rows 400000; commit;
quit;


Затем делаю gfix -w async TRNUNDO.FDB и копирую её в отдельный файлик (он весит 554 Мб).
Далее запускаю трейс и выполняю батник:
Код: plaintext
1.
%fb30bin%\isql localhost/3330:C:\1Install\FBTEST\TRNUNDO.FDB -n -i trnundo.sql
@echo exit to OS at: %time%

- где содержимое скрипта `trnundo.sql` есть:
Код: sql
1.
2.
3.
4.
5.
update tfix1 set s01=rpad('',1000, gen_uuid()); -- ~30...40 сек
rollback; -- мгновенно
set list on;
select current_timestamp dts_before_quit from rdb$database;
quit;



И вот что вижу в итоге:
Код: plaintext
1.
2.
3.
4.
C:\1Install\FBTEST>C:\1Install\fb30\isql localhost/3330:C:\1Install\FBTEST\TRNUNDO.FDB -n -i trnundo.sql

DTS_BEFORE_QUIT                 2013-08-22 15: 54:02 .7280

exit to OS at: 15: 54:24 ,44

То есть, на выполнение quit'a было затрачено 22 сек.
Трейс же показывает, что якобы всё прекратилось именно в 15:54:02, т.е. когда он засёк получение команды QUIT.
Что тогда там еще делалось 22 сек ?
 
trace, ~200 rows
Код: 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.
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.
146.
147.
148.
149.
150.
151.
152.
153.
154.
155.
156.
157.
158.
159.
160.
161.
162.
163.
164.
165.
166.
167.
168.
169.
170.
171.
172.
173.
174.
175.
176.
177.
178.
179.
180.
181.
182.
183.
184.
185.
186.
187.
188.
189.
190.
191.
192.
193.
194.
195.
196.
197.
198.
Trace session ID 1 started
2013-08-22T15:53:18.1030 (16532:01CC1900) TRACE_INIT
	SESSION_1  
	

2013-08-22T15:53:18.1030 (16532:01CC1900) DETACH_DATABASE
	C:\1INSTALL\FB30\SECURITY3.FDB (ATT_8540, SYSDBA:NONE, NONE, <internal>)

2013-08-22T15:53:18.1030 (16532:01CC1900) TRACE_FINI
	SESSION_1  
	

2013-08-22T15:53:19.0100 (16532:01CC1900) TRACE_INIT
	SESSION_1  
	

2013-08-22T15:53:19.0100 (16532:01CC1900) ATTACH_DATABASE
	C:\1INSTALL\FB30\SECURITY3.FDB (ATT_8542, SYSDBA:NONE, NONE, <internal>)

2013-08-22T15:53:19.0250 (16532:01CC1900) START_TRANSACTION
	C:\1INSTALL\FB30\SECURITY3.FDB (ATT_8542, SYSDBA:NONE, NONE, <internal>)
		(TRA_465010, CONCURRENCY | WAIT | READ_ONLY)

2013-08-22T15:53:19.0410 (16532:01CC1900) ROLLBACK_TRANSACTION
	C:\1INSTALL\FB30\SECURITY3.FDB (ATT_8542, SYSDBA:NONE, NONE, <internal>)
		(TRA_465010, CONCURRENCY | WAIT | READ_ONLY)
     17 ms, 1 write(s), 1 fetch(es), 1 mark(s)

2013-08-22T15:53:19.2910 (16532:01CC2A08) TRACE_INIT
	SESSION_1  
	

2013-08-22T15:53:19.2910 (16532:01CC2A08) ATTACH_DATABASE
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596

2013-08-22T15:53:19.2910 (16532:01CC2A08) START_TRANSACTION
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_19, CONCURRENCY | WAIT | READ_WRITE)

2013-08-22T15:53:19.3220 (16532:01CC2A08) PREPARE_STATEMENT
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_19, CONCURRENCY | WAIT | READ_WRITE)

Statement 23:
-------------------------------------------------------------------------------
update tfix1 set s01=rpad('',1000, gen_uuid())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (TFIX1 NATURAL)
      5 ms

2013-08-22T15:53:19.3220 (16532:01CC2A08) EXECUTE_STATEMENT_START
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_19, CONCURRENCY | WAIT | READ_WRITE)

Statement 23:
-------------------------------------------------------------------------------
update tfix1 set s01=rpad('',1000, gen_uuid())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (TFIX1 NATURAL)

2013-08-22T15:53:29.0560 (16532:01CC1900) DETACH_DATABASE
	C:\1INSTALL\FB30\SECURITY3.FDB (ATT_8542, SYSDBA:NONE, NONE, <internal>)

2013-08-22T15:53:29.0560 (16532:01CC1900) TRACE_FINI
	SESSION_1  
	

2013-08-22T15:54:02.1660 (16532:01CC2A08) EXECUTE_STATEMENT_FINISH
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_19, CONCURRENCY | WAIT | READ_WRITE)

Statement 23:
-------------------------------------------------------------------------------
update tfix1 set s01=rpad('',1000, gen_uuid())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (TFIX1 NATURAL)
0 records fetched
  42843 ms, 133492 read(s), 9355 write(s), 7780515 fetch(es), 2400864 mark(s)

Table                             Natural     Index    Update    Insert    Delete   Backout     Purge   Expunge
***************************************************************************************************************
RDB$PAGES                                                           148                                        
TFIX1                              400000              400000                                  400000          

2013-08-22T15:54:02.1660 (16532:01CC2A08) FREE_STATEMENT
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596

Statement 23:
-------------------------------------------------------------------------------
update tfix1 set s01=rpad('',1000, gen_uuid())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (TFIX1 NATURAL)

2013-08-22T15:54:02.1970 (16532:01CC2A08) ROLLBACK_TRANSACTION
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_19, CONCURRENCY | WAIT | READ_WRITE)
     35 ms, 1 read(s), 1 write(s), 1 fetch(es), 1 mark(s)

2013-08-22T15:54:02.2130 (16532:01CC2A08) START_TRANSACTION
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_20, CONCURRENCY | WAIT | READ_WRITE)

2013-08-22T15:54:02.6810 (16532:01CC1900) TRACE_INIT
	SESSION_1  
	

2013-08-22T15:54:02.6810 (16532:01CC1900) START_TRANSACTION
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_15, Garbage Collector, NONE, <internal>)
		(TRA_21, READ_COMMITTED | REC_VERSION | WAIT | READ_ONLY)

2013-08-22T15:54:02.7130 (16532:01CC2A08) PREPARE_STATEMENT
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_20, CONCURRENCY | WAIT | READ_WRITE)

Statement 31:
-------------------------------------------------------------------------------
select current_timestamp dts_before_quit from rdb$database
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (RDB$DATABASE NATURAL)
    508 ms

2013-08-22T15:54:02.7280 (16532:01CC2A08) EXECUTE_STATEMENT_START
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_20, CONCURRENCY | WAIT | READ_WRITE)

Statement 31:
-------------------------------------------------------------------------------
select current_timestamp dts_before_quit from rdb$database
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (RDB$DATABASE NATURAL)

2013-08-22T15:54:02.7440 (16532:01CC2A08) EXECUTE_STATEMENT_FINISH
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_20, CONCURRENCY | WAIT | READ_WRITE)

Statement 31:
-------------------------------------------------------------------------------
select current_timestamp dts_before_quit from rdb$database
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (RDB$DATABASE NATURAL)
1 records fetched
      5 ms, 1 read(s), 11 fetch(es), 2 mark(s)

Table                             Natural     Index    Update    Insert    Delete   Backout     Purge   Expunge
***************************************************************************************************************
RDB$DATABASE                            1                                                           1          

2013-08-22T15:54:02.7600 (16532:01CC2A08) CLOSE_CURSOR
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596

Statement 31:
-------------------------------------------------------------------------------
select current_timestamp dts_before_quit from rdb$database
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (RDB$DATABASE NATURAL)

2013-08-22T15:54:02.7600 (16532:01CC2A08) ROLLBACK_TRANSACTION
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596
		(TRA_20, CONCURRENCY | WAIT | READ_WRITE)
      0 ms, 1 write(s), 1 fetch(es), 1 mark(s)

2013-08-22T15:54:02.7600 (16532:01CC2A08) FREE_STATEMENT
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596

Statement 31:
-------------------------------------------------------------------------------
select current_timestamp dts_before_quit from rdb$database
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (RDB$DATABASE NATURAL)

2013-08-22T15:54:02.7600 (16532:01CC2A08) DETACH_DATABASE
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_14, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
	C:\1Install\fb30\isql.exe:5596

2013-08-22T15:54:02.7600 (16532:01CC2A08) TRACE_FINI
	SESSION_1  
	

2013-08-22T15:54:02.7750 (16532:01CC1900) COMMIT_TRANSACTION
	C:\1INSTALL\FBTEST\TRNUNDO.FDB (ATT_15, Garbage Collector, NONE, <internal>)
		(TRA_21, READ_COMMITTED | REC_VERSION | WAIT | READ_ONLY)
      0 ms

2013-08-22T15:54:02.7750 (16532:01CC1900) TRACE_FINI
	SESSION_1

PS. Замеры повторял несколько раз. Время "обдумывания" команды QUIT никогда не было меньше 15 сек.
...
Рейтинг: 0 / 0
22.08.2013, 16:06:14
| Ответить | Цитировать | Написать  
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38375462
dimitr
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
dimitr
Участник
Таблоидзаталкиваю в неё 40 тыс строк
так я тебе и поверил :-)

ТаблоидЧто тогда там еще делалось 22 сек ?
кеш писался на диск. Роллбек при большом числе изменений (когда undo не используется) не сбрасывает кеш синхронно. В твоем случае он будет сбрасываться при последнем дисконнекте, но уже после убиения аттача (ибо кеш не привязан к нему), поэтому и в трейс не попадает.
...
Рейтинг: 0 / 0
23.08.2013, 09:39:08
| Ответить | Цитировать | Написать  
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38375476
Таблоид
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Таблоид
Участник
dimitrТаблоидзаталкиваю в неё 40 тыс строктак я тебе и поверил :-)да, пардон, очепятка случилась... в 10 раз побольше было... :-)
dimitrТаблоидЧто тогда там еще делалось 22 сек ?кеш писался на диск. Роллбек при большом числе изменений (когда undo не используется) не сбрасывает кеш синхронно. В твоем случае он будет сбрасываться при последнем дисконнекте , но уже после убиения аттача (ибо кеш не привязан к нему), поэтому и в трейс не попадает.да, вижу: добавил еще один коннект ("N"), в первом выполнил снова этот bulk update + quit - и он вылетел сразу. А вот коннект-"N" на quit'e застрял.
Это только в SS такое, или в SC тоже так должно быть ?
...
Рейтинг: 0 / 0
23.08.2013, 09:54:00
| Ответить | Цитировать | Написать  
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38375480
Таблоид
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Таблоид
Участник
dimitrРоллбек при большом числе изменений (когда undo не используется) не сбрасывает кеш синхронно. В твоем случае он будет сбрасываться при последнем дисконнекте, но уже после убиения аттача (ибо кеш не привязан к нему), поэтому и в трейс не попадает.Он *не* сбрасывается, если:
1) открыть isql_1, ничего в нём не делать
2) запустить вышеприведенный bat'ник
3) дождаться окончания работы этого батника
4) закрыть isql_1 "крестиком".

Пункт "4" отработает, ясный пень, мгновенно, никаких тут 20 секунд не будет.
Наблюдение же за процессом fbserver в PE показывает, что он даже не чухается, что к нему последний коннект пропал и ничего не сбрасывает на диск - см аттач.
...
Рейтинг: 0 / 0
23.08.2013, 10:00:48
| Ответить | Цитировать | Написать  
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38376246
Таблоид
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Таблоид
Участник
dimitrкеш писался на диск. Роллбек при большом числе изменений (когда undo не используется) не сбрасывает кеш синхронно. В твоем случае он будет сбрасываться при последнем дисконнекте, но уже после убиения аттача (ибо кеш не привязан к нему), поэтому и в трейс не попадает.Что-то вспомнил только сейчас...
А вот активность "системного" ATT=0, отвечающего как раз за сброс кеша (его имя в трейсе = CACHE WRITER) - разве она не должна показываться как раз после убиения последнего "нормального" аттача (т.е. последнего isql-окна) ?
...
Рейтинг: 0 / 0
23.08.2013, 18:56:27
| Ответить | Цитировать | Написать  
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38596267
Dimitry Sibiryakov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Dimitry Sibiryakov
Участник
Извиняюсь за некрофилию.
dimitrРоллбек при большом числе изменений (когда undo не используется) не сбрасывает кеш синхронно.
Смотрю вот я в исходники и вижу, что когда undo таки используется, то кэш синхронно сбрасывается аж два раза: один раз перед откатом данных, второй - после. В комменте сказано, что это делается для очистки графа зависимостей и избежания дедлоков. Но не слишком ли брутальным способом?..
...
Рейтинг: 0 / 0
25.03.2014, 19:33:49
| Ответить | Цитировать | Написать  
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38596362
hvlad
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
hvlad
Участник
Dimitry SibiryakovСмотрю вот я в исходники и вижу, что когда undo таки используется, то кэш синхронно сбрасывается аж два раза: один раз перед откатом данных, второй - после.Реально пишутся только грязные страницы, так что не всё так страшно.
...
Рейтинг: 0 / 0
25.03.2014, 21:38:08
| Ответить | Цитировать | Написать  
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38596387
Dimitry Sibiryakov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Dimitry Sibiryakov
Участник
hvladРеально пишутся только грязные страницы, так что не всё так страшно.
Всё равно я не врубаюсь в чём проблема с зависимостями. При откате могут испачкаться
только те страницы, которые уже затрагивались транзакцией. Так что в лучшем случае они всё
ещё сидят в кэше, грязные, и их граф зависимостей не изменится. В худшем - начнут читаться
с диска и вытеснят текущие грязные вместе с их графом.
Posted via ActualForum NNTP Server 1.5
...
Рейтинг: 0 / 0
25.03.2014, 22:09:37
| Ответить | Цитировать | Написать  
Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
    #38596448
hvlad
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
hvlad
Участник
Dimitry SibiryakovВсё равно я не врубаюсь в чём проблема с зависимостями.Создаём бекверсию: первичная страница должна быть записана после вторичной.
Откатываем эту бекверсию: первичная страница должна быть записана до вторичной.
...
Рейтинг: 0 / 0
25.03.2014, 23:39:41
| Ответить | Цитировать | Написать  
9 сообщений из 9, страница 1 из 1
Форумы / Firebird, InterBase [игнор отключен] [закрыт для гостей] / Затраты на quit = 20 сек после update 400'000 строк и его rollback'a. Why ?
Найденые пользователи ...
Разблокировать пользователей ...
Читали тему (0):
Читали форум (0):
Пользователи онлайн (0):
Польз. соглашение   Полит. конфиден.  
NoSQL.ru       Кролег: Проекты, Новости, Чат       РЕД ФОРУМ       Фотоальбом: Участники, Встречи
Закрыть
start [/forum/topic.php?fid=40&gotonew=1&tid=1563781]:
 0ms
get settings:
 8ms
get forum list:
 10ms
check forum access:
 2ms
check topic access:
 2ms
track hit:
 189ms
get topic data:
 10ms
get first new msg:
 4ms
get forum data:
 2ms
get page messages:
 37ms
get tp. blocked users:
 1ms
others: 260ms
total:  525ms
созд. / загр.: 525ms
x
x
Закрыть


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