Jan 15, 2012

Making Quickpay faster

For years we know that quickpay is not the fastest payroll process, and we pointed to the wait time of the concurrent manager.

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.