Comparing Common Queries
Between Test and Production
The developers complained that their test database was so much
slower than production that they could not use it to really test whether their
batch processes would run fast enough when migrated to production. They did not
give me any particular queries to check. Instead they said that the system was
generally too slow. So, I went through a process to find SQL
statements that they had run in test and that normally run in production
and compare their run times. I thought that I would document the process that I
went through here.
First I found the top 100 queries by elapsed time on both the
test and production databases using this query:
column FORCE_MATCHING_SIGNATURE format 99999999999999999999
select FORCE_MATCHING_SIGNATURE from
(select
FORCE_MATCHING_SIGNATURE,
sum(ELAPSED_TIME_DELTA) total_elapsed
from DBA_HIST_SQLSTAT
where
FORCE_MATCHING_SIGNATURE is not null and
FORCE_MATCHING_SIGNATURE <>0
group by FORCE_MATCHING_SIGNATURE
order by total_elapsed desc)
where rownum < 101;
The output looked like this:
FORCE_MATCHING_SIGNATURE
------------------------
944718698451269965
4634961225655610267
15939251529124125793
15437049687902878835
2879196232471320459
12776764566159396624
14067042856362022182
...
Then I found the signatures that were in common between the two
lists.
insert into test_sigs values (944718698451269965);
insert into test_sigs values (4634961225655610267);
insert into test_sigs values (15939251529124125793);
...
insert into prod_sigs values (3898230136794347827);
insert into prod_sigs values (944718698451269965);
insert into prod_sigs values (11160330134321800286);
...
select * from test_sigs
intersect
select * from prod_sigs;
This led to 32 values of FORCE_MATCHING_SIGNATURE which
represented queries that ran on both test and production, except for the
possible difference in constants.
Next I looked at the overall performance of these 32 queries in
test and production using this query:
create table common_sigs
(FORCE_MATCHING_SIGNATURE number);
insert into common_sigs values (575231776450247964);
insert into common_sigs values (944718698451269965);
insert into common_sigs values (1037345866341698119);
...
select
sum(executions_delta) total_executions,
sum(ELAPSED_TIME_DELTA)/(sum(executions_delta)*1000),
sum(CPU_TIME_DELTA)/(sum(executions_delta)*1000),
sum(IOWAIT_DELTA)/(sum(executions_delta)*1000),
sum(CLWAIT_DELTA)/(sum(executions_delta)*1000),
sum(APWAIT_DELTA)/(sum(executions_delta)*1000),
sum(CCWAIT_DELTA)/(sum(executions_delta)*1000),
sum(BUFFER_GETS_DELTA)/sum(executions_delta),
sum(DISK_READS_DELTA)/sum(executions_delta),
sum(ROWS_PROCESSED_DELTA)/sum(executions_delta)
from DBA_HIST_SQLSTAT ss,common_sigs cs
where
ss.FORCE_MATCHING_SIGNATURE = cs.FORCE_MATCHING_SIGNATURE;
Here is part of the output:
TOTAL_EXECUTIONS Elapsed Average ms CPU Average ms IO Average ms
---------------- ------------------ -------------- -------------
5595295 366.185529 241.92785 59.8682797
430763 1273.75822 364.258421 1479.83294
The top line is production and the bottom is test.
This result supported the development team’s assertion that test
was slower than production. The 32 queries averaged about 3.5 times longer run
times in test than in production. Also, the time spent on I/O was about 25
times worse. I am not sure why the I/O time exceeded the elapsed time on test.
I guess it has something to do with how Oracle measures I/O time. But
clearly on average these 32 queries are much slower on test and I/O time
probably caused most of the run time difference.
After noticing this big difference between test and production I
decided to get these same sorts of performance metrics for each signature
to see if certain ones were worse than others. The query looked like this:
select
ss.FORCE_MATCHING_SIGNATURE,
sum(executions_delta) total_executions,
sum(ELAPSED_TIME_DELTA)/(sum(executions_delta)*1000),
sum(CPU_TIME_DELTA)/(sum(executions_delta)*1000),
sum(IOWAIT_DELTA)/(sum(executions_delta)*1000),
sum(CLWAIT_DELTA)/(sum(executions_delta)*1000),
sum(APWAIT_DELTA)/(sum(executions_delta)*1000),
sum(CCWAIT_DELTA)/(sum(executions_delta)*1000),
sum(BUFFER_GETS_DELTA)/sum(executions_delta),
sum(DISK_READS_DELTA)/sum(executions_delta),
sum(ROWS_PROCESSED_DELTA)/sum(executions_delta)
from DBA_HIST_SQLSTAT ss,common_sigs cs
where ss.FORCE_MATCHING_SIGNATURE = cs.FORCE_MATCHING_SIGNATURE
having
sum(executions_delta) > 0
group by
ss.FORCE_MATCHING_SIGNATURE
order by
ss.FORCE_MATCHING_SIGNATURE;
I put together the outputs from running this query on test
and production and lined the result up like this:
FORCE_MATCHING_SIGNATURE
PROD Average ms TEST Average ms
------------------------ ------------------ ------------------
575231776450247964
20268.6719 16659.4585
944718698451269965
727534.558 3456111.6 *
1037345866341698119
6640.87641 8859.53518
1080231657361448615 3611.37698 4823.62857
2879196232471320459
95723.5569 739287.601 *
2895012443099075884
687272.949 724081.946
3371400666194280661
1532797.66 761762.181
4156520416999188213 109238.997 213658.722
4634693999459450255
4923.8897 4720.16455
5447362809447709021
2875.37308 2659.5754
5698160695928381586
17139.6304 16559.1932
6260911340920427003
290069.674 421058.874 *
7412302135920006997
20039.0452 18951.6357
7723300319489155163
18045.9756 19573.4784
9153380962342466451
1661586.53 1530076.01
9196714121881881832 5.48003488 5.13169472
9347242065129163091
4360835.92 4581093.93
11140980711532357629
3042320.88 5048356.99
11160330134321800286
6868746.78 6160556.38
12212345436143033196 5189.7972 5031.30811
12776764566159396624
139150.231 614207.784 *
12936428121692179551
3563.64537 3436.59365
13637202277555795727
7360.0632 6410.02772
14067042856362022182 859.732015 771.041714
14256464986207527479
51.4042938 48.9237251
14707568089762185958
627.586095 414.14762
15001584593434987669
1287629.02 1122151.35
15437049687902878835 96014.9782 996974.876 *
16425440090840528197
48013.8912 50799.6184
16778386062441486289
29459.0089 26845.8327
17620933630628481201
51199.0511 111785.525 *
18410003796880256802 581563.611 602866.609
I put an asterisk (*) beside the six queries that were much
worse on test than production. I decided to focus on these six to get to the
bottom of the reason between the difference. Note that many of the 32 queries
ran about the same on test as prod so it really isn’t the case that everything
was slow on test.
Now that I had identified the 6 queries I wanted to look at what
they were spending their time on including both CPU and wait events. I used the
following query to use ASH to get a profile of the time spent by these queries
on both databases:
select
case SESSION_STATE
when 'WAITING' then event
else SESSION_STATE
end TIME_CATEGORY,
(count(*)*10) seconds
from DBA_HIST_ACTIVE_SESS_HISTORY
where
FORCE_MATCHING_SIGNATURE in
('944718698451269965',
'2879196232471320459',
'6260911340920427003',
'12776764566159396624',
'15437049687902878835',
'17620933630628481201')
group by SESSION_STATE,EVENT
order by seconds desc;
The profile looked like this in test:
TIME_CATEGORY
SECONDS
------------------------ -------
db file parallel read
207450
ON CPU
141010
db file sequential read
62990
direct path read
36980
direct path read temp
29240
direct path write temp 23110
The profile looked like this in production:
TIME_CATEGORY
SECONDS
------------------------ -------
ON CPU
433260
PX qref latch
64200
db file parallel read
35730
db file sequential read
14360
direct path read
12750
direct path write temp
12000
So, I/O waits dominate the time on test but not production.
Since db file parallel read and db file sequential read were the top I/O waits
for these 6 queries I used ash to see which of the 6 spent the most time on
these waits.
db file parallel read:
select
2 sql_id,
3 (count(*)*10) seconds
4 from DBA_HIST_ACTIVE_SESS_HISTORY
5 where
6 FORCE_MATCHING_SIGNATURE in
7 ('944718698451269965',
8 '2879196232471320459',
9 '6260911340920427003',
10 '12776764566159396624',
11 '15437049687902878835',
12 '17620933630628481201') and
13 event='db file parallel read'
14 group by sql_id
15 order by seconds desc;
SQL_ID SECONDS
------------- ----------
ak2wk2sjwnd34 159020
95b6t1sp7y40y 37030
brkfcwv1mqsas 11370
7rdc79drfp28a 30
db file sequential read:
select
2 sql_id,
3 (count(*)*10) seconds
4 from DBA_HIST_ACTIVE_SESS_HISTORY
5 where
6 FORCE_MATCHING_SIGNATURE in
7 ('944718698451269965',
8 '2879196232471320459',
9 '6260911340920427003',
10 '12776764566159396624',
11 '15437049687902878835',
12 '17620933630628481201') and
13 event='db file sequential read'
14 group by sql_id
15 order by seconds desc;
SQL_ID SECONDS
------------- ----------
95b6t1sp7y40y 26840
ak2wk2sjwnd34 22550
6h0km9j5bp69t 13300
brkfcwv1mqsas 170
7rdc79drfp28a 130
Two queries stood out at the top waiters on these two
events: 95b6t1sp7y40y and ak2wk2sjwnd34. Then I just ran my normal
sqlstat query for both sql_ids for both test and production to find out
when they last ran. Here is what the query looks like for ak2wk2sjwnd34:
select ss.sql_id,
ss.plan_hash_value,
sn.END_INTERVAL_TIME,
ss.executions_delta,
ELAPSED_TIME_DELTA/(executions_delta*1000) "Elapsed Average
ms",
CPU_TIME_DELTA/(executions_delta*1000) "CPU Average
ms",
IOWAIT_DELTA/(executions_delta*1000) "IO Average ms",
CLWAIT_DELTA/(executions_delta*1000) "Cluster Average
ms",
APWAIT_DELTA/(executions_delta*1000) "Application Average
ms",
CCWAIT_DELTA/(executions_delta*1000) "Concurrency Average
ms",
BUFFER_GETS_DELTA/executions_delta "Average buffer
gets",
DISK_READS_DELTA/executions_delta "Average disk
reads",
ROWS_PROCESSED_DELTA/executions_delta "Average rows
processed"
from DBA_HIST_SQLSTAT ss,DBA_HIST_SNAPSHOT sn
where ss.sql_id = 'ak2wk2sjwnd34'
and ss.snap_id=sn.snap_id
and executions_delta > 0
and ss.INSTANCE_NUMBER=sn.INSTANCE_NUMBER
order by ss.snap_id,ss.sql_id;
I found two time periods where both of these queries were
recently run on both test and production and got an AWR report for each
time period to compare them.
Here are a couple of pieces of the AWR report for the test
database:
Here are similar pieces for the production database:
What really stood out to me was that the wait events were so
different. In production the db file parallel read waits averaged around 1
millisecond and the db file sequential reads averaged under 1 ms. On test they
were 26 and 5 milliseconds, respectively. The elapsed times for
sql_ids 95b6t1sp7y40y and ak2wk2sjwnd34 were considerably longer in
test.
This is as far as my investigation went. I know that the
slowdown is most pronounced on the two queries and I know that their I/O waits
correspond to the two wait events. I am still trying to find a way to bring the
I/O times down on our test database so that it more closely matches production.
But at least I have a more narrow focus with the two top queries and the two
wait events.
