How To diagnose the "Root Cause" of OPP (java) consuming High CPU

Steps To Collect The Required Details

1. Use top/prstat (find the analogous parameter for your platform) OS command to identify the pid of OPP (java). This is the of the OPP Java process which consumes High CPU.

2. Generate the java thread dump. Use the from step1. This is required to write additional log details in the OPP log which helps us to narrow down the potential cause.
$ kill -3

3. Identify the relevant OPP file (Get absolute Path & file name using below command)
$ ps -ef | grep

4. Get the below details to get thread details. Use the from step1.
$ ps -eLo pid,ppid,tid,pcpu,comm | grep <

5. Once we know the “thread id” from step 4, we can find out the report which could be the potential “Root Cause" of OPP (java) to consume High CPU
Note: - Collect all the details in one go, to get complete picture.


$ top
top - 00:52:29 up 149 days, 22:08, 4 users, load average: 4.57, 4.42, 3.79
Tasks: 1633 total,  5 running, 1628 sleeping,  0 stopped,  0 zombie
Cpu(s): 51.7%us, 7.0%sy, 0.0%ni, 29.5%id, 10.7%wa, 0.0%hi, 1.1%si, 0.0%st
Mem: 65932544k total, 65201636k used,  730908k free,  94028k buffers
Swap: 16777208k total, 11123908k used, 5653300k free, 6651120k cached

 PID USER   PR NI VIRT RES SHR S %CPU %MEM  TIME+ COMMAND
38144 appl  20  0 2360m 790m 1940 S 100.0 1.2 97217:33 java

$ ps -ef| grep 38144
appl 30965 30856 0 00:52 pts/0  00:00:00 grep 38144
appl 38144 37993 71 Mar17 ?    67-12:17:44 /u01/app/appl/PROD/apps/tech_st/10.1.3/appsutil/jdk/bin/java -DCLIENT_PROCESSID=38144 -server -Xmx384m -XX:NewRatio=2 -XX:+UseSerialGC -Doracle.apps.fnd.common.Pool.leak.mode=stderr:off -verbose:gc -mx2048m -Ddbcfile=/u01/app/appl/PROD/inst/apps/context_name/appl/fnd/12.0.0/secure/PROD.dbc -Dcpid=1300518 -Dconc_queue_id=1132 -Dqueue_appl_id=0 -Dlogfile=/u01/app/appl/PROD/inst/apps/CONTEXT_NAME/logs/appl/conc/log/FNDOPP1300518.txt -DLONG_RUNNING_JVM=true -DOVERRIDE_DBC=true -DFND_JDBC_BUFFER_MIN=1 -DFND_JDBC_BUFFER_MAX=2 oracle.apps.fnd.cp.gsf.GSMServiceController
[applprod@psmlferro01 ~]$

OPP file name : /u01/app/appl/PROD/inst/apps/$CONTEXT_NAME/logs/appl/conc/log/FNDOPP1300518.txt

$ kill -3 38144
$

$ ps -eLo pid,ppid,tid,pcpu,comm | grep 38144
38144 37993 38144 0.0 java
38144 37993 38145 0.0 java
38144 37993 38146 0.0 java
38144 37993 38147 0.0 java
38144 37993 38148 0.0 java
38144 37993 38155 0.0 java
38144 37993 38156 0.0 java
38144 37993 38157 0.0 java
38144 37993 38158 0.0 java
38144 37993 38159 0.0 java
38144 37993 38307 0.0 java
38144 37993 38313 0.0 java
38144 37993 38480 0.0 java
38144 37993 38494 0.0 java
38144 37993 38495 0.0 java
38144 37993 38594 0.0 java
38144 37993 38596 0.0 java
38144 37993 38597 0.0 java
38144 37993 38604 0.0 java
38144 37993 38614 0.0 java
38144 37993 38615 0.0 java
38144 37993 38620 0.0 java
38144 37993 38622 0.0 java
38144 37993 38625 0.0 java
38144 37993 38640 0.0 java
38144 37993 38641 0.0 java
38144 37993 40083 0.0 java
38144 37993 40087 0.0 java
38144 37993 40150 0.0 java
38144 37993 40152 0.0 java
38144 37993 40211 0.0 java
38144 37993 40214 0.0 java
38144 37993 40282 0.0 java
38144 37993 40288 0.0 java
38144 37993 40577 0.0 java
38144 37993 40582 0.0 java
38144 37993 7785 104 java
38144 37993 36170 0.0 java
38144 37993 36171 0.0 java
38144 37993 36172 0.0 java
38144 37993 36175 0.0 java
38144 37993 36176 0.0 java
38144 37993 36181 0.0 java
38144 37993 11152 0.0 java
38144 37993 20426 0.0 java
38144 37993 64706 0.0 java
38144 37993 47140 0.0 java
$

Thread id : 7785

Hexa Value : 1E69

From logfile :

"1300518:RT50811221" daemon prio=10 tid=0xf76f3400 nid=0x1e69 runnable [0x6d883000]
  java.lang.Thread.State: RUNNABLE
    at oracle.xdo.parser.v2.XSLTContext.reset(XSLTContext.java:346)
    at oracle.xdo.parser.v2.XSLProcessor.processXSL(XSLProcessor.java:285)
    at oracle.xdo.parser.v2.XSLProcessor.processXSL(XSLProcessor.java:155)
    at oracle.xdo.parser.v2.XSLProcessor.processXSL(XSLProcessor.java:192)
    at sun.reflect.GeneratedMethodAccessor389.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at oracle.apps.xdo.common.xml.XSLT10gR1.invokeProcessXSL(XSLT10gR1.java:677)
    at oracle.apps.xdo.common.xml.XSLT10gR1.transform(XSLT10gR1.java:425)
    at oracle.apps.xdo.common.xml.XSLT10gR1.transform(XSLT10gR1.java:244)
    at oracle.apps.xdo.common.xml.XSLTWrapper.transform(XSLTWrapper.java:182)
    at oracle.apps.xdo.template.fo.util.FOUtility.generateFO(FOUtility.java:1044)
    at oracle.apps.xdo.template.fo.util.FOUtility.generateFO(FOUtility.java:997)
    at oracle.apps.xdo.template.fo.util.FOUtility.generateFO(FOUtility.java:212)
    at oracle.apps.xdo.template.FOProcessor.createFO(FOProcessor.java:1665)
    at oracle.apps.xdo.template.FOProcessor.generate(FOProcessor.java:975)
    at oracle.apps.xdo.oa.schema.server.TemplateHelper.runProcessTemplate(TemplateHelper.java:5936)
    at oracle.apps.xdo.oa.schema.server.TemplateHelper.processTemplate(TemplateHelper.java:3459)
    at oracle.apps.xdo.oa.schema.server.TemplateHelper.processTemplate(TemplateHelper.java:3548)
    at oracle.apps.fnd.cp.opp.XMLPublisherProcessor.process(XMLPublisherProcessor.java:311)
    at oracle.apps.fnd.cp.opp.OPPRequestThread.run(OPPRequestThread.java:184)

Request id : 50811221

From logfile :

[4/13/17 11:45:37 AM] [OPPServiceThread1] Post-processing request 50811221.
[4/13/17 11:45:37 AM] [1300518:RT50811221] Executing post-processing actions for request 50811221.
[4/13/17 11:45:37 AM] [1300518:RT50811221] Starting XML Publisher post-processing action.
[4/13/17 11:45:37 AM] [1300518:RT50811221]
Template code: INVARAAS_XML
Template app: INV
Language:   en
Territory:   US
Output type:  EXCEL

Template Name : INVARAAS_XML