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.43589200000 002
Total user cpu time (sec.ms) = 138.900000
65.480000 73.420000000000 002
Total system cpu time (sec.ms) = 24.830000
13.320000 11.509999999999 998

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>','AN Y')

after runstats. Any thoughts on what might cause this behavior anyone?



Thanx
/Lennart

[Serge Rielau]

Re: Stored procedure, first run slow

Lennart wrote:

>
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.43589200000 002
Total user cpu time (sec.ms) = 138.900000
65.480000 73.420000000000 002
Total system cpu time (sec.ms) = 24.830000
13.320000 11.509999999999 998
>
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>','AN Y')
>
after runstats. Any thoughts on what might cause this behavior anyone?

Not knowing much about the content. Could it be you either have dynamic
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

[Serge Rielau]

Re: Stored procedure, first run slow

How does this table function look like?
NYA.GET_BM_PERS ON_PCO1(B.ADMIS SIONROUND_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?

Cheers
Serge


--
Serge Rielau
DB2 Solutions Development
IBM Toronto Lab

[Lennart]

Re: Stored procedure, first run slow

On May 30, 5:59 pm, Serge Rielau <srie...@ca.ibm .comwrote:

How does this table function look like?
NYA.GET_BM_PERS ON_PCO1(B.ADMIS SIONROUND_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

Cheers
Serge
>
--
Serge Rielau
DB2 Solutions Development
IBM Toronto Lab

[Serge Rielau]

Re: Stored procedure, first run slow

Lennart wrote:

On May 30, 5:59 pm, Serge Rielau <srie...@ca.ibm .comwrote:

>How does this table function look like?
>NYA.GET_BM_PER SON_PCO1(B.ADMI SSIONROUND_ID)

It is defined at the bottom of my previous post.

Oops.. got it

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

Cheers
Serge

--
Serge Rielau
DB2 Solutions Development
IBM Toronto Lab

[Lennart]

Re: Stored procedure, first run slow

On May 31, 8:06 am, Serge Rielau <srie...@ca.ibm .comwrote:
[...]

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.

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_00 01('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_00 01('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_00 01('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