ТаблоидIvan_Pisarevskyдело может быть не совсем в ФБ, он всего лишь прикладная программа.Ога. Только странное дело: затыки в 2 секунды всё время на одном и том же месте, после завершения одной и той же stored-функции.В общем, всё прояснилось. Позор на мою б о шку.
Одна из ХП обращалась к этой самой deterministic-функции F1 (впрочем, там могло быть обращение и к обычной ХП - см ниже), а затем выполняла несколько действий <M>, среди которых был один сверхтормознутый DML <T>.
После чего делала еще чего-то, также обращающееся к какой-то determ-функции F2.
Ну так вот: трейс при всех включенных параметрах честно показывал старт+финиш F1, затем ФБ начинал делать <M> и, разумеется, упирался в <T>. Далее происходил вызов F2 и трейс опять показывал её старт + финиш.
То, что происходило в <M>, в том числе в <T>, трейс не показывает. Минимальной "гранулой" для показа на сегодня является ХП / функция / триггер, но не отдельные стейтменты внутри этого.
Стейтменты были вне подозрений, пока не запустил трассировку этой ХП на 2.5 - там, слава богу, можно увидеть не просто "PLAN P(NATURAL)", а пусть и винегрет из планов всех стейтментов, но это по-любому хоть какая-то зацепка.
Вот DDL: 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.
set term ^;
execute block as
begin
execute statement 'drop sequence g1'; when any do begin end
end
^
set term ;^
commit;
create sequence g1;
commit;
create or alter procedure p_main returns(dts1 timestamp, n int, dts2 timestamp) as begin end;
recreate table t1(id int primary key using index pk_t1, x int, y int);
commit;
insert into t1 select gen_id(g1,1), round(45 + rand()*59, -1), rand()*30
from rdb$types,rdb$types
rows 5000;
commit;
create index t1_x on t1(x);
commit;
set term ^;
create or alter procedure p0 returns (z int) as
begin
z=1;
suspend;
end
^
create or alter procedure p1 returns (dts timestamp) as
begin
dts = 'now';
suspend;
end
^
create or alter procedure p2 returns (dts timestamp) as
begin
dts = 'now';
suspend;
end
^
create or alter procedure p_main returns(dts1 timestamp, n int, dts2 timestamp) as
begin
select dts from p1 into dts1;
with
c as(
select a.x, a.id, a.y, sum(b.y) y_acc
from t1 a
left join t1 b on a.x=b.x and a.id>=b.id
group by a.x, a.id, a.y
)
,d as(
select x, min( iif(y_acc >= x, y_acc, 999999) ) y_first_greater
from c
group by x
)
select count( distinct c.id )
from c
join d on c.x = d.x and c.y_acc <= d.y_first_greater
into n;
select dts from p2 into dts2;
suspend;
end
^
set term ;^
commit;
Запуск:
Трейс в 2.5 : 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.
2014-07-14T22:00:08.7220 (18796:0x7f9bf70e4ab8) EXECUTE_STATEMENT_START
/var/db/fb25/tmp25.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb25sc/bin/isql:7037
(TRA_40, CONCURRENCY | WAIT | READ_WRITE)
Statement 55:
-------------------------------------------------------------------------------
select * from p_main
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
PLAN (P1 NATURAL)MERGE (SORT (SORT (JOIN (D C A NATURAL, D C B INDEX (PK_T1, T1_X)))), SORT (SORT (JOIN (C A NATURAL, C B INDEX (PK_T1, T1_X)))))(P2 NATURAL)
2014-07-14T22:00:08.7220 (18796:0x7f9bf70e4ab8) EXECUTE_PROCEDURE_START
/var/db/fb25/tmp25.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb25sc/bin/isql:7037
(TRA_40, CONCURRENCY | WAIT | READ_WRITE)
Procedure P_MAIN:
2014-07-14T22:00:08.7220 (18796:0x7f9bf70e4ab8) EXECUTE_PROCEDURE_START
/var/db/fb25/tmp25.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb25sc/bin/isql:7037
(TRA_40, CONCURRENCY | WAIT | READ_WRITE)
Procedure P1:
2014-07-14T 22:00:08 .7220 (18796:0x7f9bf70e4ab8) EXECUTE_PROCEDURE_FINISH
/var/db/fb25/tmp25.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb25sc/bin/isql:7037
(TRA_40, CONCURRENCY | WAIT | READ_WRITE)
Procedure P1:
0 ms
2014-07-14T 22:00:18 .9720 (18796:0x7f9bf70e4ab8) EXECUTE_PROCEDURE_START
/var/db/fb25/tmp25.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb25sc/bin/isql:7037
(TRA_40, CONCURRENCY | WAIT | READ_WRITE)
Procedure P2:
2014-07-14T22:00:18.9730 (18796:0x7f9bf70e4ab8) EXECUTE_PROCEDURE_FINISH
/var/db/fb25/tmp25.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb25sc/bin/isql:7037
(TRA_40, CONCURRENCY | WAIT | READ_WRITE)
Procedure P2:
0 ms
2014-07-14T22:00:18.9730 (18796:0x7f9bf70e4ab8) EXECUTE_PROCEDURE_FINISH
/var/db/fb25/tmp25.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb25sc/bin/isql:7037
(TRA_40, CONCURRENCY | WAIT | READ_WRITE)
Procedure P_MAIN:
0 ms
2014-07-14T22:00:18.9730 (18796:0x7f9bf70e4ab8) EXECUTE_STATEMENT_FINISH
/var/db/fb25/tmp25.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb25sc/bin/isql:7037
(TRA_40, CONCURRENCY | WAIT | READ_WRITE)
Statement 55:
-------------------------------------------------------------------------------
select * from p_main
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
-- ЗДЕСЬ, В 2.5, ЕЩЕ МОЖНО УВИДЕТЬ НАМЁКИ НА ТО, В КУДА РЫТЬ.
-- ПУСТЬ И В ВИДЕ ВИНЕГРЕТА ИЗ ПЛАНОВ РАЗНЫХ СТЕЙТМЕНТОВ, НО ЕСТЬ ХОТЬ ЧТО-ТО!
PLAN (P1 NATURAL)MERGE (SORT (SORT (JOIN (D C A NATURAL, D C B INDEX (PK_T1, T1_X)))), SORT (SORT (JOIN (C A NATURAL, C B INDEX (PK_T1, T1_X)))))(P2 NATURAL)
1 records fetched
10250 ms, 8 read(s), 8445204 fetch(es)
Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
T1 10000 4176212
: 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.
2014-07-14T22:04:00.0380 (12075:0x7f1d1e063740) EXECUTE_STATEMENT_START
/var/db/fb30/tmp30.fdb (ATT_11, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb30trnk/bin/isql:7181
(TRA_9, CONCURRENCY | WAIT | READ_WRITE)
Statement 33:
-------------------------------------------------------------------------------
select * from p_main
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Select Expression
-> Procedure "P_MAIN" Scan
2014-07-14T22:04:00.0380 (12075:0x7f1d1e063740) EXECUTE_PROCEDURE_START
/var/db/fb30/tmp30.fdb (ATT_11, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb30trnk/bin/isql:7181
(TRA_9, CONCURRENCY | WAIT | READ_WRITE)
Procedure P_MAIN:
2014-07-14T22:04:00.0380 (12075:0x7f1d1e063740) EXECUTE_PROCEDURE_START
/var/db/fb30/tmp30.fdb (ATT_11, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb30trnk/bin/isql:7181
(TRA_9, CONCURRENCY | WAIT | READ_WRITE)
Procedure P1:
2014-07-14T 22:04:00 .0380 (12075:0x7f1d1e063740) EXECUTE_PROCEDURE_FINISH
/var/db/fb30/tmp30.fdb (ATT_11, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb30trnk/bin/isql:7181
(TRA_9, CONCURRENCY | WAIT | READ_WRITE)
Procedure P1:
0 ms
2014-07-14T 22:04:10 .8640 (12075:0x7f1d1e063740) EXECUTE_PROCEDURE_START
/var/db/fb30/tmp30.fdb (ATT_11, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb30trnk/bin/isql:7181
(TRA_9, CONCURRENCY | WAIT | READ_WRITE)
Procedure P2:
2014-07-14T22:04:10.8650 (12075:0x7f1d1e063740) EXECUTE_PROCEDURE_FINISH
/var/db/fb30/tmp30.fdb (ATT_11, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb30trnk/bin/isql:7181
(TRA_9, CONCURRENCY | WAIT | READ_WRITE)
Procedure P2:
0 ms
2014-07-14T22:04:10.8650 (12075:0x7f1d1e063740) EXECUTE_PROCEDURE_FINISH
/var/db/fb30/tmp30.fdb (ATT_11, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb30trnk/bin/isql:7181
(TRA_9, CONCURRENCY | WAIT | READ_WRITE)
Procedure P_MAIN:
0 ms
2014-07-14T22:04:10.8650 (12075:0x7f1d1e063740) EXECUTE_STATEMENT_FINISH
/var/db/fb30/tmp30.fdb (ATT_11, SYSDBA:NONE, NONE, TCPv4:127.0.0.1)
/opt/fb30trnk/bin/isql:7181
(TRA_9, CONCURRENCY | WAIT | READ_WRITE)
Statement 33:
-------------------------------------------------------------------------------
select * from p_main
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Select Expression
-> Procedure "P_MAIN" Scan -- А В 3.0 - СПЛОШНОЕ ИЗДЕВАТЕЛЬСТВО. ВЫСШЕЙ ПРОБЫ :-)
1 records fetched
10826 ms , 8 read(s), 8445206 fetch(es)
Table Natural Index Update Insert Delete Backout Purge Expunge
***************************************************************************************************************
T1 10000 4176212
ЗЫ. 2 dimitr : отсутствие в 3.0 показа планов всех выполнявшихся внутри модуля стейтментов - может, и не зло. А вот отсутствие даже возможности включить их показ - Центр Мирового Зла. Потеря времени при поиске источника проблемы обеспечена. Как и трёхэтажная ругань тех, кто еще этого не знает.
Либо надо научить трейс выталкивать статистику до уровня отдельных стейтментов внутри модулей. |
