Subject | Re: Query is running slowly for the first time. |
---|---|
Author | un_spoken |
Post date | 2012-10-09T08:23:01Z |
Thank you Tomas for your interest.
Here are the answers for your questions, if you need anything more - just let me know.
FIRST:
Starting transaction...
Preparing statement: SELECT r.ID_SHEDULEVERSION, r.RECORD_ID, r.RECORD_TIME, r.RECORD_ACTIVE
FROM SHEDULEVERSION r
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDVER(r.ID_SHEDULEVERSION) ON 1= 1
WHERE r.RECORD_ACTIVE = 1 AND R.STARTDATE >= '01.05.2012' AND R.STOPDATE <= '09.05.2012'
Statement prepared (elapsed time: 18.274s).
Field #01: SHEDULEVERSION.ID_SHEDULEVERSION Alias:ID_SHEDULEVERSION Type:INTEGER
Field #02: SHEDULEVERSION.RECORD_ID Alias:RECORD_ID Type:INTEGER
Field #03: SHEDULEVERSION.RECORD_TIME Alias:RECORD_TIME Type:TIMESTAMP
Field #04: SHEDULEVERSION.RECORD_ACTIVE Alias:RECORD_ACTIVE Type:INTEGER
PLAN JOIN (R INDEX (IDX_SHEDULEVERSION1), JOIN (S INDEX (IDX_SHEDULE_IDUPPER, IDX_SHEDULE_RA_SHD_VER), CALC_TASKS_STATS_FOR_SHEDULE NATURAL))
Executing statement...
Statement executed (elapsed time: 0.000s).
854984 fetches, 4 marks, 43540 reads, 4 writes.
0 inserts, 0 updates, 0 deletes, 375487 index, 2964 seq.
Delta memory: 404264 bytes.
Total execution time: 0:01:13 (hh:mm:ss)
Script execution finished.
SECOND:
Starting transaction...
Preparing statement: SELECT r.ID_SHEDULEVERSION, r.RECORD_ID, r.RECORD_TIME, r.RECORD_ACTIVE
FROM SHEDULEVERSION r
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDVER(r.ID_SHEDULEVERSION) ON 1= 1
WHERE r.RECORD_ACTIVE = 1 AND R.STARTDATE >= '01.05.2012' AND R.STOPDATE <= '09.05.2012'
Statement prepared (elapsed time: 18.274s).
Field #01: SHEDULEVERSION.ID_SHEDULEVERSION Alias:ID_SHEDULEVERSION Type:INTEGER
Field #02: SHEDULEVERSION.RECORD_ID Alias:RECORD_ID Type:INTEGER
Field #03: SHEDULEVERSION.RECORD_TIME Alias:RECORD_TIME Type:TIMESTAMP
Field #04: SHEDULEVERSION.RECORD_ACTIVE Alias:RECORD_ACTIVE Type:INTEGER
PLAN JOIN (R INDEX (IDX_SHEDULEVERSION1), JOIN (S INDEX (IDX_SHEDULE_IDUPPER, IDX_SHEDULE_RA_SHD_VER), CALC_TASKS_STATS_FOR_SHEDULE NATURAL))
Executing statement...
Statement executed (elapsed time: 0.000s).
854984 fetches, 4 marks, 43540 reads, 4 writes.
0 inserts, 0 updates, 0 deletes, 375487 index, 2964 seq.
Delta memory: 404264 bytes.
Total execution time: 0:01:13 (hh:mm:ss)
Script execution finished.
Database header page information:
Flags 0
Checksum 12345
Generation 2382
Page size 4096
ODS version 11.2
Oldest transaction 2366
Oldest active 2367
Oldest snapshot 2367
Next transaction 2370
Bumped transaction 1
Sequence number 0
Next attachment ID 6
Implementation ID 16
Shadow count 0
Page buffers 0
Next header page 0
Database dialect 3
Creation date Jul 10, 2012 12:53:19
Attributes force write
Variable header data:
Sweep interval: 20000
*END*
SELECT r.ID_SHEDULEVERSION, r.RECORD_ID, r.RECORD_TIME, r.RECORD_ACTIVE
FROM SHEDULEVERSION r
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDVER(r.ID_SHEDULEVERSION) ON 1= 1
WHERE r.RECORD_ACTIVE = 1 AND R.STARTDATE >= '01.05.2012' AND R.STOPDATE <= '09.05.2012'
As you see it usues procedure CALC_TASKS_STATS_FOR_SHEDVER.
SET TERM ^ ;
ALTER PROCEDURE CALC_TASKS_STATS_FOR_SHEDVER (
P_ID_SHEDULEVERSION INTEGER )
RETURNS (
TASK_COUNT INTEGER,
UNIT_COUNT DECIMAL(18,4) )
AS
BEGIN
SELECT SUM(CALC_TASKS_STATS_FOR_SHEDULE.TASK_COUNT), SUM(CALC_TASKS_STATS_FOR_SHEDULE.UNIT_COUNT)
FROM SHEDULE S
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDULE(S.ID_SHEDULE) ON 1=1
WHERE S.RECORD_ACTIVE = 1 AND S.IDUPPER = -1 AND S.IDSHEDULEVERSION = :P_ID_SHEDULEVERSION
INTO TASK_COUNT, UNIT_COUNT;
SUSPEND;
END^
SET TERM ; ^
And this procedure, uses procedure CALC_TASKS_STATS_FOR_SHEDULE.
The last procedure is a bit tricky, it is recursive procedure because table SHEDULE is designed as a tree. I need to move downwards that tree from a given node. To each node might be connected on or more rows from table TASK.
SET TERM ^ ;
ALTER PROCEDURE CALC_TASKS_STATS_FOR_SHEDULE (
P_ID_SHEDULE INTEGER )
RETURNS (
TASK_COUNT INTEGER,
UNIT_COUNT DECIMAL(18,4),
HAS_CHILD_NODES INTEGER )
AS
BEGIN
SELECT SUM(A.TASK_COUNT), SUM(COALESCE(A.UNIT_COUNT,0)), (CASE WHEN (SUM(A.HAS_CHILD_NODES) = 0) THEN 0 ELSE 1 END) HAS_CHILD_NODES FROM
(
SELECT COUNT(*) TASK_COUNT, SUM(COALESCE(T.UNITCOUNT, 0)) UNIT_COUNT, 0 HAS_CHILD_NODES FROM TASK T
WHERE T.RECORD_ACTIVE = 1 AND T.IDSHEDULE = :P_ID_SHEDULE
UNION
SELECT CALC_TASKS_STATS_FOR_SHEDULE.TASK_COUNT, COALESCE(CALC_TASKS_STATS_FOR_SHEDULE.UNIT_COUNT, 0), (CASE WHEN S.ID_SHEDULE IS NULL THEN 0 ELSE 1 END) HAS_CHILD_NODES
FROM SHEDULE S
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDULE(S.ID_SHEDULE) ON 1=1
WHERE S.RECORD_ACTIVE = 1 AND S.IDUPPER = :P_ID_SHEDULE
) A
INTO TASK_COUNT, UNIT_COUNT, HAS_CHILD_NODES;
SUSPEND;
END^
SET TERM ; ^
I need to mention that the second execution time of the query is fully acceptable for me. Maybe my queries are not optimal but they are working fine for the second time.
What is interesing: I need to restart my machine to recreate the slow execution time.
Thank you for your help.
Here are the answers for your questions, if you need anything more - just let me know.
> * How long does it take to only prepare the query and not executing?Here are the details for first and second execution of the query:
> * What's the execution plan?
FIRST:
Starting transaction...
Preparing statement: SELECT r.ID_SHEDULEVERSION, r.RECORD_ID, r.RECORD_TIME, r.RECORD_ACTIVE
FROM SHEDULEVERSION r
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDVER(r.ID_SHEDULEVERSION) ON 1= 1
WHERE r.RECORD_ACTIVE = 1 AND R.STARTDATE >= '01.05.2012' AND R.STOPDATE <= '09.05.2012'
Statement prepared (elapsed time: 18.274s).
Field #01: SHEDULEVERSION.ID_SHEDULEVERSION Alias:ID_SHEDULEVERSION Type:INTEGER
Field #02: SHEDULEVERSION.RECORD_ID Alias:RECORD_ID Type:INTEGER
Field #03: SHEDULEVERSION.RECORD_TIME Alias:RECORD_TIME Type:TIMESTAMP
Field #04: SHEDULEVERSION.RECORD_ACTIVE Alias:RECORD_ACTIVE Type:INTEGER
PLAN JOIN (R INDEX (IDX_SHEDULEVERSION1), JOIN (S INDEX (IDX_SHEDULE_IDUPPER, IDX_SHEDULE_RA_SHD_VER), CALC_TASKS_STATS_FOR_SHEDULE NATURAL))
Executing statement...
Statement executed (elapsed time: 0.000s).
854984 fetches, 4 marks, 43540 reads, 4 writes.
0 inserts, 0 updates, 0 deletes, 375487 index, 2964 seq.
Delta memory: 404264 bytes.
Total execution time: 0:01:13 (hh:mm:ss)
Script execution finished.
SECOND:
Starting transaction...
Preparing statement: SELECT r.ID_SHEDULEVERSION, r.RECORD_ID, r.RECORD_TIME, r.RECORD_ACTIVE
FROM SHEDULEVERSION r
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDVER(r.ID_SHEDULEVERSION) ON 1= 1
WHERE r.RECORD_ACTIVE = 1 AND R.STARTDATE >= '01.05.2012' AND R.STOPDATE <= '09.05.2012'
Statement prepared (elapsed time: 18.274s).
Field #01: SHEDULEVERSION.ID_SHEDULEVERSION Alias:ID_SHEDULEVERSION Type:INTEGER
Field #02: SHEDULEVERSION.RECORD_ID Alias:RECORD_ID Type:INTEGER
Field #03: SHEDULEVERSION.RECORD_TIME Alias:RECORD_TIME Type:TIMESTAMP
Field #04: SHEDULEVERSION.RECORD_ACTIVE Alias:RECORD_ACTIVE Type:INTEGER
PLAN JOIN (R INDEX (IDX_SHEDULEVERSION1), JOIN (S INDEX (IDX_SHEDULE_IDUPPER, IDX_SHEDULE_RA_SHD_VER), CALC_TASKS_STATS_FOR_SHEDULE NATURAL))
Executing statement...
Statement executed (elapsed time: 0.000s).
854984 fetches, 4 marks, 43540 reads, 4 writes.
0 inserts, 0 updates, 0 deletes, 375487 index, 2964 seq.
Delta memory: 404264 bytes.
Total execution time: 0:01:13 (hh:mm:ss)
Script execution finished.
> * What's the page buffers value of your database (run gstat -h)?Database "D:\TESTS\#3004\Baza\777\777.FDB"
Database header page information:
Flags 0
Checksum 12345
Generation 2382
Page size 4096
ODS version 11.2
Oldest transaction 2366
Oldest active 2367
Oldest snapshot 2367
Next transaction 2370
Bumped transaction 1
Sequence number 0
Next attachment ID 6
Implementation ID 16
Shadow count 0
Page buffers 0
Next header page 0
Database dialect 3
Creation date Jul 10, 2012 12:53:19
Attributes force write
Variable header data:
Sweep interval: 20000
*END*
> * What Firebird architecture do you use?Firebird 2.5.1 Classic
> * Did you adjust anything in firebird.conf in respect to RAM usage forNothing.
> in-memory sorting?
> * I guess we need to see your stored procedure in more detail ...This is the original query:
SELECT r.ID_SHEDULEVERSION, r.RECORD_ID, r.RECORD_TIME, r.RECORD_ACTIVE
FROM SHEDULEVERSION r
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDVER(r.ID_SHEDULEVERSION) ON 1= 1
WHERE r.RECORD_ACTIVE = 1 AND R.STARTDATE >= '01.05.2012' AND R.STOPDATE <= '09.05.2012'
As you see it usues procedure CALC_TASKS_STATS_FOR_SHEDVER.
SET TERM ^ ;
ALTER PROCEDURE CALC_TASKS_STATS_FOR_SHEDVER (
P_ID_SHEDULEVERSION INTEGER )
RETURNS (
TASK_COUNT INTEGER,
UNIT_COUNT DECIMAL(18,4) )
AS
BEGIN
SELECT SUM(CALC_TASKS_STATS_FOR_SHEDULE.TASK_COUNT), SUM(CALC_TASKS_STATS_FOR_SHEDULE.UNIT_COUNT)
FROM SHEDULE S
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDULE(S.ID_SHEDULE) ON 1=1
WHERE S.RECORD_ACTIVE = 1 AND S.IDUPPER = -1 AND S.IDSHEDULEVERSION = :P_ID_SHEDULEVERSION
INTO TASK_COUNT, UNIT_COUNT;
SUSPEND;
END^
SET TERM ; ^
And this procedure, uses procedure CALC_TASKS_STATS_FOR_SHEDULE.
The last procedure is a bit tricky, it is recursive procedure because table SHEDULE is designed as a tree. I need to move downwards that tree from a given node. To each node might be connected on or more rows from table TASK.
SET TERM ^ ;
ALTER PROCEDURE CALC_TASKS_STATS_FOR_SHEDULE (
P_ID_SHEDULE INTEGER )
RETURNS (
TASK_COUNT INTEGER,
UNIT_COUNT DECIMAL(18,4),
HAS_CHILD_NODES INTEGER )
AS
BEGIN
SELECT SUM(A.TASK_COUNT), SUM(COALESCE(A.UNIT_COUNT,0)), (CASE WHEN (SUM(A.HAS_CHILD_NODES) = 0) THEN 0 ELSE 1 END) HAS_CHILD_NODES FROM
(
SELECT COUNT(*) TASK_COUNT, SUM(COALESCE(T.UNITCOUNT, 0)) UNIT_COUNT, 0 HAS_CHILD_NODES FROM TASK T
WHERE T.RECORD_ACTIVE = 1 AND T.IDSHEDULE = :P_ID_SHEDULE
UNION
SELECT CALC_TASKS_STATS_FOR_SHEDULE.TASK_COUNT, COALESCE(CALC_TASKS_STATS_FOR_SHEDULE.UNIT_COUNT, 0), (CASE WHEN S.ID_SHEDULE IS NULL THEN 0 ELSE 1 END) HAS_CHILD_NODES
FROM SHEDULE S
LEFT JOIN CALC_TASKS_STATS_FOR_SHEDULE(S.ID_SHEDULE) ON 1=1
WHERE S.RECORD_ACTIVE = 1 AND S.IDUPPER = :P_ID_SHEDULE
) A
INTO TASK_COUNT, UNIT_COUNT, HAS_CHILD_NODES;
SUSPEND;
END^
SET TERM ; ^
I need to mention that the second execution time of the query is fully acceptable for me. Maybe my queries are not optimal but they are working fine for the second time.
What is interesing: I need to restart my machine to recreate the slow execution time.
Thank you for your help.