SQL tracing off causes Performance problems

Hi All,

we ran into some performance problems with our application that sends request to a data base several times (ten thousands of times), always using the exactly same bunch of SQL statements (for test purposes). After a long-term test we recognized an enormous performance decrease within our application in combination with a very huge CPU load/memory usage on the server running the data base. Therefore, we switched on the data base SQL tracing to get the
"hotspot" statement(s) and performed a retest. However, surprisedly, we could
not reproduce this behavior.
So again, switching off SQL tracing and performing a further test, we could identify two similar statements that causes this problem! So I wrote a little Java Application that connects to our data base (only one session) and performs -- within a loop -- exactly the same two statements. We could reproduce the same behavior in a long-term term test: fast, when setting SQL tracing on, an increasing slow down when tracing off.

When taking a look in view v$sqlarea (see below), we encountered some differences between the two modes: within trace off mode, the statement is loaded each time and optimizer is set to 'multiple children'; within trace on mode, the statement is loaded only once (and this should be IMHO the correct behavior)!

Hopefully someone of you can help to me solve or at least to explain this
"feature"? What could be the reasons for this strange behavior?

At the end you will find information on our current Oracle version as well as two table entries of v$sqlarea, first with trace on, second with tracing off.

--
Thanx in advance,
    Harald Jung

-----------------------------------------
Sema Group Telecoms
hjung_at_de.lhsgroup.com


select * from v$version;
BANNER
Oracle8i Enterprise Edition Release 8.1.5.0.0 - Production
PL/SQL Release 8.1.5.0.0 - Production
CORE Version 8.1.3.0.0 - Production
TNS for HPUX: Version 8.1.5.0.0 - Production
NLSRTL Version 3.4.0.0.0 - Production


These are the respective entries after flushing shared_pool and performing an
loop of 20 executions for both modes:

select * from v$sqlarea where sql_text like 'SeLect%';

1. sql_trace == true
---------------------
SQL_TEXT SeLect COUNT(*) FROM NUMBER WHERE ROWNUM <= 50 AND CODE1 = '68' AND
CODE2 = '2' AND STATUS = 'r'
SHARABLE_MEM 13609
PERSISTENT_MEM 544
RUNTIME_MEM 1800
SORTS 1
VERSION_COUNT 1
LOADED_VERSIONS 1
OPEN_VERSIONS 0
USERS_OPENING 0
EXECUTIONS 20
USERS_EXECUTING 0
LOADS 1
FIRST_LOAD_TIME 2000-08-04/11:14:23
INVALIDATIONS 0
PARSE_CALLS 20
DISK_READS 2512
BUFFER_GETS 50086
ROWS_PROCESSED 20
COMMAND_TYPE 3
OPTIMIZER_MODE CHOOSE
PARSING_USER_ID 12
PARSING_SCHEMA_ID 12
KEPT_VERSIONS 0
ADDRESS 92B91B90
HASH_VALUE 387178638
MODULE
MODULE_HASH 0
ACTION
ACTION_HASH 0
SERIALIZABLE_ABORTS 0

2. sql_trace == false
---------------------
SQL_TEXT SeLect COUNT(*) FROM NUMBER WHERE ROWNUM <= 50 AND CODE1 = '68' AND
CODE2 = '2' AND STATUS = 'r'
SHARABLE_MEM 155885
PERSISTENT_MEM 10880
RUNTIME_MEM 36000
SORTS 20
VERSION_COUNT 20
LOADED_VERSIONS 20
OPEN_VERSIONS 0
USERS_OPENING 0
EXECUTIONS 20
USERS_EXECUTING 0
LOADS 20
FIRST_LOAD_TIME 2000-08-04/11:02:18
INVALIDATIONS 0
PARSE_CALLS 20
DISK_READS 0
BUFFER_GETS 49983
ROWS_PROCESSED 20
COMMAND_TYPE 3
OPTIMIZER_MODE MULTIPLE CHILDREN PRESENT
PARSING_USER_ID 12
PARSING_SCHEMA_ID 12
KEPT_VERSIONS 0
ADDRESS 92C068A0
HASH_VALUE 387178638
MODULE
MODULE_HASH 0
ACTION
ACTION_HASH 0
SERIALIZABLE_ABORTS 0