random high cpu utilization

[mayo]

I am using OFBiz 4.0.

I been trying to figure out what causes random high CPU utilization from OFBiz since its deployment (08/2009), which usually requires a restart of the application.  I have done lots research at the software and hardware level and tried many changes, including replacing Minerva with Apache DBCP, but I still (seemingly) random times when my server CPU is at 100% utilization, all from the OFBiz application.

I think I may have stumbled upon a possible reason.  The most recent time it has happened I did a thread dump--something I wish I did last year.  The thread dump showed one particular process that wasn't finishing, and seemed to be stuck on
org.apache.commons.collections.map.AbstractHashedMap.put(AbstractHashedMap.java:273).  The OFBiz log showed the same. A packing session was being completed and gets stuck on that put function.  The thread stack is pasted below.

I am wondering if this rings any bells with some of the more veteran developers.  I found this URL (http://www.mail-archive.com/[e-mail]/msg14324.html) which seems to be related to my issue. I also saw that on 4/29/2007 (revision 533476) that the commons jars were updated.

OFBiz 4.0 seems to using the old commons-collections. Before I start replacing my commons jars, I wanted to see if anyone had any knowledge of this situation.

[Adam Heath-2]

mayo wrote:

> I am using OFBiz 4.0.
>
> I been trying to figure out what causes random high CPU utilization from
> OFBiz since its deployment (08/2009), which usually requires a restart of
> the application.  I have done lots research at the software and hardware
> level and tried many changes, including replacing Minerva with Apache DBCP,
> but I still (seemingly) random times when my server CPU is at 100%
> utilization, all from the OFBiz application.
>
> I think I may have stumbled upon a possible reason.  The most recent time it
> has happened I did a thread dump--something I wish I did last year.  The
> thread dump showed one particular process that wasn't finishing, and seemed
> to be stuck on
> org.apache.commons.collections.map.AbstractHashedMap.put(AbstractHashedMap.java:273).
> The OFBiz log showed the same. A packing session was being completed and
> gets stuck on that put function.  The thread stack is pasted below.
>
> I am wondering if this rings any bells with some of the more veteran
> developers.  I found this URL
> (http://www.mail-archive.com/dev@.../msg14324.html) which seems
> to be related to my issue. I also saw that on 4/29/2007 (revision 533476)
> that the commons jars were updated.

Sure does.  Incorrect locking on the map, multiple threads running,
one tries a modification while another is reading, so the reading
thread ends up getting stuck following a ptr->ptr_to_itself kinda
loop, and deadlock+hilarity ensues.

> OFBiz 4.0 seems to using the old commons-collections. Before I start
> replacing my commons jars, I wanted to see if anyone had any knowledge of
> this situation.

Replacing commons-collections with a newer version won't fix the
problem, as it's ofbiz's use of it that is wrong.  But it might be
fixed in later versions.

[mayo]

I wanted to clarify I have been getting this since MY OFBiz deployment, not since the creation of OFBiz of course.

Also here is the thread stack for the process that did not complete.


"http-0.0.0.0-8443-Processor7" daemon prio=1 tid=0x090fdc08 nid=0x7089 runnable [0xad76d000..0xad76ffb0]
        at org.apache.commons.collections.map.AbstractHashedMap.put(AbstractHashedMap.java:273)
        at org.ofbiz.service.ServiceDispatcher.logService(ServiceDispatcher.java:922)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:256)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:211)
        at org.ofbiz.service.GenericDispatcher.runSync(GenericDispatcher.java:150)
        at org.ofbiz.minilang.method.callops.CallService.exec(CallService.java:239)
        at org.ofbiz.minilang.SimpleMethod.runSubOps(SimpleMethod.java:931)
        at org.ofbiz.minilang.method.ifops.IfEmpty.exec(IfEmpty.java:79)
        at org.ofbiz.minilang.SimpleMethod.runSubOps(SimpleMethod.java:931)
        at org.ofbiz.minilang.SimpleMethod.exec(SimpleMethod.java:568)
        at org.ofbiz.minilang.SimpleMethod.runSimpleMethod(SimpleMethod.java:105)
        at org.ofbiz.minilang.SimpleMethod.runSimpleService(SimpleMethod.java:87)
        at org.ofbiz.minilang.SimpleServiceEngine.serviceInvoker(SimpleServiceEngine.java:76)
        at org.ofbiz.minilang.SimpleServiceEngine.runSync(SimpleServiceEngine.java:51)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:344)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:211)
        at org.ofbiz.service.GenericDispatcher.runSync(GenericDispatcher.java:136)
        at org.ofbiz.accounting.invoice.InvoiceServices.createInvoiceForOrder(InvoiceServices.java:253)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.ofbiz.service.engine.StandardJavaEngine.serviceInvoker(StandardJavaEngine.java:91)
        at org.ofbiz.service.engine.StandardJavaEngine.runSync(StandardJavaEngine.java:53)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:344)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:211)
        at org.ofbiz.service.GenericDispatcher.runSync(GenericDispatcher.java:136)
        at org.ofbiz.accounting.invoice.InvoiceServices.createInvoicesFromShipments(InvoiceServices.java:1491)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.ofbiz.service.engine.StandardJavaEngine.serviceInvoker(StandardJavaEngine.java:91)
        at org.ofbiz.service.engine.StandardJavaEngine.runSync(StandardJavaEngine.java:53)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:344)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:211)
        at org.ofbiz.service.GenericDispatcher.runSync(GenericDispatcher.java:136)
        at org.ofbiz.accounting.invoice.InvoiceServices.createInvoicesFromShipment(InvoiceServices.java:1007)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.ofbiz.service.engine.StandardJavaEngine.serviceInvoker(StandardJavaEngine.java:91)
        at org.ofbiz.service.engine.StandardJavaEngine.runSync(StandardJavaEngine.java:53)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:344)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:211)
        at org.ofbiz.service.GenericDispatcher.runSync(GenericDispatcher.java:136)
        at org.ofbiz.service.eca.ServiceEcaAction.runAction(ServiceEcaAction.java:104)
        at org.ofbiz.service.eca.ServiceEcaRule.eval(ServiceEcaRule.java:138)
        at org.ofbiz.service.eca.ServiceEcaUtil.evalRules(ServiceEcaUtil.java:165)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:380)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:211)
        at org.ofbiz.service.GenericDispatcher.runSync(GenericDispatcher.java:136)
        at org.ofbiz.shipment.packing.PackingSession.setShipmentToPacked(PackingSession.java:785)
        at org.ofbiz.shipment.packing.PackingSession.complete(PackingSession.java:601)
        at org.ofbiz.shipment.packing.PackingServices.completePack(PackingServices.java:282)
        at sun.reflect.GeneratedMethodAccessor861.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.ofbiz.service.engine.StandardJavaEngine.serviceInvoker(StandardJavaEngine.java:91)
        at org.ofbiz.service.engine.StandardJavaEngine.runSync(StandardJavaEngine.java:53)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:344)
        at org.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:211)
        at org.ofbiz.service.GenericDispatcher.runSync(GenericDispatcher.java:136)
        at org.ofbiz.webapp.event.ServiceEventHandler.invoke(ServiceEventHandler.java:308)
        at org.ofbiz.webapp.control.RequestHandler.runEvent(RequestHandler.java:446)
        at org.ofbiz.webapp.control.RequestHandler.doRequest(RequestHandler.java:274)
        at org.ofbiz.webapp.control.ControlServlet.doGet(ControlServlet.java:189)
        at org.ofbiz.webapp.control.ControlServlet.doPost(ControlServlet.java:77)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:615)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:688)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.ofbiz.webapp.control.ContextFilter.doFilter(ContextFilter.java:248)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:664)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)

[Adam Heath-2]

mayo wrote:

> I wanted to clarify I have been getting this since MY OFBiz deployment, not
> since the creation of OFBiz of course.
>
> Also here is the thread stack for the process that did not complete.
>
>
> "http-0.0.0.0-8443-Processor7" daemon prio=1 tid=0x090fdc08 nid=0x7089
> runnable [0xad76d000..0xad76ffb0]
>         at
> org.apache.commons.collections.map.AbstractHashedMap.put(AbstractHashedMap.java:273)
>         at
> org.ofbiz.service.ServiceDispatcher.logService(ServiceDispatcher.java:922)

This bug was fixed in revision 536399, May 9, 2007.

[Adam Heath-2]

Adam Heath wrote:

> mayo wrote:
>> I wanted to clarify I have been getting this since MY OFBiz deployment, not
>> since the creation of OFBiz of course.
>>
>> Also here is the thread stack for the process that did not complete.
>>
>>
>> "http-0.0.0.0-8443-Processor7" daemon prio=1 tid=0x090fdc08 nid=0x7089
>> runnable [0xad76d000..0xad76ffb0]
>>         at
>> org.apache.commons.collections.map.AbstractHashedMap.put(AbstractHashedMap.java:273)
>>         at
>> org.ofbiz.service.ServiceDispatcher.logService(ServiceDispatcher.java:922)
>
> This bug was fixed in revision 536399, May 9, 2007.

I just backported that fix to release4.0, version 955718.

[mayo]

I just found the same revision! Thanks so much Adam.  Hopefully my battle with this will finally come to an end.  Thanks again for the information.