Stored procedure, first run slow
Lennart
Here is a problem I would like some opinions on. I have a stored
procedure (I suspect that the problem exists for other procedures as
well, but I haven't verified it). First time it runs (each day) it
takes 8-10 minutes to run. If I rerun the procedure after a while it
runs in 2-4 minutes. The SP doesnt update any data itself, but of
course others do but that difference in data is irrelevant for the
problem. My first thought was that it had to do with data being
flushed from the bp first time the SP runs, and hence had to be read
from disk. But if I look at snapshots for statement it appears as if
this is not true (2 run, 1 run and diff):
Number of executions = 2
1 1
Number of compilations = 1
1 0
Worst preparation time (ms) = 2
2 0
Best preparation time (ms) = 2
2 0
Internal rows deleted = 0
0 0
Internal rows inserted = 0
0 0
Rows read = 2436952
1217676 1219276
Internal rows updated = 0
0 0
Rows written = 600530
299724 300806
Statement sorts = 64
32 32
Statement sort overflows = 0
0 0
Total sort time = 206
126 80
Buffer pool data logical reads = 1790269
894874 895395
Buffer pool data physical reads = 186221
95849 90372
Buffer pool temporary data logical reads = 1088320
543379 544941
Buffer pool temporary data physical reads = 843
398 445
Buffer pool index logical reads = 12090657
6036290 6054367
Buffer pool index physical reads = 409185
205583 203602
Buffer pool temporary index logical reads = 0
0 0
Buffer pool temporary index physical reads = 0
0 0
Total execution time (sec.ms) = 649.251017
484.815125 164.43589200000002
Total user cpu time (sec.ms) = 138.900000
65.480000 73.420000000000002
Total system cpu time (sec.ms) = 24.830000
13.320000 11.509999999999998
Data BP hitratio = 89%
89% 89%
Index BP hitratio = 96%
96% 96%
I can see that the proc was rebinded as:
call SYSPROC.REBIND_ROUTINE_PACKAGE('P','<SP>','ANY')
after runstats. Any thoughts on what might cause this behavior anyone?
Thanx
/Lennart
Serge Rielau
SQL in there that has long compile times? Or you may have statements
referring to DGTT with the same property?
Cheers
Serge
--
Serge Rielau
DB2 Solutions Development
IBM Toronto Lab
Lennart
[...]
> Not knowing much about the content. Could it be you either have dynamic
> SQL in there that has long compile times?
Hi Serge. I'm not sure what you mean, would it spend 6 minutes
compiling the statement, and would the reason be that the package is
not in the cache first time it runs? What would be the best way to
verify if this is the case? Anyhow, this morning I copied the code
from the procedure and executed it. It took 13 minutes. Looking at the
snapshot:
Number of executions = 1
Number of compilations = 1
Worst preparation time (ms) = 949
Best preparation time (ms) = 949
Internal rows deleted = 0
Internal rows inserted = 0
Rows read = 1053178
Internal rows updated = 0
Rows written = 236925
Statement sorts = 38
Statement sort overflows = 2
Total sort time = 610
Buffer pool data logical reads = 793156
Buffer pool data physical reads = 65778
Buffer pool temporary data logical reads = 441556
Buffer pool temporary data physical reads = 235
Buffer pool index logical reads = 5075870
Buffer pool index physical reads = 145582
Buffer pool temporary index logical reads = 0
Buffer pool temporary index physical reads = 0
Total execution time (sec.ms) = 723.659314
Total user cpu time (sec.ms) = 44.720000
Total system cpu time (sec.ms) = 11.400000
Statement text = select rtrim(admissionround_id)
as admissi
onround_id, type_of_check, process_state_id,
sum(nbr_of_app_in_admround) as nbr_
of_app_in_admround, sum(nbr_of_pco_in_admround) as
nbr_of_pco_in_admround from (
select b.admissionround_id, b.type_of_check, ar.process_state_id,
count(distinc
t x.person_id) as nbr_of_app_in_admround, count(*) as
nbr_of_pco_in_admround fro
m NYA.BATCH_ORDER_ELIGCR_ADMISSIONROUND B, NYA.ADMISSION_ROUND AR,
table(NYA.GET
_BM_PERSON_PCO1(B.ADMISSIONROUND_ID)) X where B.EDUCATIONORG_ID =
'VHS' and B.BA
TCH_ID = 15 and B.SUBMIT_TIME = '2008-05-21-09.59.46.555000' and
AR.ADMISSIONROU
ND_ID = B.ADMISSIONROUND_ID and B.TYPE_OF_CHECK = 1 group by
B.ADMISSIONROUND_ID
, B.TYPE_OF_CHECK, AR.PROCESS_STATE_ID union all select
b.admissionround_id, b.t
ype_of_check, ar.process_state_id, count(distinct x.person_id) as
nbr_of_app_in_
admround, count(*) as nbr_of_pco_in_admround from
NYA.BATCH_ORDER_ELIGCR_ADMISSI
ONROUND B, NYA.ADMISSION_ROUND AR,
table(NYA.GET_BM_PERSON_PCO2(B.ADMISSIONROUND
_ID)) X where B.EDUCATIONORG_ID = 'VHS' and B.BATCH_ID = 15 and
B.SUBMIT_TIME =
'2008-05-21-09.59.46.555000' and AR.ADMISSIONROUND_ID =
B.ADMISSIONROUND_ID and
B.TYPE_OF_CHECK = 2 group by B.ADMISSIONROUND_ID, B.TYPE_OF_CHECK,
AR.PROCESS_ST
ATE_ID union all select b.admissionround_id, b.type_of_check,
ar.process_state_i
d,0,0 from NYA.BATCH_ORDER_ELIGCR_ADMISSIONROUND B,
NYA.ADMISSION_ROUND AR where
B.EDUCATIONORG_ID = 'VHS' and B.BATCH_ID = 15 and B.SUBMIT_TIME =
'2008-05-21-0
9.59.46.555000' and AR.ADMISSIONROUND_ID = B.ADMISSIONROUND_ID ) Y
(admissionrou
nd_id, type_of_check, process_state_id, nbr_of_app_in_admround,
nbr_of_pco_in_ad
mround) group by admissionround_id, type_of_check, process_state_id
In a matter of minutes another go. This time it took 4.5 minutes:
Number of executions = 2
Number of compilations = 1
Worst preparation time (ms) = 949
Best preparation time (ms) = 949
Internal rows deleted = 0
Internal rows inserted = 0
Rows read = 2106350
Internal rows updated = 0
Rows written = 473849
Statement sorts = 76
Statement sort overflows = 4
Total sort time = 1170
Buffer pool data logical reads = 1586307
Buffer pool data physical reads = 123150
Buffer pool temporary data logical reads = 883101
Buffer pool temporary data physical reads = 391
Buffer pool index logical reads = 10151540
Buffer pool index physical reads = 292757
Buffer pool temporary index logical reads = 0
Buffer pool temporary index physical reads = 0
Total execution time (sec.ms) = 987.252832
Total user cpu time (sec.ms) = 83.630000
Total system cpu time (sec.ms) = 19.420000
Third run took 3.5 minutes
Fourth run 44 seconds
Fifth run 47 seconds
Sixth run 38 seconds
Seventh run 50 seconds
and so forth
>Or you may have statements
> referring to DGTT with the same property?
No the procedure does not contain any references to DGTT (See below).
I will start analyzing the code to see if it can be improved, but
right now I'm mostly interested in why it is so much slower first time
it runs.
/Lennart
CREATE PROCEDURE NYA.ELIGCR_R_0001 (IN EDUORG_ID_P CHAR(3), IN
BATCH_ID_P SMALLI
NT, IN SUBMIT_TIME_P TIMESTAMP)
BEGIN
declare C2 cursor WITH RETURN TO CLIENT for
select
rtrim(admissionround_id) as admissionround_id,
type_of_check, process_state_id,
sum(nbr_of_app_in_admround) as nbr_of_app_in_admround,
sum(nbr_of_pco_in_admround) as nbr_of_pco_in_admround
from (
select
b.admissionround_id, b.type_of_check, ar.process_state_id,
count(distinct x.person_id) as nbr_of_app_in_admround,
count(*) as nbr_of_pco_in_admround
from NYA.BATCH_ORDER_ELIGCR_ADMISSIONROUND B, NYA.ADMISSION_ROUND
AR,
table(NYA.GET_BM_PERSON_PCO1(B.ADMISSIONROUND_ID)) X
where B.EDUCATIONORG_ID = EDUORG_ID_P
and B.BATCH_ID = BATCH_ID_P
and B.SUBMIT_TIME = SUBMIT_TIME_P
and AR.ADMISSIONROUND_ID = B.ADMISSIONROUND_ID
and B.TYPE_OF_CHECK = 1
group by B.ADMISSIONROUND_ID, B.TYPE_OF_CHECK, AR.PROCESS_STATE_ID
union all
select
b.admissionround_id, b.type_of_check, ar.process_state_id,
count(distinct x.person_id) as nbr_of_app_in_admround,
count(*) as nbr_of_pco_in_admround
from NYA.BATCH_ORDER_ELIGCR_ADMISSIONROUND B, NYA.ADMISSION_ROUND
AR,
table(NYA.GET_BM_PERSON_PCO2(B.ADMISSIONROUND_ID)) X
where B.EDUCATIONORG_ID = EDUORG_ID_P
and B.BATCH_ID = BATCH_ID_P
and B.SUBMIT_TIME = SUBMIT_TIME_P
and AR.ADMISSIONROUND_ID = B.ADMISSIONROUND_ID
and B.TYPE_OF_CHECK = 2
group by B.ADMISSIONROUND_ID, B.TYPE_OF_CHECK, AR.PROCESS_STATE_ID
union all
select b.admissionround_id, b.type_of_check, ar.process_state_id,
0,0
from NYA.BATCH_ORDER_ELIGCR_ADMISSIONROUND B, NYA.ADMISSION_ROUND
AR
where B.EDUCATIONORG_ID = EDUORG_ID_P
and B.BATCH_ID = BATCH_ID_P
and B.SUBMIT_TIME = SUBMIT_TIME_P
and AR.ADMISSIONROUND_ID = B.ADMISSIONROUND_ID
) Y (admissionround_id, type_of_check, process_state_id,
nbr_of_app_in_admround, nbr_of_pco_in_admround)
group by admissionround_id, type_of_check, process_state_id
;
OPEN C2;
END @
Where the functions GET_BM_PCO1 and GET_BM_PCO2 are defined as:
CREATE FUNCTION NYA.GET_BM_PERSON_PCO1 (
ADMISSIONROUND_ID_P CHAR(10)
)
RETURNS TABLE (PERSON_ID CHAR(12))
LANGUAGE SQL
READS SQL DATA
NO EXTERNAL ACTION
DETERMINISTIC
VAR: BEGIN ATOMIC
declare last_25_exec date;
declare last_26_exec date;
declare last_27_exec date;
-- last successfull execution of 25
set last_25_exec = (
select date(max(execution_time)) from (
select execution_time
from nya.BATCH_STATE
where batch_id = 25
and state = 0
union all
values current timestamp - 100 years
) X (execution_time)
);
-- minimum (edu) last successfull execution of 26
set last_26_exec = (
select min(execution_date) from (
select educationorg_id,
date(max(execution_time)) as execution_date
from (
select x.current_educationorg_id,
x.execution_time
from nya.BATCH_STATE_LADOK x,
nya.education_org y
where x.batch_id = 26
and x.current_educationorg_id =
y.educationorg_id
and x.state = 0
and y.fetch_academic_data = 1
union all
select educationorg_id, current timestamp -
100 years
from nya.education_org
where fetch_academic_data = 1
union all
-- Om det saknas organisationer som hämtar data från Ladok så
returneras dagens
datum
select 'XXX', current timestamp
from nya.education_org
where not exists (select 1 from
nya.education_org where
fetch_academic_data = 1)
) X (educationorg_id, execution_time)
group by educationorg_id
) Y
);
-- last successfull execution of 27
set last_27_exec = (
select date(max(execution_time)) from (
select execution_time
from nya.BATCH_STATE
where batch_id = 27
and state = 0
union all
values current timestamp - 100 years
) X (execution_time)
);
RETURN
SELECT PERSON_ID FROM (
SELECT PCO.PERSON_ID, PCO.ADMISSIONROUND_ID as ADMROUND_ID
FROM (
select person_id, admissionround_id,educationorg_id,
courseoffering_id, within_program,
process_state_id,
condition, elig
from NYA.PICKED_COURSE_OFFERING y
where admissionround_id = ADMISSIONROUND_ID_P
and process_state_id = 40
and not exists (
select 1 from
nya.picked_course_offering_measure pcom,
nya.measure m
where pcom.admissionround_id =
y.admissionround_id
and pcom.courseoffering_id =
y.courseoffering_id
and pcom.educationorg_id = y.educationorg_id
and pcom.person_id = y.person_id
and pcom.within_program = y.within_program
and pcom.measure_id = m.measure_id
and pcom.admissionround_id =
m.admissionround_id
and pcom.state = 1
and m.halt_in_process_state = 1
)
) PCO
INNER JOIN NYA.COURSE_OFFERING CO
ON CO.EDUCATIONORG_ID = PCO.EDUCATIONORG_ID
AND CO.ADMISSIONROUND_ID = PCO.ADMISSIONROUND_ID
AND CO.COURSEOFFERING_ID = PCO.COURSEOFFERING_ID
INNER JOIN NYA.ADMISSION_ROUND A
ON A.ADMISSIONROUND_ID = PCO.ADMISSIONROUND_ID
INNER JOIN (
select person_id, admissionround_id, appl_date
from nya.application y
where admissionround_id = ADMISSIONROUND_ID_P
and not exists (
select 1 from nya.appl_measure am, nya.measure
m
where am.measure_id = m.measure_id
and am.admissionround_id =
m.admissionround_id
and am.state = 1
and am.person_id = y.person_id
and am.admissionround_id =
y.admissionround_id
and m.halt_in_process_state = 1
union all
select 1 from nya.appl_document_measure am,
nya.measure m
where am.measure_id = m.measure_id
and am.admissionround_id =
m.admissionround_id
and am.state = 1
and am.person_id = y.person_id
and am.admissionround_id =
y.admissionround_id
and m.halt_in_process_state = 1
union all
select 1 from nya.credential_measure cm,
nya.measure m,
nya.diploma_upsec_error due
where due.person_id = y.person_id
and due.diploma_upsec_error_id
= cm.diploma_upsec_error_id
and m.measure_id = cm.measure_id
and m.admissionround_id =
y.admissionround_id
and m.halt_in_process_state = 1
and cm.state = 1
)
) APP
ON (APP.PERSON_ID, APP.ADMISSIONROUND_ID) =
(PCO.PERSON_ID, PCO.ADMISSIONROUND_ID)
WHERE CO.CANCELDATE IS NULL
AND A.PROCESS_STATE_ID IN (20, 70)
AND CO.PROCESS_STATE_ID IN (40,50)
AND (NYA.TREATED_PCO_EXISTS(PCO.ADMISSIONROUND_ID,
PCO.PERSON_ID) = 1
OR (APP.appl_date < last_25_exec AND
APP.appl_date < last_26_exec AND
APP.appl_date < last_27_exec)
)
) X;
END @
CREATE FUNCTION NYA.GET_BM_PERSON_PCO2 (
ADMISSIONROUND_ID_P CHAR(10)
)
RETURNS TABLE (PERSON_ID CHAR(12))
LANGUAGE SQL
READS SQL DATA
NO EXTERNAL ACTION
DETERMINISTIC
RETURN
SELECT PCO.PERSON_ID
FROM (
select person_id, admissionround_id, educationorg_id,
courseoffering_id, within_program,
process_state_id,
condition, elig
from NYA.PICKED_COURSE_OFFERING y
where admissionround_id = ADMISSIONROUND_ID_P
and process_state_id = 50
and condition = 1
and elig = 11
and not exists (
select 1 from
nya.picked_course_offering_measure pcom,
nya.measure m
where pcom.admissionround_id =
y.admissionround_id
and pcom.courseoffering_id =
y.courseoffering_id
and pcom.educationorg_id = y.educationorg_id
and pcom.person_id = y.person_id
and pcom.within_program = y.within_program
and pcom.measure_id = m.measure_id
and pcom.admissionround_id =
m.admissionround_id
and pcom.state = 1
and m.halt_in_process_state = 1
)
) PCO
INNER JOIN NYA.COURSE_OFFERING CO
ON CO.EDUCATIONORG_ID = PCO.EDUCATIONORG_ID
AND CO.ADMISSIONROUND_ID = PCO.ADMISSIONROUND_ID
AND CO.COURSEOFFERING_ID = PCO.COURSEOFFERING_ID
INNER JOIN NYA.ADMISSION_ROUND A
ON A.ADMISSIONROUND_ID = PCO.ADMISSIONROUND_ID
INNER JOIN (
select person_id, admissionround_id
from nya.application y
where admissionround_id = ADMISSIONROUND_ID_P
and not exists (
select 1 from nya.appl_measure am, nya.measure
m
where am.measure_id = m.measure_id
and am.admissionround_id =
m.admissionround_id
and am.state = 1
and am.person_id = y.person_id
and am.admissionround_id =
y.admissionround_id
and m.halt_in_process_state = 1
union all
select 1 from nya.appl_document_measure am,
nya.measure m
where am.measure_id = m.measure_id
and am.admissionround_id =
m.admissionround_id
and am.state = 1
and am.person_id = y.person_id
and am.admissionround_id =
y.admissionround_id
and m.halt_in_process_state = 1
union all
select 1 from nya.credential_measure cm,
nya.measure m,
nya.diploma_upsec_error due
where due.person_id = y.person_id
and due.diploma_upsec_error_id
= cm.diploma_upsec_error_id
and m.measure_id = cm.measure_id
and m.admissionround_id =
y.admissionround_id
and m.halt_in_process_state = 1
and cm.state = 1
)
) APP
ON (APP.PERSON_ID, APP.ADMISSIONROUND_ID) =
(PCO.PERSON_ID, PCO.ADMISSIONROUND_ID)
WHERE CO.CANCELDATE IS NULL
AND A.PROCESS_STATE_ID IN (20, 70 ,80)
AND CO.PROCESS_STATE_ID IN (40, 50)
@
Serge Rielau
NYA.GET_BM_PERSON_PCO1(B.ADMISSIONROUND_ID)
But, does the number of rows read/written make any sense to you?Is it
what you woudl reasonably expect Db2 to look at or is this a sign of a
missing index?
Lennart
> How does this table function look like?
> NYA.GET_BM_PERSON_PCO1(B.ADMISSIONROUND_ID)
>
It is defined at the bottom of my previous post.
> But, does the number of rows read/written make any sense to you?Is it
> what you woudl reasonably expect Db2 to look at or is this a sign of a
> missing index?
>
Assuming there are missing index(es), Would the improvement in
execution time depend on the fact that more data is in the bufferpool
on second run, or might there be another reason?
/Lennart
Serge Rielau
> On May 30, 5:59 pm, Serge Rielau <srie...@ca.ibm.com> wrote:
>> How does this table function look like?
>> NYA.GET_BM_PERSON_PCO1(B.ADMISSIONROUND_ID)
> It is defined at the bottom of my previous post.
>> But, does the number of rows read/written make any sense to you?Is it
>> what you woudl reasonably expect Db2 to look at or is this a sign of a
>> missing index?
>>
>
> Assuming there are missing index(es), Would the improvement in
> execution time depend on the fact that more data is in the bufferpool
> on second run, or might there be another reason?
Absolutely. You should see various telltales.
One of them being the number of logical reads going up.
Also you would see CPU utilization going up with IO activity going down.
BTW. The prepare time for this query was under 1 second.
While thsi isn't fast it also means it's not teh reason fro he query
being slow.
Time to look at teh plan. You coudl also play with other optimization
levels.
E.g. optlevel 7 has soem good stuff for UNION ALL with which your query
is riddled.
Lennart
> > execution time depend on the fact that more data is in the bufferpool
> > on second run, or might there be another reason?
>
> Absolutely. You should see various telltales.
> One of them being the number of logical reads going up.
This is what puzzles me. First a snapshot
Buffer pool data logical reads = 6051710
Buffer pool data physical reads = 656833
Buffer pool temporary data logical reads = 3587244
Buffer pool temporary data physical reads = 2568
Buffer pool index logical reads = 40211260
Buffer pool index physical reads = 1461438
Total execution time (sec.ms) = 6125.973736
Total user cpu time (sec.ms) = 518.570000
Total system cpu time (sec.ms) = 84.310000
Statement text = call nya.ELIGCR_R_0001('VHS',
15,'2008-05-2
1-09.59.46.555000')
Then a run for the first time, took 9 minutes and another snapshot
Buffer pool data logical reads = 6802236
Buffer pool data physical reads = 687249
Buffer pool temporary data logical reads = 4010338
Buffer pool temporary data physical reads = 2630
Buffer pool index logical reads = 45140103
Buffer pool index physical reads = 1575870
Total execution time (sec.ms) = 6705.263263
Total user cpu time (sec.ms) = 556.250000
Total system cpu time (sec.ms) = 91.530000
Statement text = call nya.ELIGCR_R_0001('VHS',
15,'2008-05-2
1-09.59.46.555000')
Second run took 40 seconds and a snapshot
Buffer pool data logical reads = 7552732
Buffer pool data physical reads = 706233
Buffer pool temporary data logical reads = 4433396
Buffer pool temporary data physical reads = 2806
Buffer pool index logical reads = 50068675
Buffer pool index physical reads = 1662097
Total execution time (sec.ms) = 6742.886307
Total user cpu time (sec.ms) = 588.990000
Total system cpu time (sec.ms) = 95.140000
Statement text = call nya.ELIGCR_R_0001('VHS',
15,'2008-05-2
1-09.59.46.555000')
So first run has:
Buffer pool data logical reads = 6802236-6051710 = 750526
Buffer pool data physical reads = 687249-656833 = 30416
Buffer pool index logical reads = 45140103-40211260 = 4928843
Buffer pool index physical reads = 1575870-1461438=114432
And second run has:
Buffer pool data logical reads = 7552732 - 6802236 = 750496
Buffer pool data physical reads = 706233 - 687249 = 18984
Buffer pool index logical reads = 50068675 - 45140103 = 4928572
Buffer pool index physical reads = 1662097 - 1575870 = 86227
So there is indeed a difference in bp hitratio, but IMO it is not big
enough to explain 8.5 minutes difference in execution time. Feel free
to convince that I'm wrong ;-)
> Also you would see CPU utilization going up with IO activity going down.
> BTW. The prepare time for this query was under 1 second.
> While thsi isn't fast it also means it's not teh reason fro he query
> being slow.
> Time to look at teh plan. You coudl also play with other optimization
> levels.
> E.g. optlevel 7 has soem good stuff for UNION ALL with which your query
> is riddled.
>
At the moment I'm mostly concerned with the difference in execution
time, but I will look into this later
/Lennart