| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Usenet -> c.d.o.server -> Re: SQL INSERT INTO SELECT FROM fast then slow then fast again
Sybrand Bakker <gooiditweg_at_sybrandb.verwijderdit.demon.nl> wrote in message news:<f6ura0hfcb78fg5dp0lg313q14pur6bb8m_at_4ax.com>...
> On 21 May 2004 04:50:29 -0700, info_at_thunkbox.com (John Ashton) wrote:
>
> >I have some sql running on the following:
> >Oracle9i Enterprise Edition Release 9.2.0.2.0 - 64bit Production
> >Solaris 9
> >
> >It is basically of the form:
> >INSERT into temp_table (c1, c2)
> > SELECT t1.c1, t2.c2
> > FROM tabel1 t1, table2 t2 ...
> >
> >I don't think there is a problem with the query per se as it takes
> >about 2 seconds most of the time which is fine given the amount of
> >data I have. The only interesting things about the SQL are:
> >1. insert is into a global temporary table
> >2. select looks at a date-partitioned-by-month table (with around 1.5
> >million rows per month) for record for a single date (about 55,000
> >rows)
> >
> >The problem is that this query, when run as a procedure, will
> >sometimes take about 20 minutes. While it is running, if I take the
> >same query and run it as sql, it will complete in about 2 secs! A some
> >point later (which appears to be random, normally hours later) the
> >procedure will again take 2 secs.
> >
> >Here is an extract of the TKProf when its fast:
> >call count cpu elapsed disk query current
> > rows
> >------- ------ -------- ---------- ---------- ---------- ----------
> >----------
> >Parse 1 0.00 0.00 0 0 0
> > 0
> >Execute 1 0.00 3.32 400 178362 89
> > 24
> >Fetch 0 0.00 0.00 0 0 0
> > 0
> >------- ------ -------- ---------- ---------- ---------- ----------
> >----------
> >total 2 0.00 3.32 400 178362 89
> > 24
> >
> >Misses in library cache during parse: 1
> >Optimizer goal: CHOOSE
> >Parsing user id: 33 (recursive depth: 1)
> >
> >Elapsed times include waiting on following events:
> > Event waited on Times Max. Wait Total
> >Waited
> > ---------------------------------------- Waited ----------
> >------------
> > db file sequential read 400 0.01
> > 0.50
> >
> >And when it's slow:
> >call count cpu elapsed disk query current
> > rows
> >------- ------ -------- ---------- ---------- ---------- ----------
> >----------
> >Parse 1 0.00 0.00 0 0 0
> > 0
> >Execute 1 0.00 1360.16 631 69335893 92
> > 24
> >Fetch 0 0.00 0.00 0 0 0
> > 0
> >------- ------ -------- ---------- ---------- ---------- ----------
> >----------
> >total 2 0.00 1360.16 631 69335893 92
> > 24
> >
> >Misses in library cache during parse: 1
> >Optimizer goal: CHOOSE
> >Parsing user id: 33 (recursive depth: 1)
> >
> >Elapsed times include waiting on following events:
> > Event waited on Times Max. Wait Total
> >Waited
> > ---------------------------------------- Waited ----------
> >------------
> > db file sequential read 631 0.03
> > 5.07
> > latch free 5 0.00
> > 0.00
> >
> >The 'db file sequential read' events occur on the index and data files
> >for the month partition I'm selecting.
> >
> >I am guessing there is some IO problem, maybe dues to something else
> >running on the system, but I'm not sure why the SQL query that is run
> >outside the procedure at the same time is fast. I'm also unsure of
> >where to look next for the cause of this behaviour.
> >
> >Any help would be appreciated.
>
>
> Get the explain plans and show them here.
> Other than that: CBO runs by default in ALL_ROWS mode in stored
> procedure.
> You might run in FIRST_ROWS mode in plain vanilla SQL
OK, I've been a silly boy with at least one part of this problem, but I don't know that I understand yet what is happening or if I've solved the problem.
The default optimizer mode on the system is CHOOSE. In order to
compare apples with apples bearing in mind what you said I used the
following for each session:
SQL> alter session set timed_statistics=true;
Session altered
SQL> alter session set optimizer_mode=all_rows;
Session altered
SQL> alter session set sql_trace=true;
The first run was the slow stored procedure
call count cpu elapsed disk query current
rows
Parse 1 0.01 0.00 0 0 0
0
Execute 1 1265.75 1241.28 544 63796026 97
26
Fetch 0 0.00 0.00 0 0 0
0
total 2 1265.76 1241.29 544 63796026 97
26
Misses in library cache during parse: 1
Optimizer goal: ALL_ROWS
Parsing user id: 33 (HHDC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
26 SORT GROUP BY (cr=63796025 r=542 w=0 time=112293649 us)
51 FILTER (cr=63796025 r=542 w=0 time=1219787472 us)
6657 FILTER (cr=63755064 r=68 w=0 time=1237693858 us)
6657 TABLE ACCESS BY INDEX ROWID C_CONFIGS (cr=63755064 r=68
w=0 time=1237656091 us)
49893505 NESTED LOOPS (cr=63749946 r=68 w=0 time=1203513599 us)
49879980 NESTED LOOPS (cr=13641904 r=41 w=0 time=329866638 us)
3062 NESTED LOOPS (cr=3754 r=40 w=0 time=281152 us)
3062 TABLE ACCESS BY INDEX ROWID REGISTRATIONS (cr=3752
r=40 w=0 time=226203 us)
16298 INDEX RANGE SCAN SUPP_EFF_DATE_INDX (cr=38 r=38 w=0
time=141707 us)(object id 24375)
3062 INDEX RANGE SCAN TIMETABLE_PK (cr=2 r=0 w=0 time=36850
us)(object id 24367)
49879980 TABLE ACCESS BY INDEX ROWID APPOINTMENTS (cr=13638150
r=1 w=0 time=298202897 us)
49879980 INDEX RANGE SCAN HHDC_EFF_DATE_INDX (cr=128606 r=1
w=0 time=128192237 us)(object id 24289)
13524 INDEX RANGE SCAN CC_MPAN_INDX (cr=50108042 r=27 w=0
time=715559417 us)(object id 23747)
6606 NESTED LOOPS (cr=40961 r=474 w=0 time=3163897 us) 6657 INDEX UNIQUE SCAN C_CONFIGS_PK (cr=13314 r=60 w=0 time=508707 us)(object id 23744)
6606 PARTITION RANGE SINGLE PARTITION: KEY KEY (cr=27647 r=414 w=0 time=2510684 us)
6606 TABLE ACCESS BY LOCAL INDEX ROWID READINGS PARTITION: KEY KEY (cr=27647 r=414 w=0 time=2502045 us)
6712 INDEX RANGE SCAN READINGS_PK PARTITION: KEY KEY (cr=19971 r=38 w=0 time=208676 us)(object id 25869)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: ALL_ROWS
26 SORT (GROUP BY)
51 FILTER
6657 FILTER
6657 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'C_CONFIGS'
49893505 NESTED LOOPS
49879980 NESTED LOOPS
3062 NESTED LOOPS
3062 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'REGISTRATIONS'
16298 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'SUPP_EFF_DATE_INDX' (NON-UNIQUE)
3062 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'TIMETABLE_PK' (UNIQUE)
49879980 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'APPOINTMENTS'
49879980 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'HHDC_EFF_DATE_INDX' (NON-UNIQUE)
13524 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'CC_MPAN_INDX'
(NON-UNIQUE)
6606 NESTED LOOPS
6657 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'C_CONFIGS_PK'
(UNIQUE)
6606 PARTITION RANGE (SINGLE) PARTITION:KEYKEY
6606 TABLE ACCESS GOAL: ANALYZED (BY LOCAL INDEX ROWID) OF
'READINGS' PARTITION:KEYKEY
6712 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'READINGS_PK'
(UNIQUE) PARTITION:KEYKEY
At nearly the same time, I ran the plain vanilla SQL which resulted
in:
call count cpu elapsed disk query current
rows
Parse 2 0.02 0.02 0 0 0
0
Execute 2 5.52 5.41 0 347431 84
26
Fetch 0 0.00 0.00 0 0 0
0
total 4 5.54 5.43 0 347431 84
26
Misses in library cache during parse: 1
Optimizer goal: ALL_ROWS
Parsing user id: 33 (HHDC)
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT GROUP BY (cr=173714 r=0 w=0 time=2705313 us)
51 FILTER (cr=173714 r=0 w=0 time=2704844 us)
6657 TABLE ACCESS BY INDEX ROWID APPOINTMENTS (cr=132753 r=0 w=0
time=2212306 us)
13892 NESTED LOOPS (cr=130520 r=0 w=0 time=2155119 us)
6657 NESTED LOOPS (cr=123853 r=0 w=0 time=2016435 us)
46617 NESTED LOOPS (cr=24016 r=0 w=0 time=623092 us)
1 INDEX UNIQUE SCAN TIMETABLE_PK (cr=1 r=0 w=0 time=32
us)(object id 24367)
46617 TABLE ACCESS BY INDEX ROWID C_CONFIGS (cr=24015 r=0 w=0
time=591846 us)
141651 INDEX RANGE SCAN CC_EFF_FROM_INDX (cr=124 r=0 w=0
time=167919 us)(object id 23746)
6657 TABLE ACCESS BY INDEX ROWID REGISTRATIONS (cr=99837 r=0
w=0 time=1177666 us)
61169 INDEX RANGE SCAN REGISTRATIONS_PK (cr=46704 r=0 w=0
time=714503 us)(object id 24374)
7234 INDEX RANGE SCAN APPOINTMENTS_PK (cr=6667 r=0 w=0
time=99148 us)(object id 24288)
6606 NESTED LOOPS (cr=40961 r=0 w=0 time=394974 us) 6657 INDEX UNIQUE SCAN C_CONFIGS_PK (cr=13314 r=0 w=0 time=83991 us)(object id 23744)
6606 PARTITION RANGE SINGLE PARTITION: KEY KEY (cr=27647 r=0 w=0 time=227829 us)
6606 TABLE ACCESS BY LOCAL INDEX ROWID READINGS PARTITION: KEY KEY (cr=27647 r=0 w=0 time=222298 us)
6712 INDEX RANGE SCAN READINGS_PK PARTITION: KEY KEY (cr=19971 r=0 w=0 time=136951 us)(object id 25869)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: ALL_ROWS
1 SORT (GROUP BY)
51 FILTER
6657 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'APPOINTMENTS'
13892 NESTED LOOPS
6657 NESTED LOOPS
46617 NESTED LOOPS
1 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'TIMETABLE_PK'
(UNIQUE)
46617 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'C_CONFIGS'
141651 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'CC_EFF_FROM_INDX' (NON-UNIQUE)
6657 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'REGISTRATIONS'
61169 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'REGISTRATIONS_PK' (UNIQUE)
7234 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'APPOINTMENTS_PK'
(UNIQUE)
6606 NESTED LOOPS
6657 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'C_CONFIGS_PK'
(UNIQUE)
6606 PARTITION RANGE (SINGLE) PARTITION:KEYKEY
6606 TABLE ACCESS GOAL: ANALYZED (BY LOCAL INDEX ROWID) OF
'READINGS' PARTITION:KEYKEY
6712 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'READINGS_PK'
(UNIQUE) PARTITION:KEYKEY
So the explain plans are different even with the the same optimizer
mode. I'm not sure why. OK, this could be the problem but next I
decided to recompile the stored procedure and ran it again. I was just
as quick as the plain SQL:
call count cpu elapsed disk query current
rows
Parse 1 0.00 0.00 0 0 0
0
Execute 1 2.68 2.61 0 173711 95
26
Fetch 0 0.00 0.00 0 0 0
0
total 2 2.68 2.62 0 173711 95
26
Misses in library cache during parse: 1
Optimizer goal: ALL_ROWS
Parsing user id: 33 (HHDC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
26 SORT GROUP BY (cr=173710 r=0 w=0 time=2593403 us)
51 FILTER (cr=173710 r=0 w=0 time=2592704 us)
6657 FILTER (cr=132749 r=0 w=0 time=2122169 us)
6657 TABLE ACCESS BY INDEX ROWID APPOINTMENTS (cr=132749 r=0
w=0 time=2102833 us)
13892 NESTED LOOPS (cr=130516 r=0 w=0 time=2048712 us)
6657 NESTED LOOPS (cr=123849 r=0 w=0 time=1912832 us)
46617 NESTED LOOPS (cr=24016 r=0 w=0 time=606591 us)
1 INDEX RANGE SCAN TIMETABLE_PK (cr=1 r=0 w=0 time=48
us)(object id 24367)
46617 TABLE ACCESS BY INDEX ROWID C_CONFIGS (cr=24015 r=0
w=0 time=575510 us)
141651 INDEX RANGE SCAN CC_EFF_FROM_INDX (cr=124 r=0 w=0
time=164149 us)(object id 23746)
6657 TABLE ACCESS BY INDEX ROWID REGISTRATIONS (cr=99833 r=0
w=0 time=1096349 us)
61165 INDEX RANGE SCAN REGISTRATIONS_PK (cr=46704 r=0 w=0
time=667923 us)(object id 24374)
7234 INDEX RANGE SCAN APPOINTMENTS_PK (cr=6667 r=0 w=0
time=95041 us)(object id 24288)
6606 NESTED LOOPS (cr=40961 r=0 w=0 time=378665 us) 6657 INDEX UNIQUE SCAN C_CONFIGS_PK (cr=13314 r=0 w=0 time=81114 us)(object id 23744)
6606 PARTITION RANGE SINGLE PARTITION: KEY KEY (cr=27647 r=0 w=0 time=214957 us)
6606 TABLE ACCESS BY LOCAL INDEX ROWID READINGS PARTITION: KEY KEY (cr=27647 r=0 w=0 time=209385 us)
6712 INDEX RANGE SCAN READINGS_PK PARTITION: KEY KEY (cr=19971 r=0 w=0 time=128721 us)(object id 25869)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: ALL_ROWS
26 SORT (GROUP BY)
51 FILTER
6657 FILTER
6657 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'C_CONFIGS'
13892 NESTED LOOPS
6657 NESTED LOOPS
46617 NESTED LOOPS
1 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'REGISTRATIONS'
46617 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'SUPP_EFF_DATE_INDX' (NON-UNIQUE)
141651 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'TIMETABLE_PK' (UNIQUE)
6657 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'APPOINTMENTS'
61165 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'HHDC_EFF_DATE_INDX' (NON-UNIQUE)
7234 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'CC_MPAN_INDX'
(NON-UNIQUE)
6606 NESTED LOOPS
6657 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'C_CONFIGS_PK'
(UNIQUE)
6606 PARTITION RANGE (SINGLE) PARTITION:KEYKEY
6606 TABLE ACCESS GOAL: ANALYZED (BY LOCAL INDEX ROWID) OF
'READINGS' PARTITION:KEYKEY
6712 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'READINGS_PK'
(UNIQUE) PARTITION:KEYKEY
Still seems to be the same explain plan as the slow stored procedure
but the recompile seems to have made it a lot faster. Huh? So, I
decided to take a closer look at my SQL and found a problem which may
or may not explain this:
INSERT INTO temp_valid_mcode_dates (mcode, timetable_date)
SELECT cc.mcode, t.timetable_date
FROM c_configs cc,
appointments app,
registrations regi,
timetable t
WHERE cc.checks_mrc_id IS NULL AND
cc.eff_from_msmtd <= t.timetable_date AND
cc.eff_to_msmtd >= t.timetable_date AND
t.timetable_date BETWEEN p_start_date AND p_end_date AND
app.mcode = cc.mcode AND
app.eff_from_dca <= t.timetable_date AND
app.eff_to_dca >= t.timetable_date AND
cc.mrc_id NOT IN
(SELECT dcd.mrc_id
FROM readings r, ***C_CONFIGS CC***
WHERE r.mrc_id = cc.mrc_id AND
r.utc_date = t.timetable_date AND
r.latest_reading_yn = 'Y' AND r.utc_ean <> 'N') AND
regi.mcode = cc.mcode AND
regi.eff_from_regi <= t.timetable_date AND
regi.eff_to_regi >= t.timetable_date AND
regi.participant_id = CASE WHEN p_regi = 'ANY' THEN
regi.participant_id ELSE p_regi END
GROUP BY cc.mcode, t.timetable_date
The extra c_configs table (hi-lighted with *s) in the inner select isn't needed so I removed it a recompiled the stored procedure. It seemed as quick and the TKPROF explain plan seems to bear this out:
call count cpu elapsed disk query current
rows
Parse 1 0.01 0.00 0 0 0
0
Execute 1 2.56 2.50 0 160397 97
26
Fetch 0 0.00 0.00 0 0 0
0
total 2 2.57 2.51 0 160397 97
26
Misses in library cache during parse: 1
Optimizer goal: ALL_ROWS
Parsing user id: 33 (HHDC) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
26 SORT GROUP BY (cr=160396 r=0 w=0 time=2485840 us)
51 FILTER (cr=160396 r=0 w=0 time=2485145 us)
6657 FILTER (cr=132749 r=0 w=0 time=2118376 us)
6657 TABLE ACCESS BY INDEX ROWID APPOINTMENTS (cr=132749 r=0
w=0 time=2099097 us)
13892 NESTED LOOPS (cr=130516 r=0 w=0 time=2045149 us)
6657 NESTED LOOPS (cr=123849 r=0 w=0 time=1909179 us)
46617 NESTED LOOPS (cr=24016 r=0 w=0 time=602510 us)
1 INDEX RANGE SCAN TIMETABLE_PK (cr=1 r=0 w=0 time=41
us)(object id 24367)
46617 TABLE ACCESS BY INDEX ROWID C_CONFIGS (cr=24015 r=0
w=0 time=572630 us)
141651 INDEX RANGE SCAN CC_EFF_FROM_INDX (cr=124 r=0 w=0
time=163491 us)(object id 23746)
6657 TABLE ACCESS BY INDEX ROWID REGISTRATIONS (cr=99833 r=0
w=0 time=1099344 us)
61165 INDEX RANGE SCAN REGISTRATIONS_PK (cr=46704 r=0 w=0
time=669149 us)(object id 24374)
7234 INDEX RANGE SCAN APPOINTMENTS_PK (cr=6667 r=0 w=0
time=95927 us)(object id 24288)
6606 PARTITION RANGE SINGLE PARTITION: KEY KEY (cr=27647 r=0 w=0 time=222257 us)
6606 TABLE ACCESS BY LOCAL INDEX ROWID READINGS PARTITION: KEY KEY (cr=27647 r=0 w=0 time=216552 us)
6712 INDEX RANGE SCAN READINGS_PK PARTITION: KEY KEY (cr=19971 r=0 w=0 time=134901 us)(object id 25869)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: ALL_ROWS
26 SORT (GROUP BY)
51 FILTER
6657 FILTER
6657 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'C_CONFIGS'
13892 NESTED LOOPS
6657 NESTED LOOPS
46617 NESTED LOOPS
1 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'REGISTRATIONS'
46617 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'SUPP_EFF_DATE_INDX' (NON-UNIQUE)
141651 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'TIMETABLE_PK'
(UNIQUE)
6657 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
'APPOINTMENTS'
61165 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'HHDC_EFF_DATE_INDX' (NON-UNIQUE)
7234 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'CC_MPAN_INDX'
(NON-UNIQUE)
6606 PARTITION RANGE (SINGLE) PARTITION:KEYKEY
6606 TABLE ACCESS GOAL: ANALYZED (BY LOCAL INDEX ROWID) OF
'READINGS' PARTITION:KEYKEY
6712 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'READINGS_PK'
(UNIQUE) PARTITION:KEYKEY
However the explain plan is still not the same as the plain vanilla
SQL.
Usually this re-compile fix does not last but might now the extra
table has been removed but I don't understand why.
What dumb thing have I missed now? Received on Tue May 25 2004 - 11:27:40 CDT
 |
 |