Friday, February 27, 2009

Performance Benefits of ReUse Statement Flag in Application Engine

I have achieved some significant performance improvements in some Application Engine programs by just enabling the ReUse Statement flag on certain steps. I thought I would share a recent example of how effective this can be. I don't think I can improve on the description of this feature in PeopleBooks: 
"One of the key performance features of PeopleSoft Application Engine is the ability to reuse SQL statements by dedicating a persistent cursor to that statement. Unless you select the ReUse property for a SQL action, %BIND fields are substituted with literal values in the SQL statement. The database has to recompile the statement every time it is executed. However, selecting ReUse converts any %BIND fields into real bind variables (:1, :2, and so on), enabling PeopleSoft Application Engine to compile the statement once, dedicate a cursor, and re-execute it with new data multiple times. This reduction in compile time can result in dramatic improvements to performance. In addition, some databases have SQL statement caching. Every time they receive SQL, they compare it against their cache of previously executed statements to see if they have seen it before. If so, they can reuse the old query plan. This works only if the SQL text matches exactly. This is unlikely with literals instead of bind variables." 
In fact, most databases do this, and Oracle certainly does. 
On Oracle, you could enable CURSOR_SHARING. Then Oracle effectively replaces the literals with bind variables at parse time. However, I certainly would not recommend doing this database-wide. Whenever I have tried this on a PeopleSoft system, it has had severe negative effects elsewhere. I have enabled cursor sharing at session level for specific batch programs (using a trigger), but even then it is not always beneficial. 
Instead, I do recommend using the ReUse Statement flag wherever possible. It cannot just be turned on indiscriminately, the same section in PeopleBooks goes on to describe some limitations (which is probably why the default value for the flag is false). To illustrate the kind of improvement you can obtain, here is a real-life example. 
This is an extract from the batch timings report at the end of the Application Engine trace file. We are interested in statements with the high compile count. ReUse Statement is not enabled on these 4 steps. They account for more that 50% of the overall execution time.
                          PeopleSoft Application Engine Timings
                              (All timings in seconds)

        C o m p i l e    E x e c u t e    F e t c h        Total
SQL Statement                  Count   Time     Count   Time     Count   Time     Time
------------------------------ ------- -------- ------- -------- ------- -------- --------
99XxxXxx.Step02.S                 8453      2.8    8453    685.6       0      0.0    688.4
99XxxXxx.Step03.S                 8453      5.0    8453   2718.8       0      0.0   2723.8
99XxxXxx.Step05.S                 8453      0.9    8453    888.4       0      0.0    889.3
99XxxXxx.Step06.S                 8453      0.4    8453     17.4       0      0.0     17.8

------------------------------------------------------------------------------------------
Total run time                :     8416.4
Total time in application SQL :     8195.0   Percent time in application SQL :       97.4%
Total time in PeopleCode      :      192.7   Percent time in PeopleCode      :        2.3%
Total time in cache           :        8.7   Number of calls to cache        :       8542
------------------------------------------------------------------------------------------
Now, I have enabled ReUse Statement on these steps. I have not changed anything else.
                         C o m p i l e    E x e c u t e    F e t c h        Total
SQL Statement                  Count   Time     Count   Time     Count   Time     Time
------------------------------ ------- -------- ------- -------- ------- -------- --------
99XxxXxx.Step02.S                    1      0.0    8453    342.3       0      0.0    342.3
99XxxXxx.Step03.S                    1      0.0    8453     83.3       0      0.0     83.3
99XxxXxx.Step05.S                    1      0.0    8453      8.7       0      0.0      8.7
99XxxXxx.Step06.S                    1      0.0    8453      7.6       0      0.0      7.6
------------------------------------------------------------------------------------------
Total run time                :     5534.1
Total time in application SQL :     5341.7   Percent time in application SQL :       96.5%
Total time in PeopleCode      :      190.8   Percent time in PeopleCode      :        3.4%
Total time in cache           :        1.1   Number of calls to cache        :         90
------------------------------------------------------------------------------------------
Notice that:
  • The number of compilations for each step has gone down to 1, though the number of executions remains the same
  • The execution time for the first three statements has fallen by nearly 90%.
  • The improvement in the 4th statement is quite modest because it did not contain any bind variables, but clearly, some of the time reported as execution time by Application Engine is associated with the preparation of a new SQL statement.
To emphasise the point, lets look at the effect on the database. The following are extracts from the TKPROF output for Oracle SQL trace files for these processes. First the TKPROF without ReUse Statement:
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   101063   2600.60    2602.83       6197     661559          4           0
Execute 101232   1817.96    3787.17    1572333   73729207   10617830     4770112
Fetch    96186    385.41    1101.47     374425   25986600          0       96285
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   298481   4803.97    7491.48    1952955  100377366   10617834     4866397

Misses in library cache during parse: 25498
Misses in library cache during execute: 90

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
db file sequential read                   1199472        0.36       2601.83
SQL*Net message from client                130345        1.57        296.50
db file scattered read                       8816        0.39        171.47

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   100002     13.51      13.57         17        820         94           0
Execute 131495     30.00      31.31       7025      29277      21164       74315
Fetch   141837    218.77     295.49     159969    3039304         12      519406
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   373334    262.28     340.38     167011    3069401      21270      593721

160446  user  SQL statements in session.
70478  internal SQL statements in session.
230924  SQL statements in session.
And now with ReUse Statement set on only those four steps
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    67238     10.24      10.75         47       4415          9           0
Execute 101160   1650.25    4040.88    1766325  129765633   11160830     4781797
Fetch    96123    385.50    1024.50     372737   26097251          0      103844
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   264521   2045.99    5076.14    2139109  155867299   11160839     4885641

Misses in library cache during parse: 73
Misses in library cache during execute: 21

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
db file sequential read                   1506834        0.61       2839.19
SQL*Net message from client                130312        1.53        258.81
db file scattered read                       8782        0.37        147.01

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     1331      0.46       0.46          0        173         16           0
Execute   4044      2.72       5.82      12923      33374      24353      113323
Fetch     5697      8.38      13.43      15550      55431         12       13449
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    11072     11.56      19.72      28473      88978      24381      126772

67425  user  SQL statements in session.
3154  internal SQL statements in session.
70579  SQL statements in session.
  • Nearly all the saving is in parse time of non-recursive statements, the rest is the reduction of recursive SQL because there is less parsing.
  • There is less parsing because there are fewer different SQL statements submitted by Application Engine. The number of user statements has fallen from 160446 to 67425.
  • The number of misses on the library cache has fallen from 25498 to just 73.
  • There has been a reduction in SQL*Net message from client (database idle time) from 296 seconds to 253 because the Application Engine program spends less time compiling SQL statements.
Conclusion Enabling ReUse Statement can have a very significant effect on the performance of Application Engine batches. It is most effective when SQL statements with %BIND() variables are executed within loops. Otherwise, for each execution of the loop, Application Engine must recompile the SQL statement with different bind variable values, which the database will treat as a new statement that must be parsed. SQL parsing is CPU intensive. Reducing excessive parse also reduces CPU consumption on the database server. It can also reduce physical I/O to the database catalogue. On PeopleSoft 8.x applications that use Unicode, the overhead of parsing is magnified by the use of length checking constraints on all character columns. This is no longer an issue in version 9 applications which use character semantics. If you use Oracle's Automatic Memory Management, excessive parsing can cause the database to allocate more memory to the Shared Pool at the expense of the Block Buffer Cache. This in turn can increase physical I/O and can degrade query performance. Bind Variables are a good thing. You should use them. Therefore, ReUse Statement is also a good thing. You should use that too!

4 comments :

Ciphersbak said...

Hi David,

This is a great example to show the ReUse feature of App Engines. Really appreciate your article on it ...

Thank You very much

Cheers
Thanks!
Prashant

Ciphersbak said...

Hi David,

I was trying to fine tune my AE, using the tips you have talked about, and I've seen phenomenal improvement in the processing times for my AE. I was initially writing to a file about a million rows in 30 mins, some tweaking and ReUseCursor for CreateSQL got the time down to 3 minutes. I'm now able to successfully write about 11 million rows in a single file in just under 30 mins.


Thanks to you.

Cheers!!
Prashant

Anonymous said...

Whats the trace value you would set to derive such timings

David Kurtz said...

These are batch timings. They are enabled by setting the TraceAE flag 128 to write them to file, and 1024 to the database.