Output Post Processor (OPP) Hangs With High CPU Utilization in R12

Issue:

OPP (java) processes consuming High CPU.Most of the time it is due to un-optimized "Template Code" that causes slowness.
It could be either Standard Template Code or Custom Code.

Error in concurrent program log:

Post-processing of request 657502 failed at 10-FEB-2016 21:20:40 with the error message:
The concurrent manager has timed out waiting for the Output Post-processor to finish this request.

Check that there are enough Output Post-processor service processes running.

Cause:

Inactive OPP (java) processes consuming High CPU(100% cpu) or Might be Java garbage collector gets OPP java process hung.

Solution:

We need to collect all the required details to identify the report (Template Code) that caused the issue. Once you identify the "Template Code", you need to take the corrective action to fix it. 

Below are the steps:

1. Identify <PID> of OPP that is spinning. Use top (or) prstat

   1.1 top

   1.2 ps -ef|grep <high cpu pid>

2. Generate the java thread dump. It will generate trace in opp log.

  2.1 $kill -3

  Ex: Kill -3 5456

  2.2 Identify opp file using below command

  Ex: ps -ef|grep <high cpu pid>

[applmgr@testdb ~]$ ps -ef|grep 5456
applmgr   5456 7037  0 Oct18 ?        00:55:15 /u01/oracle/APPS/apps/tech_st/10.1.3/appsutil/jdk/bin/java -DCLIENT_PROCESSID=7133 -server -Xmx384m -XX:NewRatio=2 -XX:+UseSerialGC -Doracle.apps.fnd.common.Pool.leak.mode=stderr:off -verbose:gc -mx512m -Ddbcfile=/u01/oracle/APPS/inst/apps/testserver/appl/fnd/12.0.0/secure/testdb.dbc -Dcpid=2044321 -Dconc_queue_id=2158 -Dqueue_appl_id=0 -Dlogfile=/u01/oracle/APPS/inst/apps/testserver/logs/appl/conc/log/FNDOPP2044321.txt -DLONG_RUNNING_JVM=true -DOVERRIDE_DBC=true -DFND_JDBC_BUFFER_MIN=1 -DFND_JDBC_BUFFER_MAX=2 oracle.apps.fnd.cp.gsf.GSMServiceController
applmgr  24740 24696  0 08:37 pts/1    00:00:00 grep 5456

  2.3 Trace log generte like below

  Full thread dump Java HotSpot(TM) Server VM (20.71-b01 mixed mode):

"Worker-4" daemon prio=3 tid=0x00156400 nid=0x3091 in Object.wait() [0x74e7f000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at oracle.ias.cache.TaskQ.waitForWork(Unknown Source)
- locked <0xa2938800> (a oracle.ias.cache.TaskQ)
at oracle.ias.cache.TaskQ.getTask(Unknown Source)
- locked <0xa2938800> (a oracle.ias.cache.TaskQ)
at oracle.ias.cache.WorkerThread.run(Unknown Source)


"GSMServiceController:657502" prio=3 tid=0x0077e400 nid=0x38 runnable [0x7467f000]
   java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Packet.java:282)
at oracle.net.ns.DataPacket.receive(DataPacket.java:103)
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:230)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:175)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:100)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:85)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:122)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:78)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1179)
at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1155)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:279)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:186)
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:521)
at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:202)
at oracle.jdbc.driver.T4CCallableStatement.executeForRows(T4CCallableStatement.java:1005)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1307)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3449)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3550)
- locked <0xa2938140> (a oracle.jdbc.driver.T4CConnection)
at oracle.jdbc.driver.OracleCallableStatement.execute(OracleCallableStatement.java:4710)
- locked <0xa2938140> (a oracle.jdbc.driver.T4CConnection)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1374)
at oracle.apps.fnd.cp.gsm.GenCartComm.getQueueMessage(GenCartComm.java:189)
at oracle.apps.fnd.cp.gsf.GSMStateMonitor.waitForNextEvent(GSMStateMonitor.java:98)
at oracle.apps.fnd.cp.gsf.GSMServiceController.mainLoop(GSMServiceController.java:236)
at oracle.apps.fnd.cp.gsf.BaseServiceController.run(BaseServiceController.java:71)
at java.lang.Thread.run(Thread.java:680)

3. Get “thread ID” which consumes High CPU. Use this command.

  3.1 $ ps -eLo pid,ppid,tid,pcpu,comm | grep <PID>

Solaris
$ prstat -L -p 5456 1 1
If you do not have prstat available on your Solaris installation, you can do the following instead:
ps -Le -o pid,user,s,lwp,pcpu,args | awk '$3 != "S" { print }'

Linux (discussed in this document)
$ ps -eLo pid,ppid,tid,pcpu,comm | grep <PID>

AIX.
ps -mp 5456 -o THREAD will show the following:

HP-UX
Click hp_prstat to download the hp_prstat utility developed by WebLogic Support.

Windows
Run pslist -d <Java PID>


4. Convert the “thread ID” to Hexadecimal which helps to identify the “Template code” (potential cause).

"GSMServiceController:657502" prio=3 tid=0x0077e400 nid=0x38 runnable [0x7467f000]
   java.lang.Thread.State: RUNNABLE

5. Resolution - Optimizing the Template code.

From the above output take out the string 657502 which is the Concurrent Request ID. 
You can now search for 657502 in OPP log again. 
You should be able to locate the template code.

Reference: 2028617.1