The real performance impact of logging and nettrace to JD Edwards

Ever wanted to know what the affect of enabling logging was going to be on your back end users?  Have you ever really wanted to get some sqlnet tracing and some jdedwards logging on a problem – but not been brave enough because of the impact on your servers and your end users.  Well, I might have some handy metrics for you.

I’ve been working with a client that gets a little too many of these bad boys when they are under load:

D:\JDEdwards\E910\log>findstr  ORA-03113 *
jdedebug_1880.log:Jan 19 19:42:12.516059 - 1880/7520 WRK:DGTEST01_09F8D008_P01012       OCI0000179 - Error - ORA-03113: end-of-file on communication channel
jdedebug_5204.log:Jan 19 19:20:18.520003 - 5204/4840 WRK:DGTEST01_0B3BFEF0_P4310        OCI0000179 - Error - ORA-03113: end-of-file on communication channel
jdedebug_6800.log:Jan 19 19:43:08.980002 - 6800/2952 WRK:DGTEST01_0975AA28_P01012       OCI0000179 - Error - ORA-03113: end-of-file on communication channel
jde_1880.log:   OCI0000179 - Error - ORA-03113: end-of-file on communication channel
jde_5204.log:   OCI0000179 - Error - ORA-03113: end-of-file on communication channel
jde_6800.log:   OCI0000179 - Error - ORA-03113: end-of-file on communication channel

Yep, this is not good.  It’s essentially the client saying my connection has been terminated, I give up.  There is generally a requisite alert in the database error logs.

Tue Jan 12 21:21:49 2016

Errors in file /u01/app/oracle/diag/rdbms/jdegsuat/JDEGSUAT1/trace/JDEGSUAT1_ora_90089.trc  (incident=120946):

ORA-03137: TTC protocol internal error : [12333] [7] [2] [0] [] [] [] []

Incident details in: /u01/app/oracle/diag/rdbms/jdegsuat/JDEGSUAT1/incident/incdir_120946/JDEGSUAT1_ora_90089_i120946.trc

Of course, oracle support are not going to touch this without a shed load of logs – so guess what – I’m going to give them a shed load of logs.

sqlnet.ora has been modified with the following (this is a 12C database and client).

trace_level_client = 16

trace_file_client = cli

trace_directory_client = d:\trace

trace_unique_client = on

trace_timestamp_client = on

trace_filelen_client = 100

trace_fileno_client = 2

log_file_client = cli

log_directory_client = d:\trace\log

tnsping.trace_directory = d:\trace\trace

tnsping.trace_level = admin

Not too sure how many of these are working, because all of the logs are being written to d:\oracle\diag – not the dir that I’m specifying…  Anyways…...

So my scripts with a mixed work load saw up to 7.1% net speed loss with logging (interactive speed, averaged over 1000 sessions executing the same mixed workload).  An average of 14.6% slower with sqlnet tracing and jde logging. 

I’d expect batch to slowdown more, but this was pretty good.

Note that the server was running at about 85% CPU utilisation when logging was enabled, not the 12% that it was without logging enabled!!!