jvdmunt
1st June 2004, 10:43
We have two (nearly) identical systems with baan5c and oracle 8.1.7.

For the same query the reaction is difference; on system A is takes 2 minutes
(30982 rows), on system P is takes 2,5 hours (36930 rows)!

I did some investigation via tkprof. The SQL-query that ORACLE receives is on both systems equal

But the ORACLE execution plan is difference (see below)

- Why is ORACLE react difference???? and adds a MERGE JOIN CARTESIAN. Is this due "commands" oracle received from the db-driver (oracle8, equal on both systems)?

When I apply the query in SQLPLUS (without the hint /*+ FIRST_ROWS */) I face no problem (with hint I must wait 2,5 hour)

System A:

SELECT /*+ FIRST_ROWS */ a.t$drct,a.t$coun,b.t$orno,c.t$bpid,c.t$nama,
d.t$pono,d.t$otbp,d.t$item,d.t$citg,d.t$oltp,d.t$oqua,d.t$ddta,d.t$ddtb,
d.t$ddtc,d.t$ddtd,d.t$ddte,d.t$dqua,d.t$clyn,e.t$kitm,e.t$dsca,f.t$dsca
FROM
baan.ttdpur094400 a,baan.ttdpur400400 b,baan.ttccom100400 c,
baan.ttdpur401400 d,baan.ttcibd001400 e,baan.ttcmcs023400 f WHERE c.t$bpid =
b.t$otbp AND e.t$citg = f.t$citg AND e.t$kitm <> :1 AND a.t$coun = :2 AND
a.t$drct = :2 AND b.t$cotp = a.t$potp AND b.t$orno = d.t$orno AND d.t$item =
e.t$item ORDER BY 4,9,8,3,6

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 15492 5.03 51.67 5389 163519 385 30982
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 15494 5.03 51.67 5389 163519 385 30982

Misses in library cache during parse: 0
Optimizer goal: FIRST_ROWS
Parsing user id: 23

Rows Row Source Operation
------- ---------------------------------------------------
30982 SORT ORDER BY
30982 NESTED LOOPS
30983 NESTED LOOPS
32986 NESTED LOOPS
11611 NESTED LOOPS
11611 NESTED LOOPS
12688 TABLE ACCESS FULL TTDPUR400400
24297 TABLE ACCESS BY INDEX ROWID TTDPUR094400
25374 INDEX UNIQUE SCAN (object id 273756)
23220 TABLE ACCESS BY INDEX ROWID TTCCOM100400
23220 INDEX UNIQUE SCAN (object id 272999)
44595 TABLE ACCESS BY INDEX ROWID TTDPUR401400
44595 INDEX RANGE SCAN (object id 273894)
63967 TABLE ACCESS BY INDEX ROWID TTCIBD001400
65970 INDEX UNIQUE SCAN (object id 273230)
30982 TABLE ACCESS BY INDEX ROWID TTCMCS023400
61964 INDEX UNIQUE SCAN (object id 273348)

System P:

SELECT /*+ FIRST_ROWS */ a.t$drct,a.t$coun,b.t$orno,c.t$bpid,c.t$nama,
d.t$pono,d.t$otbp,d.t$item,d.t$citg,d.t$oltp,d.t$oqua,d.t$ddta,d.t$ddtb,
d.t$ddtc,d.t$ddtd,d.t$ddte,d.t$dqua,d.t$clyn,e.t$kitm,e.t$dsca,f.t$dsca
FROM
baan.ttdpur094100 a,baan.ttdpur400100 b,baan.ttccom100100 c,
baan.ttdpur401100 d,baan.ttcibd001100 e,baan.ttcmcs023100 f WHERE c.t$bpid =
b.t$otbp AND e.t$citg = f.t$citg AND e.t$kitm <> :1 AND a.t$coun = :2 AND
a.t$drct = :2 AND b.t$cotp = a.t$potp AND b.t$orno = d.t$orno AND d.t$item =
e.t$item ORDER BY 4,9,8,3,6

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.01 0 0 0 0
Fetch 18466 7862.62 7884.75 6560 892561791 381 36930
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 18468 7862.62 7884.76 6560 892561791 381 36930

Misses in library cache during parse: 1
Optimizer goal: FIRST_ROWS
Parsing user id: 22

Rows Row Source Operation
------- ---------------------------------------------------
36930 SORT ORDER BY
36930 NESTED LOOPS
344962350 NESTED LOOPS
2331488 MERGE JOIN CARTESIAN
13962 NESTED LOOPS
15207 NESTED LOOPS
4372 TABLE ACCESS FULL TTCCOM100100
19577 TABLE ACCESS BY INDEX ROWID TTDPUR400100
19577 INDEX RANGE SCAN (object id 8400)
29167 TABLE ACCESS BY INDEX ROWID TTDPUR094100
30412 INDEX UNIQUE SCAN (object id 14182)
2345448 SORT JOIN
167 TABLE ACCESS FULL TTCMCS023100
347293836 TABLE ACCESS BY INDEX ROWID TTCIBD001100
348005847 INDEX RANGE SCAN (object id 13975)
36930 TABLE ACCESS BY INDEX ROWID TTDPUR401100
344999279 INDEX RANGE SCAN (object id 147446)

dave_23
1st June 2004, 13:45
Try running compute statstistics on all of the tables for that query in the box with the bad execution plan..

Also - do both boxes have the same init.ora parameters?
are they on the exact same version (8.1.7.???)

Dave

jvdmunt
1st June 2004, 14:50
Hi Dave,

I ask for last_analyzed from dba_tab_columns, the all form 30-MAY-04.

I don't recognize parameters related to the execution plan in the init.ora (but I'am not an expert). Here are the init.ora files:

System A

$ cat initbaantest.ora |grep -v ^#|grep -v ^$|sort
background_dump_dest = /usr1/apps/oracle/admin/baantest/bdump
compatible = "8.0.5"
control_files = ("/usr1/apps/oracle/oradata/baantest/control01.ctl", "/usr1/apps
/oracle/oradata/baantest/control02.ctl", "/usr1/apps/oracle/oradata/baantest/con
trol03.ctl")
core_dump_dest = /usr1/apps/oracle/admin/baantest/cdump
db_block_buffers = 211126
db_block_size = 8192
db_name = baantest
instance_name = baantest
java_pool_size = 0
large_pool_size = 614400
log_buffer = 163840
log_checkpoint_interval = 10000
log_checkpoint_timeout = 1800
max_enabled_roles = 30
open_cursors = 10000
optimizer_max_permutations = 1500
os_authent_prefix = ""
processes = 150
service_names = baantest
shared_pool_size = 288258048
sort_area_retained_size = 65536
sort_area_size = 65536
user_dump_dest = /usr1/apps/oracle/admin/baantest/udump


SYSTEM P

$ cat initbaanprod.ora|grep -v ^#|grep -v ^$|sort
background_dump_dest = /usr1/apps/oracle/admin/baanprod/bdump
compatible = "8.0.5"
control_files = ("/usr1/apps/oracle/oradata/baanprod/control01.ctl", "/usr1/apps
/oracle/oradata/baanprod/control02.ctl", "/usr1/apps/oracle/oradata/baanprod/con
trol03.ctl")
core_dump_dest = /usr1/apps/oracle/admin/baanprod/cdump
db_block_buffers = 80960
db_block_size = 8192
db_name = "baanprod"
instance_name = baanprod
java_pool_size = 0
large_pool_size = 614400
log_buffer = 163840
log_checkpoint_interval = 10000
log_checkpoint_timeout = 1800
max_enabled_roles = 30
open_cursors = 10000
optimizer_max_permutations = 1500
os_authent_prefix = ""
processes = 150
remote_login_passwordfile = exclusive
service_names = baanprod
session_cached_cursors = 200
sessions = 500
shared_pool_size = 524288000
sort_area_retained_size = 65536
sort_area_size = 65536
user_dump_dest = /usr1/apps/oracle/admin/baanprod/udump

both systems have the same oracle version: 8.1.7.4.0

Han Brinkman
1st June 2004, 17:02
Joop,

Your second system still seems to do a full table scan in some cases (e.g. tccom100).

To make sure that the tables are analyzed can you do it manually for the tables mentioned?

btw, why does your test environment have more cache defined as your production server?

Groeten,
Han

jvdmunt
1st June 2004, 18:32
Dave, Han,

Thanks a lot for your help. I did a test with qptool6.2. It takes 0m22.26s !!!!

Two questions more:

- I use "analyze table TAABBBCCC100 estimate statistics;". Is it better to use the compute variant?
- Must this be done on a regular base for all tables? Doesn't the "baan-erp" application do this automatic?

Once again, thanks

Regards, Joop

dave_23
1st June 2004, 19:28
Hi Joop,

"Compute" is better than "estimate"
needs to be done everyonce it a while, once a month, or once a week..

Baan only estimates statistics (bare minimum) when you create a table,
so if the table changes afterwards, the DB doesn't know..

Dave

Dikkie Dik
2nd June 2004, 11:21
The Baan driver creates always the same query independent on how the database is.

When looking to the init.ora parameters the following looks weird:
- compatible flag should be set to current version of database
- on the test system db_block_buffers is (almost 3 times ) higher than prod
- on the prod system the shared_pool_size is is (2 times) higher than test

I currently have no clue why a different execution plan is generated, but as far as I can see the original query seems a very difficult query to solve anyway. The execution plans you showed are not always the execution plans taken. To find these you should run tkprof with the EXPLAIN option.

A few questions:
- Can you post the original application query?
- Is this custo and can you change it?

Another thread (http://www.baanboard.com/baanboard/showthread.php?t=14313) was finally solved by creating missing indexes. So maybe you can also check if all indexes are there. Especially on tccom100.

Hope this helps,
Dick

jvdmunt
2nd June 2004, 11:45
Hi Dick,

Thanks for your reaction.

Here a new tkprof output. With another (very faster) execution plan. So I think "analyze table TAABBBCCC100 estimate statistics;" has a positive effect on the execution plan.


TKPROF: Release 8.1.7.4.0 - Production on Wed Jun 2 10:35:42 2004

(c) Copyright 2000 Oracle Corporation. All rights reserved.

Trace file: baanprod_ora_10664.trc
Sort options: prsela exeela fchela
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

SELECT /*+ FIRST_ROWS */ a.t$drct,a.t$coun,b.t$orno,c.t$bpid,c.t$nama,
d.t$pono,d.t$otbp,d.t$item,d.t$citg,d.t$oltp,d.t$oqua,d.t$ddta,d.t$ddtb,
d.t$ddtc,d.t$ddtd,d.t$ddte,d.t$dqua,d.t$clyn,e.t$kitm,e.t$dsca,f.t$dsca
FROM
baan.ttdpur094100 a,baan.ttdpur400100 b,baan.ttccom100100 c,
baan.ttdpur401100 d,baan.ttcibd001100 e,baan.ttcmcs023100 f WHERE c.t$bpid =
b.t$otbp AND e.t$citg = f.t$citg AND e.t$kitm <> :1 AND a.t$coun = :2 AND
a.t$drct = :2 AND b.t$cotp = a.t$potp AND b.t$orno = d.t$orno AND d.t$item =
e.t$item ORDER BY 4,9,8,3,6


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 18644 6.88 16.70 6710 197623 497 37285
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 18646 6.89 16.71 6710 197623 497 37285

Misses in library cache during parse: 1
Optimizer goal: FIRST_ROWS
Parsing user id: 22

Rows Row Source Operation
------- ---------------------------------------------------
37285 SORT ORDER BY
37285 NESTED LOOPS
37286 NESTED LOOPS
39672 NESTED LOOPS
14091 NESTED LOOPS
14091 NESTED LOOPS
15346 TABLE ACCESS FULL TTDPUR400100
29435 TABLE ACCESS BY INDEX ROWID TTDPUR094100
30690 INDEX UNIQUE SCAN (object id 14182)
28180 TABLE ACCESS BY INDEX ROWID TTCCOM100100
28180 INDEX UNIQUE SCAN (object id 13302)
53761 TABLE ACCESS BY INDEX ROWID TTDPUR401100
53761 INDEX RANGE SCAN (object id 147439)
76956 TABLE ACCESS BY INDEX ROWID TTCIBD001100
79342 INDEX UNIQUE SCAN (object id 13972)
37285 TABLE ACCESS BY INDEX ROWID TTCMCS023100
74570 INDEX UNIQUE SCAN (object id 14026)

********************************************************************************

ALTER SESSION SET SQL_TRACE = true


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.01 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.01 0 0 0 0

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 22



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 2 0.00 0.01 0 0 0 0
Fetch 18644 6.88 16.70 6710 197623 497 37285
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 18647 6.89 16.72 6710 197623 497 37285

Misses in library cache during parse: 1
Misses in library cache during execute: 1


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 211 0.06 0.06 0 0 0 0
Execute 211 0.15 0.14 0 1505 175 105
Fetch 177 0.01 0.00 0 458 0 71
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 599 0.22 0.20 0 1963 175 176

Misses in library cache during parse: 5

2 user SQL statements in session.
211 internal SQL statements in session.
213 SQL statements in session.
********************************************************************************
Trace file: baanprod_ora_10664.trc
Trace file compatibility: 8.00.04
Sort options: prsela exeela fchela
1 session in tracefile.
2 user SQL statements in trace file.
211 internal SQL statements in trace file.
213 SQL statements in trace file.
7 unique SQL statements in trace file.
20554 lines in trace file.


The original SQL code comes from Crystal. But with qptool6.2 we faced the same problem. So here is the code used by qptool6.2


select
tccom100.bpid, | Business Partner
tccom100.nama, | Name
tdpur400.orno, | Purchase Order
tdpur094.drct, | Direct Delivery
tdpur094.coun, | Collect Order
tdpur401.pono, | Position Number
tdpur401.otbp, | Buy-from BP
tdpur401.item, | Item
tdpur401.citg, | Item Group
tdpur401.oltp, | Order Line Type
tdpur401.oqua, | Ordered Quantity
tdpur401.ddta, | Planned Delivery Date
tdpur401.ddtb, | Current Planned Delivery Dat
tdpur401.ddtc, | Confirmed Delivery Date
tdpur401.ddtd, | Changed Delivery Date
tdpur401.ddte, | Actual Delivery Date
tdpur401.dqua, | Delivered Quantity
tdpur401.clyn, | Canceled
tcibd001.kitm, | Item Type
tcibd001.dsca, | Description
tcmcs023.dsca | Description
from
tccom100, | Business Partners
tcibd001, | General Item Data
tcmcs023, | Item Groups
tdpur094, | Purchase Order Types
tdpur400, | Purchase Orders
tdpur401 | Purchase Order Lines
where
tccom100.bpid = tdpur400.otbp and
tcibd001.citg = tcmcs023.citg and
tcibd001.kitm <> tckitm.cost and
tdpur094.coun = tcyesno.no and
tdpur094.drct = tcyesno.no and
tdpur400.cotp = tdpur094.potp and
tdpur400.orno = tdpur401.orno and
tdpur401.item = tcibd001.item
order by
tccom100.bpid,
tdpur401.citg,
tdpur401.item,
tdpur400.orno,
tdpur401.pono


Regards, Joop

Han Brinkman
2nd June 2004, 12:10
Joop,

On our (as you probably remember as you were here) systems we schedule a compute statistics on a weekly basis via:

execute dmbs_utility.analyze_schema('BAANDB', 'COMPUTE');

Please note that this causes in very specific cases a decrease of performance!

I also noticed that you can use the hint clause already in Baan ERP 5.0 although it is not specified yet in the online help. I guess it's supported in later porting sets.

As far as I know (but tell me if I am wrong) Dikkie Dik is a colleque of you, perhaps a direct contact would speed up things. ;-)

Kind regards,
Han