Overall slow performance due to very intensive logging (Doc ID 1571850.1)

Last updated on SEPTEMBER 30, 2022

Applies to:

Symptoms

Overall performance of the delivery system is increasingly slow. Reboot makes little difference, after restart the performance is largely the same. It does not seem linked to any particular activity, such as publishing or UI work.

Thread dumps on CS show many threads doing this:

"[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'" id=62 idx=0x10c tid=68 prio=5 alive, blocked, native_blocked, daemon
  -- Blocked trying to get lock: java/lang/Object@0x32491d88[fat lock]
  at jrockit/vm/Threads.waitForUnblockSignal()V(Native Method)
  at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1411)[optimized]
  at jrockit/vm/Locks.lockFat(Locks.java:1512)[optimized]
  at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1054)[optimized]
  at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1005)[optimized]
  at com/fatwire/cs/core/logging/TraditionalLog.rollLogFile(y:1235)[optimized]
  at com/fatwire/cs/core/logging/TraditionalLog.write(y:164)[optimized]
  at com/fatwire/cs/core/logging/AbstractLog.log(y:141)[inlined]
  at com/fatwire/cs/core/logging/AbstractLog.debug(y:2650)[inlined]
  at com/fatwire/cs/core/logging/AbstractLog.debug(y:1798)[inlined]
  at COM/FutureTense/Common/X.moveToRow(y:303)[optimized]
  at com/openmarket/framework/objects/AbstractContent.Read(y:2460)[inlined]
  at com/openmarket/framework/objects/AbstractObject.Read(y:2303)[inlined]
  at com/openmarket/framework/objects/AbstractObject.Read(y:268)[inlined]
  at com/openmarket/xcelerate/asset/AssetType.Load(y:234)[inlined]

And the lock is held by one thread doing this:

"[ACTIVE] ExecuteThread: '133' for queue: 'weblogic.kernel.Default (self-tuning)'" id=219 idx=0x378 tid=225 prio=5 alive, native_blocked, daemon
  at jrockit/io/FileNativeIO.writeBytesPinned(Ljava/io/FileDescriptor;[BIIZ)V(Native Method)
  at jrockit/io/FileNativeIO.writeBytes(FileNativeIO.java:52)[inlined]
  at java/io/FileOutputStream.writeBytes([BII)V(FileOutputStream.java)[inlined]
  at java/io/FileOutputStream.write(FileOutputStream.java:282)[optimized]
  at sun/nio/cs/StreamEncoder.writeBytes(StreamEncoder.java:202)[optimized]
  at sun/nio/cs/StreamEncoder.implClose(StreamEncoder.java:297)[inlined]
  at sun/nio/cs/StreamEncoder.close(StreamEncoder.java:130)[inlined]
  at java/io/OutputStreamWriter.close(OutputStreamWriter.java:216)[optimized]
  ^-- Holding lock: java/io/OutputStreamWriter@0x3c3f1130[recursive]
  at java/io/BufferedWriter.close(BufferedWriter.java:248)[optimized]
  ^-- Holding lock: java/io/OutputStreamWriter@0x3c3f1130[biased lock]
  at java/io/PrintWriter.close(PrintWriter.java:295)[inlined]
  at com/fatwire/cs/core/logging/TraditionalLog.write(y:929)[optimized]
  ^-- Holding lock: java/io/BufferedWriter@0x3c3f1108[biased lock]
  ^-- Holding lock: java/lang/Object@0x32491d88[fat lock]
  at com/fatwire/cs/core/logging/AbstractLog.log(y:141)[inlined]
  at com/fatwire/cs/core/logging/AbstractLog.debug(y:2650)[inlined]
  at com/fatwire/cs/core/logging/AbstractLog.debug(y:1798)[inlined]
  at COM/FutureTense/Common/X.moveToRow(y:303)[optimized]
  at com/openmarket/framework/objects/AbstractContent.Read(y:2460)[inlined]
  at com/openmarket/framework/objects/AbstractObject.Read(y:2303)[inlined]
  at com/openmarket/framework/objects/AbstractObject.Read(y:268)[inlined]
  at com/openmarket/xcelerate/asset/AssetType.Load(y:234)[inlined

Cause

My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.