Добро пожаловать в форум, Guest  >>   Войти | Регистрация | Поиск | Правила | В избранное | Подписаться
Все форумы / Firebird, InterBase Новый топик    Ответить
Топик располагается на нескольких страницах: Ctrl  назад   1 2 3 4 5 [6] 7 8 9   вперед  Ctrl      все
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
Таблоид
Секундомер показал, к примеру, 5.94 сек, сумма же значений времени вып-я в трейсе равна 8300 мс.
пардон муа, глупость я сморозил :-[.
Один из... (страшно даже сказать кто) показал в личке элементарный пример, объясняющий то, что суммарное время по трейсу больше, чем "по часам":
1. start select from sp
2. start select from sp2
3. finish select from sp2, t = 10
4.finish from sp, t = 20

sp вызывает sp2; общее время вып-я будет 20, а не бездумно просуммированное 30.

В общем, вопрос про расхождение в суммах снят.
6 мар 12, 18:36    [12206002]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
Что ж, продолжим разговор :-)

session #1: мониторное окно, в нём - старт трейса с параметрами:
  enabled true
log_context true
log_connections true
log_transactions true

log_statement_prepare true
log_statement_free true

log_statement_start true
log_statement_finish true

log_trigger_finish true

log_blr_requests true

print_perf true
print_blr true

time_threshold 0
max_sql_length 4000
max_blr_length 1000
max_dyn_length 1000
max_log_size 0

session #2: isql-окно с неким тяжелым запросом, которое либо срубается "крестиком", либо обламывается командой delete from mon$attachments (из третьего окна), либо прерывается банальным Ctrl-Break:
C:\1INSTALL\FIREBIRD\Data>isql localhost/3050:C:\1INSTALL\FIREBIRD\Data\T1.fdb -n
Database: localhost/3050:C:\1INSTALL\FIREBIRD\Data\T1.fdb
SQL> select count(*) from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields;
-- гарантированно уйдёт в нирвану, ждем для приличия 20-30 сек, затем прерываем

Trace-1:
+
Trace session ID 7 started
2012-05-10T23:44:27.4530 (580:0202B970) TRACE_INIT

SESSION_7

2012-05-10T23:44:27.4530 (580:0202B970) ATTACH_DATABASE

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672



2012-05-10T23:44:27.4680 (580:0202B970) START_TRANSACTION

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672

(TRA_16, CONCURRENCY | WAIT | READ_WRITE)



2012-05-10T23:44:38.1870 (580:0202B970) PREPARE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672

(TRA_16, CONCURRENCY | WAIT | READ_WRITE)



Statement 257:

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

select count(*) from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields

5 ms



2012-05-10T23:44:38.1870 (580:0202B970) EXECUTE_STATEMENT_START

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672

(TRA_16, CONCURRENCY | WAIT | READ_WRITE)



Statement 257:

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

select count(*) from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields



2012-05-10T23:45:04.1250 (580:0202B970) ROLLBACK_TRANSACTION

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672

(TRA_16, CONCURRENCY | WAIT | READ_WRITE)

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



2012-05-10T23:45:04.1250 (580:0202B970) EXECUTE_STATEMENT_FINISH

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672

(TRA_16, CONCURRENCY | WAIT | READ_WRITE)



Statement 257:

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

select count(*) from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields

0 records fetched

0 ms, 1 read(s), 37969951 fetch(es)



Table Natural Index Update Insert Delete Backout Purge Expunge

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

RDB$FIELDS 18446943



2012-05-10T23:45:04.1250 (580:0202B970) CLOSE_CURSOR

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672



Statement 257:

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

select count(*) from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields



2012-05-10T23:45:04.1250 (580:0202B970) DETACH_DATABASE

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672



2012-05-10T23:45:04.1250 (580:0202B970) FREE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1672



Statement 257:

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

select count(*) from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields



2012-05-10T23:45:04.1250 (580:0202B970) TRACE_FINI

SESSION_7
Вопрос-1: почему время выполнения прерванного запроса = 0 мс ?

И второй эксперимент: в том же окне-молотилке вместо select count(*) выполняем:
SQL> out nul;
SQL> select * from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields;
- и также ждём не менее 30 секунд.
Затем прерываем его работу через delete from mon$attachments where mon$attachment_id<>current_connection; commit;
В трейсе будет видно уже НЕнулевое время, около 7 сек.
Но оно намного меньше, чем то, что фактически прошло! В нижеприведенном логе видно, что:
EXECUTE_STATEMENT_START случился в 2012-05-10T23:59:02.3280
EXECUTE_STATEMENT_FINISH произошёл в 2012-05-10T23:59:48.0310
-- таким обр, прошло 45 сек.
А в трейсе говорится, что молотьба шла якобы 6.9 сек.

Trace-2:
+
Trace session ID 9 started
2012-05-10T23:58:07.6400 (580:0202B970) TRACE_INIT

SESSION_9

2012-05-10T23:58:07.6400 (580:0202B970) ATTACH_DATABASE

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1668



2012-05-10T23:58:07.6560 (580:0202B970) START_TRANSACTION

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1668

(TRA_18, CONCURRENCY | WAIT | READ_WRITE)



2012-05-10T23:59:02.3280 (580:0202B970) PREPARE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1668

(TRA_18, CONCURRENCY | WAIT | READ_WRITE)



Statement 337:

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

select * from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields

6 ms



2012-05-10T23:59:02.3280 (580:0202B970) EXECUTE_STATEMENT_START

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1668

(TRA_18, CONCURRENCY | WAIT | READ_WRITE)



Statement 337:

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

select * from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields



2012-05-10T23:59:48.0150 (580:0202D67C) TRACE_INIT

SESSION_9





2012-05-10T23:59:48.0150 (580:0202D67C) START_TRANSACTION

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1188

(TRA_19, CONCURRENCY | WAIT | READ_WRITE)



2012-05-10T23:59:48.0150 (580:0202D67C) START_TRANSACTION

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1188

(TRA_20, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)



2012-05-10T23:59:48.0150 (580:0202D67C) PREPARE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1188

(TRA_20, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)



Statement 84:

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

delete from mon$attachments where mon$attachment_id<>current_connection

0 ms



2012-05-10T23:59:48.0150 (580:0202D67C) EXECUTE_STATEMENT_START

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1188

(TRA_19, CONCURRENCY | WAIT | READ_WRITE)



Statement 84:

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

delete from mon$attachments where mon$attachment_id<>current_connection



2012-05-10T23:59:48.0150 (580:0202D67C) EXECUTE_STATEMENT_FINISH

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1188

(TRA_19, CONCURRENCY | WAIT | READ_WRITE)



Statement 84:

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

delete from mon$attachments where mon$attachment_id<>current_connection

0 records fetched

2 ms, 1 read(s), 1 fetch(es)



2012-05-10T23:59:48.0150 (580:0202D67C) FREE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1188



Statement 84:

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

delete from mon$attachments where mon$attachment_id<>current_connection



2012-05-10T23:59:48.0150 (580:0202D67C) COMMIT_TRANSACTION

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1188

(TRA_19, CONCURRENCY | WAIT | READ_WRITE)

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



2012-05-10T23:59:48.0150 (580:0202D67C) COMMIT_TRANSACTION

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1188

(TRA_20, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)

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



2012-05-10T23:59:48.0310 (580:0202B970) EXECUTE_STATEMENT_FINISH

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1668

(TRA_18, CONCURRENCY | WAIT | READ_WRITE)



Statement 337:

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

select * from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields

83600 records fetched

6936 ms, 1 read(s), 173531 fetch(es)



Table Natural Index Update Insert Delete Backout Purge Expunge

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

RDB$FIELDS 84306

RDB$CHARACTER_SETS 1

RDB$COLLATIONS 1



2012-05-10T23:59:48.0310 (580:0202B970) CLOSE_CURSOR

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1668



Statement 337:

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

select * from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields



2012-05-10T23:59:48.0310 (580:0202B970) DETACH_DATABASE

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1668



2012-05-10T23:59:48.0310 (580:0202B970) FREE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1668



Statement 337:

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

select * from rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields,rdb$fields



2012-05-10T23:59:48.0310 (580:0202B970) TRACE_FINI

SESSION_9
Вопрос-2: почему время в статистике запроса, хоть и ненулевое, но совершенно нереальное ?
11 май 12, 00:11    [12533464]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
hvlad
Member

Откуда:
Сообщений: 9237
Таблоид
Вопрос-1: почему время выполнения прерванного запроса = 0 мс ?
Потому что бага

Таблоид
Вопрос-2: почему время в статистике запроса, хоть и ненулевое, но совершенно нереальное ?
Потому что трейс считает только время, проведенное в движке.
А isql учитывает :
- время на трансфер данных между сетевым сервером и движком
- время на трансфер данных между приложениями
- время на обработку данных самим isql
11 май 12, 01:58    [12533713]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
hvlad
Таблоид
Вопрос-2: почему время в статистике запроса, хоть и ненулевое, но совершенно нереальное ?
Потому что трейс считает только время, проведенное в движке.
А isql учитывает :
- время на трансфер данных между сетевым сервером и движком
- время на трансфер данных между приложениями
- время на обработку данных самим isql
Да, но данных в этой таблице (rdb$fields) - кот накакал: not_null значений во всех блоб-полях только 4, и все - по несколько байт; два (var)char-поля из трёх (query_name, edit_string) - все null. Остальные поля - smallint, причем только 4 столбца заполнены целиком (field_len, field_scale, field_type & system_flag). Остальные - опять-таки по большей части null'ы.

Повторил эксперимент, но для таблицы с единственным smallint-полем и 120 строками.
DDL:
recreate table t(id smallint);
commit;
insert into t select rdb$system_flag from rdb$fields;
select count(*) from t;
commit;
quit;

Test:
C:\1INSTALL\FIREBIRD\Data>isql localhost/3050:C:\1INSTALL\FIREBIRD\Data\T1.fdb -n
Database: localhost/3050:C:\1INSTALL\FIREBIRD\Data\T1.fdb
SQL> out nul;
SQL> select a.id from t a,t b,t c,t d,t e,t f; -- передаём "на клиента" только одно smallint-поле

Теперь ждём три минуты, затем прерываем из другого окна по delete from mon$attachments.
Смотрим после этого в трейс: он показывает, что время "в движке" составило всего 48 сек! И это при том, что данные таблицы никуда на самом деле не выводились (всё перенаправлялось в nul). Передача значений smallint-поля (это же два байта всего) заняла в два с лишним раза больше, чем их извлечение движком...
+
Trace session ID 2 started
2012-05-11T08:48:00.4060 (584:0202C0C0) TRACE_INIT

SESSION_2





2012-05-11T08:48:00.4060 (584:0202C0C0) PREPARE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1632

(TRA_122, CONCURRENCY | WAIT | READ_WRITE)



Statement 707:

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

select a.id from t a,t b,t c,t d,t e,t f

5 ms



2012-05-11T08:48:00.4060 (584:0202C0C0) EXECUTE_STATEMENT_START

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1632

(TRA_122, CONCURRENCY | WAIT | READ_WRITE)



Statement 707:

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

select a.id from t a,t b,t c,t d,t e,t f



2012-05-11T08:51:00.5930 (584:0202ADCC) TRACE_INIT

SESSION_2





2012-05-11T08:51:00.6090 (584:0202ADCC) PREPARE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1688

(TRA_124, CONCURRENCY | WAIT | READ_WRITE)



Statement 721:

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

delete from mon$attachments where mon$attachment_id<>current_connection

5 ms



2012-05-11T08:51:00.6090 (584:0202ADCC) EXECUTE_STATEMENT_START

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1688

(TRA_124, CONCURRENCY | WAIT | READ_WRITE)



Statement 721:

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

delete from mon$attachments where mon$attachment_id<>current_connection



2012-05-11T08:51:00.6250 (584:0202ADCC) EXECUTE_STATEMENT_FINISH

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1688

(TRA_124, CONCURRENCY | WAIT | READ_WRITE)



Statement 721:

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

delete from mon$attachments where mon$attachment_id<>current_connection

0 records fetched

12 ms, 1 read(s), 73 fetch(es)



Table Natural Index Update Insert Delete Backout Purge Expunge

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

RDB$RELATIONS 16

RDB$CHARACTER_SETS 1

RDB$COLLATIONS 1



2012-05-11T08:51:00.6250 (584:0202ADCC) FREE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1688



Statement 721:

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

delete from mon$attachments where mon$attachment_id<>current_connection



2012-05-11T08:51:00.6250 (584:0202ADCC) COMMIT_TRANSACTION

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1688

(TRA_124, CONCURRENCY | WAIT | READ_WRITE)

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



2012-05-11T08:51:00.6870 (584:0202C0C0) EXECUTE_STATEMENT_FINISH

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1632

(TRA_122, CONCURRENCY | WAIT | READ_WRITE)



Statement 707:

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

select a.id from t a,t b,t c,t d,t e,t f

4979394 records fetched

47900 ms, 1 read(s), 10249266 fetch(es)



Table Natural Index Update Insert Delete Backout Purge Expunge

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

RDB$CHARACTER_SETS 1

RDB$COLLATIONS 1

T 5020893



2012-05-11T08:51:00.6870 (584:0202C0C0) CLOSE_CURSOR

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1632



Statement 707:

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

select a.id from t a,t b,t c,t d,t e,t f



2012-05-11T08:51:00.6870 (584:0202C0C0) DETACH_DATABASE

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1632



2012-05-11T08:51:00.6870 (584:0202C0C0) FREE_STATEMENT

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

C:\1INSTALL\FIREBIRD\FB_2_5\bin\isql.exe:1632



Statement 707:

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

select a.id from t a,t b,t c,t d,t e,t f



2012-05-11T08:51:00.6870 (584:0202C0C0) TRACE_FINI

SESSION_2

PS. ПОЛУОФФ. gstat -r -t для rdb$-таблиц не работает, что ли ?
+
C:\1INSTALL\FIREBIRD\Data>gstat -r -t RDB$FIELDS T1.FDB > ttt
table "RDB$FIELDS" not found

C:\1INSTALL\FIREBIRD\Data>gstat -r -t "RDB$FIELDS" T1.FDB > ttt
table "RDB$FIELDS" not found

C:\1INSTALL\FIREBIRD\Data>gstat -r -t rdb$fields T1.FDB > ttt
table "rdb$fields" not found

C:\1INSTALL\FIREBIRD\Data>gstat -r -t "rdb$fields" T1.FDB > ttt
table "rdb$fields" not found

C:\1INSTALL\FIREBIRD\Data>gstat -r -t "RDB\$FIELDS" T1.FDB > ttt
table "RDB\$FIELDS" not found

C:\1INSTALL\FIREBIRD\Data>gstat -r -t RDB\$FIELDS T1.FDB > ttt
table "RDB\$FIELDS" not found
11 май 12, 08:56    [12533981]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
hvlad
Member

Откуда:
Сообщений: 9237
Таблоид
Теперь ждём три минуты, затем прерываем из другого окна по delete from mon$attachments.
Смотрим после этого в трейс: он показывает, что время "в движке" составило всего 48 сек! И это при том, что данные таблицы никуда на самом деле не выводились (всё перенаправлялось в nul)
Ага, не выводились. Из движка в y-valve, из y-valve в сетевой редиректор, потом через сеть потом в клиентский сетевой редиректор, потом в клиентский y-valve, потом в isql, потом в строку, потом в nul - мало ?
Кроме того, я же сказал, что при прерывании запроса время не считается правильно.

Таблоид
Передача значений smallint-поля (это же два байта всего) заняла в два с лишним раза больше, чем их извлечение движком...
Ну так движок рулит, что плохого ? :)
11 май 12, 11:17    [12534795]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
hvlad
Member

Откуда:
Сообщений: 9237
Таблоид
gstat -r -t для rdb$-таблиц не работает, что ли ?
Борманов спрашивай, они это делали...
11 май 12, 11:18    [12534802]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
hvlad
Из движка в y-valve, из y-valve в сетевой редиректор, потом через сеть потом в клиентский сетевой редиректор, потом в клиентский y-valve, потом в isql, потом в строку, потом в nul - мало ?
Судя по перечисленному (5 посредников) - не мало, конечно. Но всё равно неожиданно сильная "помеха" от них.
Надо будет проверить еще и DML, а не только селект.
11 май 12, 12:16    [12535326]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
hvlad
Кроме того, я же сказал, что при прерывании запроса время не считается правильно.
Оно странно выглядит также и в следующем случае:
C:\MIX\firebird\fb25>isql localhost/3050:C:\MIX\firebird\fb25\T1.FDB
Database: localhost/3050:C:\MIX\firebird\fb25\T1.FDB
SQL> out nul;
SQL> select a.id from t a,t b,t c; -- около 1.7 млн записей, дождаться окончания вполне реально. Ждём-c.
SQL> out;

Трейс:
+
Trace session ID 4 started
2012-05-11T16:48:50.9060 (592:022FDDF8) TRACE_INIT

SESSION_4





2012-05-11T16:48:50.9060 (592:022FDDF8) ATTACH_DATABASE

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_10, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

C:\MIX\firebird\fb25\bin\isql.exe:1632



2012-05-11T16:48:50.9060 (592:022FDDF8) START_TRANSACTION

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_10, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

C:\MIX\firebird\fb25\bin\isql.exe:1632

(TRA_23, CONCURRENCY | WAIT | READ_WRITE)



2012-05-11T16:48:50.9060 (592:022FDDF8) START_TRANSACTION

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_10, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

C:\MIX\firebird\fb25\bin\isql.exe:1632

(TRA_24, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)



2012-05-11T16:48:56.9210 (592:022FDDF8) PREPARE_STATEMENT

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_10, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

C:\MIX\firebird\fb25\bin\isql.exe:1632

(TRA_24, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)



Statement 419:

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

select a.id from t a,t b,t c

5 ms



2012-05-11T16:48:56.9210 (592:022FDDF8) EXECUTE_STATEMENT_START

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_10, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

C:\MIX\firebird\fb25\bin\isql.exe:1632

(TRA_23, CONCURRENCY | WAIT | READ_WRITE)



Statement 419:

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

select a.id from t a,t b,t c



2012-05-11T16:50:00.2960 (592:022FDDF8) EXECUTE_STATEMENT_FINISH

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_10, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

C:\MIX\firebird\fb25\bin\isql.exe:1632

(TRA_23, CONCURRENCY | WAIT | READ_WRITE)



Statement 419:

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

select a.id from t a,t b,t c

1771561 records fetched

29173 ms, 1 read(s), 3646469 fetch(es)



Table Natural Index Update Insert Delete Backout Purge Expunge

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

RDB$CHARACTER_SETS 1

RDB$COLLATIONS 1

T 1786323



2012-05-11T16:50:00.3750 (592:022FDDF8) CLOSE_CURSOR

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_10, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)

C:\MIX\firebird\fb25\bin\isql.exe:1632



Statement 419:

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

select a.id from t a,t b,t c
- то есть, "в движке" всё делалось якобы за 29173 мс.
А теперь смотрим на значения моментов времени начала и окончания вып-я запроса, те что я выделил синим цветом:
SQL> select datediff(millisecond from timestamp '11.05.2012 16.48.56.921' to timestamp '11.05.2012 16:50:00.296') 
CON> from rdb$database;

DATEDIFF
=====================
63375
11 май 12, 17:01    [12538031]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Dzirt
Member

Откуда:
Сообщений: 526
Таблоид,

почему бы тебе вместо
select a.id from t a,t b,t c;

не сделать
select count(*) from t a,t b,t c;

? Уберешь время передачи данных клиенту, при таком раскладе практически все время должно быть временем отработки запроса в движке.
11 май 12, 17:19    [12538144]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
Dzirt
при таком раскладе практически все время должно быть временем отработки запроса в движке.
Оно понятно, только "одиночный count" (одна строка с результатом) гораздо реже возвращается, чем сами данные.
А при передаче данных даже без сети, как выясняется, эти данным приходится через тучу посредников проходить.
И даже при отключке TCP-стека, т.е. работе по XNET, ощутимо влияние этих посредников: трейс говорит, что без tcp-стека "в движке" всё выполнялось 28.3 сек, а на самом деле это длилось 58,3 сек:
+
2012-05-11T17:27:37.3900 (592:022FDDF8) EXECUTE_STATEMENT_START

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_11, SYSDBA:NONE, NONE, XNET:CSPROG)

C:\MIX\firebird\fb25\bin\isql.exe:1672

(TRA_25, CONCURRENCY | WAIT | READ_WRITE)



Statement 467:

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

select a.id from t a,t b,t c



2012-05-11T17:28:35.7810 (592:022FDDF8) EXECUTE_STATEMENT_FINISH

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_11, SYSDBA:NONE, NONE, XNET:CSPROG)

C:\MIX\firebird\fb25\bin\isql.exe:1672

(TRA_25, CONCURRENCY | WAIT | READ_WRITE)



Statement 467:

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

select a.id from t a,t b,t c

1771561 records fetched

28368 ms, 1 read(s), 3646469 fetch(es)



Table Natural Index Update Insert Delete Backout Purge Expunge

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

RDB$CHARACTER_SETS 1

RDB$COLLATIONS 1

T 1786323

SQL> select datediff(millisecond from timestamp '11.05.2012 17:27:37.390' to timestamp '11.05.2012 17:28:35.781') f
rom rdb$database;

DATEDIFF
=====================
58391
Из этого и предыдущего примера, кстати, видно, что затраты проход через TCP-стек - минимальные.
Настоящая тёмная материя - это y_valve и редиректор.
11 май 12, 17:42    [12538249]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
Dzirt
Таблоид,

почему бы тебе вместо
select a.id from t a,t b,t c;

не сделать
select count(*) from t a,t b,t c;
Сделал и это (только добавил еще одну таблицу в кросс-джойн, а то с тремя очень быстро получилось).
Итог: данные статистики трейса практически совпали с разницей моментов execute_statement_start & _finish:
+
2012-05-11T17:30:18.5780 (592:022FC6FC) EXECUTE_STATEMENT_START

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_11, SYSDBA:NONE, NONE, XNET:CSPROG)

C:\MIX\firebird\fb25\bin\isql.exe:1672

(TRA_25, CONCURRENCY | WAIT | READ_WRITE)



Statement 470:

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

select count(a.id) from t a,t b,t c,t d



2012-05-11T17:36:58.4370 (592:022FC6FC) EXECUTE_STATEMENT_FINISH

C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_11, SYSDBA:NONE, NONE, XNET:CSPROG)

C:\MIX\firebird\fb25\bin\isql.exe:1672

(TRA_25, CONCURRENCY | WAIT | READ_WRITE)



Statement 470:

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

select count(a.id) from t a,t b,t c,t d

1 records fetched

399864 ms, 441222028 fetch(es)



Table Natural Index Update Insert Delete Backout Purge Expunge

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

T 216145204

Check:
SQL> select datediff(millisecond from timestamp '11.05.2012 17:30:18.578' to timestamp '11.05.2012 17:36:58.437') 
CON> from rdb$database;

DATEDIFF
=====================
399859
11 май 12, 17:48    [12538273]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Dimitry Sibiryakov
Member

Откуда:
Сообщений: 43664

Таблоид
даже при отключке TCP-стека, т.е. работе по XNET, ощутимо влияние этих посредников

Потому что в XNET задействована точно та же самая цепочка, что и в TCP.

Posted via ActualForum NNTP Server 1.5

11 май 12, 18:09    [12538409]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
Давно мечтал спросить, да всё как-то стеснялся.
Вот фрагмент трейса:
2012-05-25T18:15:57.8270 (1264:01F3BE6C) ATTACH_DATABASE
C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_25, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\firebird\fb25.2\bin\isql.exe:1584

2012-05-25T18:15:57.8270 (1264:01F3BE6C) START_TRANSACTION
C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_25, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\firebird\fb25.2\bin\isql.exe:1584
(TRA_266, CONCURRENCY | WAIT | READ_WRITE)

2012-05-25T18:16:02.4200 (1264:01F3BE6C) START_TRANSACTION
C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_25, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\firebird\fb25.2\bin\isql.exe:1584
(TRA_267, CONCURRENCY | WAIT | READ_WRITE)

1) Что указывается в скобках ? Почему это число всё время одинаковое во всех блоках ?
2) Можно ли снабжать неким уникальным маркером каждый блок инфы, например:
2012-05-25T18:15:57.8270 (1264:01F3BE6C) ATTACH_DATABASE (00000161)
....
2012-05-25T18:15:57.8270 (1264:01F3BE6C) START_TRANSACTION (00000162)
...
etc
25 май 12, 18:22    [12617610]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
hvlad
Member

Откуда:
Сообщений: 9237
Таблоид
1) Что указывается в скобках ? Почему это число всё время одинаковое во всех блоках ?
Идентификатор данной трейс-сессии в данном аттаче (или сервисе). Все сообщения с данным ид относятся к одному и тому же аттачу\сессии.
Теоритически, может использоваться повторно

Таблоид
2) Можно ли снабжать неким уникальным маркером каждый блок инфы
Можно, но это будет стоить немножко скорости в рантайме. Оно того не стоит, имхо.
25 май 12, 21:35    [12618318]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
hvlad
это будет стоить немножко скорости в рантайме. Оно того не стоит, имхо.
но ведь так легче ссылаться на блоки, ибо они будут однозначно идентифицированы.
Скорость в рантайме теряется и сейчас на "наладные расходы" вида отчеркивающих линий (80 знаков у "---...----" и 111 знаков у "***...***").
25 май 12, 23:36    [12618631]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
hvlad
Member

Откуда:
Сообщений: 9237
Таблоид
но ведь так легче ссылаться на блоки, ибо они будут однозначно идентифицированы.
Ничего не понял

Таблоид
Скорость в рантайме теряется и сейчас на "наладные расходы" вида отчеркивающих линий (80 знаков у "---...----" и 111 знаков у "***...***").
Лишь бы поспорить ?
Ты мерял расходы на эти линии и на конкурентный межпроцессный счётчик ?
25 май 12, 23:57    [12618680]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
hvlad
Ничего не понял
есть блоки, у которых проставлены совершенно одинаковые моменты времени в виду точности до 10 мс. Например, могут быть два одинаковых exe_trigger_finish'a с одинаковым временем (для db_level-триггера). Как их различить, когда идёт разбор полётов с коллегами (а я их устраиваю периодически :)) ? пальцем тыркать или копипастить в word и цветом выделять ?

hvlad
Ты мерял расходы на эти линии и на конкурентный межпроцессный счётчик ?
Поясни, о какой конкуренции идёт речь ? лог трейса заполняется развене одним процессом, имя которому = fbtracemgr ?
26 май 12, 00:17    [12618737]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
hvlad
Member

Откуда:
Сообщений: 9237
Таблоид
есть блоки, у которых проставлены совершенно одинаковые моменты времени в виду точности до 10 мс. Например, могут быть два одинаковых exe_trigger_finish'a с одинаковым временем (для db_level-триггера). Как их различить
Они, вообще-то, друг за другом в файле лога идут.
Можешь отличать по смещению или номеру строки, разрешаю

Да и имена у двух db-level триггеров не могут совпадать...

Таблоид
лог трейса заполняется развене одним процессом, имя которому = fbtracemgr ?
OMG

fbtracemgr
только
читает
лог
используя
сервисы

А пишут его все процессы с движком внутри - как сервер, так и embedded
26 май 12, 00:39    [12618783]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
hvlad
Можешь отличать по смещению или номеру строки, разрешаю
гы... а какое "смещение или номер строки" можно указать при публикации фрагмента трейса тут, на форуме ?
Или, допустим, я выслал своему коллеге часть трейса, начинающуюся НЕ с начала. Он тогда видит строки с совсем другими номерами, чем я.
В общем - надо таки нумеровать блоки... :-)
26 май 12, 00:45    [12618795]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Dimitry Sibiryakov
Member

Откуда:
Сообщений: 43664

Таблоид
допустим, я выслал своему коллеге часть трейса, начинающуюся НЕ с начала

Никогда не высылай обрывки логов. Чаще всего они бесполезны.

Posted via ActualForum NNTP Server 1.5

26 май 12, 00:53    [12618814]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
hvlad
Member

Откуда:
Сообщений: 9237
Таблоид
В общем - надо таки нумеровать блоки... :-)
Нумеруй, я тут при чём ?

Я не понимаю, к чему ты прицепился на этот раз ???
26 май 12, 01:04    [12618833]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
hvlad
Нумеруй, я тут при чём ?
чем нумеровать, шариковой ручкой что ли ? и что значит "я тут причем" ?! как будто кто-то еще в природе туда полезет.
hvlad
Я не понимаю, к чему ты прицепился на этот раз ???
Очень прошу: введи опцию в fbtrace.conf, что-то типа: numerate_blocks, по дефолту = false. Кому надо, включат.
26 май 12, 01:08    [12618843]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
Должен ли fbtracemgr, к которому я стучусь вот так:
%fb_25_instance_3051_home%\bin\fbtracemgr -sta -c zaudit.conf -se localhost/3051:service_mgr | mtee trc.txt
- выводить активность в базе, которая открыта в соседнем инстансе (3050):
C:\MIX\firebird\fb25>C:\MIX\firebird\fb25\bin\isql -n localhost/3050:C:\MIX\firebird\fb25\T1.FDB
Database: localhost/3050:C:\MIX\firebird\fb25\T1.FDB
SQL>
-----------
Трейс по порту 3051:
Trace session ID 13 started
2012-05-29T20:12:21.9110 (1936:020EBEB0) TRACE_INIT
SESSION_13


2012-05-29T20:12:21.9110 (1936:020EBEB0) ATTACH_DATABASE
C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_52, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\firebird\fb25\bin\isql.exe:1528

2012-05-29T20:12:21.9110 (1936:020EBEB0) START_TRANSACTION
C:\MIX\FIREBIRD\FB25\T1.FDB (ATT_52, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
C:\MIX\firebird\fb25\bin\isql.exe:1528
(TRA_368, CONCURRENCY | WAIT | READ_WRITE)
--------
29 май 12, 20:17    [12634070]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
hvlad
Member

Откуда:
Сообщений: 9237
Таблоид,

должен
29 май 12, 20:28    [12634096]     Ответить | Цитировать Сообщить модератору
 Re: fbtracemgr: разные мелкие вопросы  [new]
Таблоид
Member

Откуда:
Сообщений: 9454
Блог
hvlad,

а как сделать, чтобы "временно не мог" ? неудобно же...
29 май 12, 20:29    [12634100]     Ответить | Цитировать Сообщить модератору
Топик располагается на нескольких страницах: Ctrl  назад   1 2 3 4 5 [6] 7 8 9   вперед  Ctrl      все
Все форумы / Firebird, InterBase Ответить