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

ORA-01078 ORA-29701: unable to connect to Cluster Synchronization Service

SQL> startup
ORA-01078: failure in processing system parameters
ORA-29701: unable to connect to Cluster Synchronization Service
SQL>

$ cd $ORACLE_HOME
$ cd bin
$ ./crsctl status resource ora.cssd
NAME=ora.cssd
TYPE=ora.cssd.type
TARGET=ONLINE
STATE=OFFLINE

$ ./crs_stat -t
Name           Type           Target    State     Host
------------------------------------------------------------
ora....DATA.dg ora....up.type ONLINE    OFFLINE
ora....ER.lsnr ora....er.type ONLINE    ONLINE    nsml...db01
ora....DATA.dg ora....up.type ONLINE    OFFLINE
ora....DATA.dg ora....up.type ONLINE    OFFLINE
ora.asm        ora.asm.type   OFFLINE   OFFLINE
ora.cssd       ora.cssd.type  ONLINE    OFFLINE
ora.diskmon    ora....on.type OFFLINE   OFFLINE
ora.evmd       ora.evm.type   ONLINE    ONLINE    nsml...db01
ora.ons        ora.ons.type   OFFLINE   OFFLINE
$ ./crsctl start resource ora.asm
CRS-2672: Attempting to start 'ora.cssd' on '*****'
CRS-2672: Attempting to start 'ora.diskmon' on '*****'
CRS-2676: Start of 'ora.diskmon' on '*****' succeeded
CRS-2676: Start of 'ora.cssd' on '*****' succeeded
CRS-2672: Attempting to start 'ora.asm' on '*****'
CRS-2676: Start of 'ora.asm' on '*****' succeeded
CRS-2672: Attempting to start 'ora.*****.dg' on '*****'
CRS-2672: Attempting to start 'ora.*****.dg' on '*****'
CRS-2672: Attempting to start 'ora.*****.dg' on '*****'
CRS-2676: Start of 'ora.*****.dg' on '*****' succeeded
CRS-2676: Start of 'ora.*****.dg' on '*****' succeeded
CRS-2676: Start of 'ora.*****.dg' on '*****' succeeded
$ sqlplus '/as sysasm'

SQL*Plus: Release 11.2.0.4.0 Production on Sun Jun 11 08:58:46 2017

Copyright (c) 1982, 2013, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Automatic Storage Management option

SQL>