Clarity

Hello, during the last week we experienced two falls processing engine (bg) and in the last one we were able to capture this lines in the bg-ca.log.

Someone had any problem related with this issue?

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 1 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Condition Id: 5058742 Result: false

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 1 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Condition Id: 5058742 Result: false

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 1 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> End processing PostConditionStepQueue. Steps in Queue:0

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 1 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> End processing PostConditionStepQueue. Steps in Queue:0

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 1 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Post Condition Transition Pipeline 1 sleeping

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 1 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Post Condition Transition Pipeline 1 sleeping

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Condition Id: 5052474 Result: false

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Condition Id: 5052474 Result: false

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Expression: project.thisProyecto.osde_anular == 1 &&  ( project.thisProyecto.osde_motivos_anula != null) &&  project.thisProyecto.osde_detalle_anula != null Condition Id: 5058742 Split Type: BPM_ST_EXCLUSIVE_CHOICE

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Expression: project.thisProyecto.osde_anular == 1 &&  ( project.thisProyecto.osde_motivos_anula != null) &&  project.thisProyecto.osde_detalle_anula != null Condition Id: 5058742 Split Type: BPM_ST_EXCLUSIVE_CHOICE

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 0 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Condition Id: 5058652 Result: false

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 0 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Condition Id: 5058652 Result: false

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 0 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> End processing PostConditionStepQueue. Steps in Queue:0

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 0 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> End processing PostConditionStepQueue. Steps in Queue:0

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 0 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Post Condition Transition Pipeline 0 sleeping

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 0 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Post Condition Transition Pipeline 0 sleeping

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Condition Id: 5058742 Result: false

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Condition Id: 5058742 Result: false

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> End processing PostConditionStepQueue. Steps in Queue:0

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> End processing PostConditionStepQueue. Steps in Queue:0

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Post Condition Transition Pipeline 2 sleeping

DEBUG 2014-08-08 04:00:46,008 [Post Condition Transition Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) ----> Post Condition Transition Pipeline 2 sleeping

DEBUG 2014-08-08 04:00:46,024 [Process Loader (tenant=clarity)] bpm.engine (clarity:process_admin:7509534__4528166C-A32F-4A89-9EE6-64A8F45231E5:none) ----> Claimed Processes: [5288355, 5288356, 5288357, 5288358, 5288359, 5288435, 5288437, 5288467, 5288472, 5288498]

DEBUG 2014-08-08 04:00:46,024 [Process Loader (tenant=clarity)] bpm.engine (clarity:process_admin:7509534__4528166C-A32F-4A89-9EE6-64A8F45231E5:none) ----> Claimed Processes: [5288355, 5288356, 5288357, 5288358, 5288359, 5288435, 5288437, 5288467, 5288472, 5288498]

DEBUG 2014-08-08 04:00:46,024 [Process Loader (tenant=clarity)] bpm.engine (clarity:process_admin:7509534__4528166C-A32F-4A89-9EE6-64A8F45231E5:none) ----> Expected to load: 10

DEBUG 2014-08-08 04:00:46,024 [Process Loader (tenant=clarity)] bpm.engine (clarity:process_admin:7509534__4528166C-A32F-4A89-9EE6-64A8F45231E5:none) ----> Expected to load: 10

DEBUG 2014-08-08 04:00:46,024 [Process Loader (tenant=clarity)] bpm.engine (clarity:process_admin:7509534__4528166C-A32F-4A89-9EE6-64A8F45231E5:none) ----> Claimed: 10

DEBUG 2014-08-08 04:00:46,024 [Process Loader (tenant=clarity)] bpm.engine (clarity:process_admin:7509534__4528166C-A32F-4A89-9EE6-64A8F45231E5:none) ----> Claimed: 10

DEBUG 2014-08-08 04:03:38,055 [ProcessEngineThreadMonitor (tenant=clarity)] bpm.engine (none:none:none:none) ----> ProcessEngineThreadMonitor wakeup after wait()

DEBUG 2014-08-08 04:03:44,149 [Process Monitor (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) Raising heartbeat ***

DEBUG 2014-08-08 04:03:44,149 [Process Monitor (tenant=clarity)] bpm.engine (clarity:process_admin:7509019__5B51EF3D-9E1F-433C-B17F-97216AD337C7:none) Raising heartbeat ***

ERROR 2014-08-08 04:26:12,477 [NMS Message Receiver (tenant=clarity)] bpm.eventmgr (clarity:none:none:none) Error thrown in processing messages.

java.lang.OutOfMemoryError: Java heap space

ERROR 2014-08-08 04:32:47,243 [NMS Message Receiver (tenant=clarity)] bpm.eventmgr (clarity:none:none:none) Error thrown in processing messages.

ERROR 2014-08-08 04:35:10,602 [NMS Message Receiver (tenant=clarity)] bpm.eventmgr (clarity:none:none:none) Error thrown in processing messages.

java.lang.OutOfMemoryError: Java heap space

ERROR 2014-08-08 04:50:02,485 [NMS Message Receiver (tenant=clarity)] bpm.eventmgr (clarity:none:none:none) Error thrown in processing messages.

java.lang.OutOfMemoryError: Java heap space

HI,

Is there any scheduled Jobs or Process that is running during this time, which does a bulk updates?

Regards,

Teena Antony

Hi Teena,

the true is that at 04:00 a.m. it runs a custom process called "Internal OSDE CA Clarity Process". But i think that this process does not generated the error, because in other opportunity the bg service stop processing at 17:20 p.m when this process not executed yet.

HI,

Is there any other process scheduled during this time? Which version of Clarity are you in? IS there any orphan records? You can chheck by executing the below query?

select count(*) from NMS_MESSAGE_DELIVERY where message_id not in (select id from nms_messages)

Regards,

Teena Antony

what are your java vm memory settings for service which runs the process engine?

Hi,

The processing engine has the following parameters in the JVM:

-Xms512m -Xmx3072m -XX:-UseGCOverheadLimit -DforceMemorySettings=false -XX:MaxPermSize=192m -XX:HeapDumpPath=E:\OOM\bg-dump.HPROF

Regards,

Patricio

Hi Teena,

At that time no exists other scheduled process. Our version of Clarity is 13.2.

I ran the query you provided me and does not appear any case, it says 0.

Regards,

Patricio.

Hi...

There is a heap error message which indicate the BG did not have the allocated memory it required to process./run the jobs. So to know the rot cause you need to confgure the heap dump setting and when next time similar heap issue/out of memory occurs then you can analyze the heap and see where the memory was consumed more.

Also for a short team resolutions is to allocate big extra memory so that you dont run into the hear issues. And on a long team please have the sizing reviewed to know the exact requirement of memoy/CPU etc.]

Hope this helps

Regards

Suman Pramanik

Hi Suman,

Thanks, I increased in the parameters of the process engine of the JVM the value of XMX of the BG and apparently it's behaving normally.

Regards.

Patricio.

Hi Patrico,

Good to hear that.

Regards

Suman Pramanik

What are the new parameters for java vm?

The new parameters that I set was:

-Xms512m -Xmx4096m -XX:-UseGCOverheadLimit -DforceMemorySettings=false -XX:MaxPermSize=192m -XX:HeapDumpPath=E:\OOM\bg-dump.HPROF

Do you have any aditional recommendation for me?

Regards.

Patricio.

HI

I would recommend to have  same Xmx=XMX, so that while start up it allocates the entire 4GB to clarity

-Xms4096m -Xmx4096m -XX:-UseGCOverheadLimit -DforceMemorySettings=false -XX:MaxPermSize=192m -XX:HeapDumpPath=E:\OOM\bg-dump.HPROF

Regards

Suman Pramanik

I have issues along this area before. increasing the heap has always fixed it. JAVA at times can be a pig.

HI Mike,

It not really the fault with java, these type of problem happens when the proper sizing of application is not done. So its always better to go for a sizing exercise atleast for production environment

Regards

Suman Pramanik

But as your environment matures you need to continually keep the sizing in mind, and perform periodic updates to ensure you have adequate space.

Hi Mike,

Really this task should have been did by the consultants, now we are analyzing if we need upgrade our hardware, so I'll have news in the short term, thanks.

Regards.

Patricio.

Patricio, as a matter of interest how much installed RAM is installed on your affected server?

Hi,

In the affected server we have 8GB the memory RAMy, and the process engine has assigned 4GB.

-Xms512m -Xmx4096m -XX:-UseGCOverheadLimit -DforceMemorySettings=false -XX:MaxPermSize=192m -XX:HeapDumpPath=E:\OOM\bg-dump.HPROF

Regards.

Patricio.

We get roughly 2 Java OOM errors a month, and can see the error messages in the app-ca.log file.

Currently the java vm parameters for heapdump look like this:

APP - <applicationServerInstance id="app" serviceName="Niku Server" rmiPort="23791" jvmParameters="-Xms2560m -Xmx2560m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:\niku\clarity\logs\heapdumps\app

BG - <backgroundServer jvmParameters="-Xms2048m -Xmx2048m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:\niku\clarity\logs\heapdumps\bg

We have never seen an OOM issue in BG, but regularly see them in APP.

The server has 8GB installed RAM.

Would increasing the memory setting in APP be beneficial to us as it was for Patricio?

Hi,

Yes and no ... by increase the memory you may solve the issue .. or not.. The best thing to do is 1st to find the Root Cause. check the HPROF files generated under:

D:\niku\clarity\logs\heapdumps\bg

or

D:\niku\clarity\logs\heapdumps\app

depending on if it's OOM for BG or APP. Once you find the root cause, you can determine if by increasing a bit the memory will be sufficient or if something needs to be re-designed in clarity.

If you need help with Root Cause analysis, please lot a ticket with support. They will help you out to find the exact root cause and provide advice.

Yes we have a case open already and the advice is to upgrade to 13.3 from our current version 13.1

This of course will require us to test firstly in our test environments before we can upgrade Production and so will take quite some time.

I just wondered if increasing the memory setting may buy us some time.

Most of the times, yes, it buys time

Thank you.

As you can see,

<applicationServerInstance id="app" serviceName="Niku Server" rmiPort="23791" jvmParameters="-Xms2560m -Xmx2560m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:\niku\clarity\logs\heapdumps\app

What would be a sensible increase in our xms and xmx setting to begin with?

Hi cmcn,

Increasing the JVM can only buy time, so you need to do a sizing to see how much memory you require for your environment, So if 4 GB goes a sweet spot and you don't see any OOM they you are ok to have the same.

Regards

Suman

Hi,

the truth is that last week the people of support contact us to validate all processes that are running on Clarity, and found one process that apparently generated a loop that fall into the processing engine.

Regards.

Patricio.