But we had a closer look, and saw that even an empty Quickpay took always at least 5 seconds, excluding the time doing nothing in a concurrent queue. A sql trace file was generated at concurrent program level.
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 151 0.00 0.00 0 0 0 0
Execute 760 0.06 0.07 2 110 115 112
Fetch 663 0.08 0.07 0 7926 0 1317
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1574 0.16 0.16 2 8036 115 1429
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 837 0.00 0.00
SQL*Net message from client 837 5.00 5.08
asynch descriptor resize 13 0.00 0.00
Disk file operations I/O 2 0.00 0.00
SQL*Net more data from client 8 0.00 0.00
SQL*Net more data to client 17 0.00 0.00
log file sync 12 0.02 0.04
utl_file I/O 22 0.00 0.00
db file sequential read 2 0.00 0.00
The totals show clearly that the sql part needed only 0.16 seconds, while the wait event “Sql*net message from client” took in total 5.08 seconds, where there was a max wait of 5 seconds. We see this line in the raw tracefile that corresponds with that maximum wait:
WAIT #0: nam='SQL*Net message from client' ela= 5001949 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1304197240453556
That wait event indicates that the database is waiting (doing nothing) for a next sql statement to process. During that time, the client application must be busy performing other non-database, non-sql related activities. The client over here is the pyugen pro*C program, that executes the concurrent program of the Quickpay. We do not have access to the source code of that pro*C program. So it was time to call support, and a few weeks later patch 12565924 was released.
