Subject Re: [firebird-support] Re: Query is running slowly for the first time.
Author Thomas Steinmaurer
Hello,

> Thank you Tomas for your interest.
>
> 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?
>> * What's the execution plan?
>
> Here are the details for first and second execution of the query:
>
> 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).

Ah, alright. Thought so. It has been discovered (and discussed a few
weeks/months? ago) that preparing a query on largish tables can take a
quite some time. I can't recall the outcome of the discussion at the
moment, but I think the recommendation is to strictly use prepared
queries and re-use them and/or have some sort of a prepared statement
cache at the client-side.


> 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.

Quite some physical I/O (43540 reads) and a bunch of indexed reads, so
basically to get your result set, a lot of access is going through the
index, possibly randomly seeking the disk head to read index pages from
disk, also due to a very small (non-existent) page cache. See my comment
after the header page below.


> 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.

Taking your corrected second email into account, prepare time is 0, thus
your second run is based on an already prepared statement. The same
indexed reads but less execution time. Although you have a very small
page cache, OS file system cache probably thus its job here.



>> * 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*

Page buffers is 0, so the default comes out of firebird.conf, which
basically is 75 for your used architecture (Classic). That's way LOW.

In Classic, max. RAM usage for the Firebird page cache *per database* is
calculated as:

<page buffers> * <page size> * <number of connections>

Due to the <number of connections> variable, you have to be careful to
not get into a scenario where the OS starts swapping to disk due to
exhausted RAM usage.

With Classic and SuperClassic, although I don't know your available RAM,
you could try using a page buffers value of e.g. 2048 and see if this
changes previously physical I/O intensive operations.

E.g. you can use gfix to set page buffers.


Another questionable setting is a page size of 4K. Especially with your
huge table, my chrystal ball tells me, that indexes on that table might
have an index depth > 3, which is not good. Run gstat -r -i and check
out the index depth. You can also send me the output privately, if you like.

Increasing the page size will reduce the index depth for largish
indexes. Changing the page size can be done via a backup/restore cycle
with gbak.


>> * What Firebird architecture do you use?
>
> Firebird 2.5.1 Classic
>
>> * Did you adjust anything in firebird.conf in respect to RAM usage for
>> in-memory sorting?
>
> Nothing.

;-).

In respect to available RAM, you also might consider changing RAM usage
for an in-memory sort. Check out the TempCacheLimit parameter in
firebird.conf.

Again, be careful when increasing RAM-oriented settings with Classic!

I have an excel sheet, which calculates the approx. RAM usage based on
different settings and environment pre-requisites. So, if you tell me
the following variables:

RAM available for Firebird
Number of Firebird server instances
AVG number of databases per Firebird server instance
Approx. AVG number of connections per database

I can run that through my various formulas.

>> * 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 ; ^

If you can't get an acceptable performance with your on-the-fly
aggregation, aggregate tables might be a serious path to investigate.
Have been using that in an OLAP database with success.


> 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.

Or unpreparing the query and/or disconneting in case of Classic to purge
the local per-connection page cache.



--
With regards,
Thomas Steinmaurer (^TS^)
Firebird Technology Evangelist

http://www.upscene.com/

Do you care about the future of Firebird? Join the Firebird Foundation:
http://www.firebirdsql.org/en/firebird-foundation/