Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

OutOfMemoryError: Java heap space #1412

Closed
jmiranda opened this issue Jan 28, 2020 · 2 comments
Closed

OutOfMemoryError: Java heap space #1412

jmiranda opened this issue Jan 28, 2020 · 2 comments

Comments

@jmiranda
Copy link
Member

The server might have been leaking memory for awhile but there's something suspicious about the multiple Create Requisition requests just before the out of memory error. I believe it might have been due to the fact that the server was already slow but worth investigating in case it sheds light on the cause.

2020-01-28 14:06:30,597 [ajp-bio-8009-exec-719] INFO  filters.AccessLogFilters  - inventory.manage: [user:demo, location:A01]
2020-01-28 14:06:32,715 [ajp-bio-8009-exec-719] INFO  filters.AccessLogFilters  - Request duration for (inventory/manage): 1214ms/904ms
2020-01-28 14:06:34,045 [ajp-bio-8009-exec-719] INFO  web.Timer  - Cached request for /openboxes/grails/dashboard/megamenu.dispatch took 0:00:00.353
2020-01-28 14:06:34,421 [ajp-bio-8009-exec-719] INFO  core.UserService  - null ROLE_SHIPMENT_NOTIFICATION = false
2020-01-28 14:06:34,421 [ajp-bio-8009-exec-719] INFO  core.UserService  - null ROLE_PRODUCT_NOTIFICATION = false
2020-01-28 14:06:34,421 [ajp-bio-8009-exec-719] INFO  core.UserService  - null ROLE_ADMIN = true
2020-01-28 14:06:35,504 [ajp-bio-8009-exec-755] INFO  filters.AccessLogFilters  - inventory.binLocations: [user:demo, location:A01]
2020-01-28 14:06:35,757 [ajp-bio-8009-exec-755] INFO  filters.AccessLogFilters  - Request duration for (inventory/binLocations): 249ms/3ms
2020-01-28 14:06:42,497 [ajp-bio-8009-exec-753] INFO  filters.AccessLogFilters  - shipper.list: [user:demo, location:A01]
2020-01-28 14:06:42,687 [ajp-bio-8009-exec-753] INFO  filters.AccessLogFilters  - Request duration for (shipper/list): 25ms/165ms
2020-01-28 14:06:42,737 [ajp-bio-8009-exec-753] INFO  web.Timer  - Cached request for /openboxes/grails/dashboard/megamenu.dispatch took 0:00:00.003
2020-01-28 14:06:42,755 [ajp-bio-8009-exec-753] INFO  core.UserService  - null ROLE_PRODUCT_NOTIFICATION = false
2020-01-28 14:06:42,755 [ajp-bio-8009-exec-753] INFO  core.UserService  - null ROLE_ADMIN = true
2020-01-28 14:06:51,437 [ajp-bio-8009-exec-757] INFO  filters.AccessLogFilters  - document.list: [user:demo, location:A01]
2020-01-28 14:06:51,450 [ajp-bio-8009-exec-757] INFO  core.DocumentController  - params: [action:list, controller:document]
2020-01-28 14:06:51,451 [ajp-bio-8009-exec-757] INFO  core.DocumentController  - show all: [action:list, controller:document, max:10]
2020-01-28 14:06:53,809 [ajp-bio-8009-exec-757] INFO  filters.AccessLogFilters  - Request duration for (document/list): 2099ms/272ms
2020-01-28 14:06:53,905 [ajp-bio-8009-exec-757] INFO  web.Timer  - Cached request for /openboxes/grails/dashboard/megamenu.dispatch took 0:00:00.002
2020-01-28 14:06:53,975 [ajp-bio-8009-exec-757] INFO  core.UserService  - null ROLE_PRODUCT_NOTIFICATION = false
2020-01-28 14:06:53,975 [ajp-bio-8009-exec-757] INFO  core.UserService  - null ROLE_SHIPMENT_NOTIFICATION = false
2020-01-28 14:06:53,975 [ajp-bio-8009-exec-757] INFO  core.UserService  - null ROLE_ADMIN = true
2020-01-28 14:07:19,551 [ajp-bio-8009-exec-743] INFO  filters.AccessLogFilters  - eventType.list: [user:demo, location:A01]
2020-01-28 14:07:19,655 [ajp-bio-8009-exec-743] INFO  filters.AccessLogFilters  - Request duration for (eventType/list): 31ms/73ms
2020-01-28 14:07:19,686 [ajp-bio-8009-exec-743] INFO  web.Timer  - Cached request for /openboxes/grails/dashboard/megamenu.dispatch took 0:00:00.001
2020-01-28 14:07:19,698 [ajp-bio-8009-exec-743] INFO  core.UserService  - null ROLE_PRODUCT_NOTIFICATION = false
2020-01-28 14:07:19,698 [ajp-bio-8009-exec-743] INFO  core.UserService  - null ROLE_SHIPMENT_NOTIFICATION = false
2020-01-28 14:07:19,698 [ajp-bio-8009-exec-743] INFO  core.UserService  - null ROLE_ADMIN = true
2020-01-28 14:07:31,784 [ajp-bio-8009-exec-728] INFO  filters.AccessLogFilters  - dashboard.index: [user:demo, location:A01]
2020-01-28 14:07:32,205 [ajp-bio-8009-exec-728] INFO  user.DashboardController  - dashboard.index Response time: 416 ms
2020-01-28 14:07:32,282 [ajp-bio-8009-exec-728] INFO  requisition.RequisitionService  - destination A01
2020-01-28 14:07:32,282 [ajp-bio-8009-exec-728] INFO  requisition.RequisitionService  - origin null
2020-01-28 14:07:32,282 [ajp-bio-8009-exec-728] INFO  requisition.RequisitionService  - user null
2020-01-28 14:07:32,282 [ajp-bio-8009-exec-728] INFO  requisition.RequisitionService  - Date null
2020-01-28 14:07:33,910 [ajp-bio-8009-exec-728] INFO  filters.AccessLogFilters  - Request duration for (dashboard/index): 1625ms/501ms
2020-01-28 14:07:33,942 [ajp-bio-8009-exec-728] INFO  web.Timer  - Cached request for /openboxes/grails/dashboard/megamenu.dispatch took 0:00:00.002
2020-01-28 14:07:33,952 [ajp-bio-8009-exec-728] INFO  core.UserService  - null ROLE_PRODUCT_NOTIFICATION = false
2020-01-28 14:07:33,952 [ajp-bio-8009-exec-728] INFO  core.UserService  - null ROLE_SHIPMENT_NOTIFICATION = false
2020-01-28 14:07:33,952 [ajp-bio-8009-exec-728] INFO  core.UserService  - null ROLE_ADMIN = true
2020-01-28 14:07:56,995 [ajp-bio-8009-exec-749] INFO  filters.AccessLogFilters  - purchaseOrderWorkflow.index: [user:demo, location:A01]
2020-01-28 14:07:57,076 [ajp-bio-8009-exec-749] INFO  filters.AccessLogFilters  - Request duration for (purchaseOrderWorkflow/index): 80ms/1ms
2020-01-28 14:07:57,407 [ajp-bio-8009-exec-749] INFO  filters.AccessLogFilters  - purchaseOrderWorkflow.purchaseOrder: [user:demo, location:A01]
2020-01-28 14:07:57,448 [ajp-bio-8009-exec-749] INFO  order.PurchaseOrderWorkflowController  - Starting order workflow [action:purchaseOrder, controller:purchaseOrderWorkflow]
2020-01-28 14:07:57,863 [ajp-bio-8009-exec-749] INFO  filters.AccessLogFilters  - Request duration for (purchaseOrderWorkflow/purchaseOrder): 455ms/1ms
2020-01-28 14:07:58,027 [ajp-bio-8009-exec-749] INFO  filters.AccessLogFilters  - purchaseOrderWorkflow.purchaseOrder: [user:demo, location:A01]
2020-01-28 14:07:58,051 [ajp-bio-8009-exec-749] WARN  pages.GroovyPagesTemplateEngine  - Precompiled GSP not found for uri: [/WEB-INF/grails-app/views//purchaseOrderWorkflow/purchaseOrder/enterOrderDetails.gsp]. Using resource ServletContext resource [/WEB-INF/grails-app/views//purchaseOrderWorkflow/purchaseOrder/enterOrderDetails.gsp]
2020-01-28 14:07:58,051 [ajp-bio-8009-exec-749] INFO  pages.GroovyPagesTemplateEngine  - Creating template using resource ServletContext resource [/WEB-INF/grails-app/views//purchaseOrderWorkflow/purchaseOrder/enterOrderDetails.gsp]
2020-01-28 14:08:07,372 [ajp-bio-8009-exec-749] INFO  filters.AccessLogFilters  - Request duration for (purchaseOrderWorkflow/purchaseOrder): 9344ms/1ms
2020-01-28 14:08:07,410 [ajp-bio-8009-exec-749] INFO  web.Timer  - Cached request for /openboxes/grails/dashboard/megamenu.dispatch took 0:00:00.002
2020-01-28 14:08:07,425 [ajp-bio-8009-exec-749] INFO  core.UserService  - null ROLE_SHIPMENT_NOTIFICATION = false
2020-01-28 14:08:07,426 [ajp-bio-8009-exec-749] INFO  core.UserService  - null ROLE_PRODUCT_NOTIFICATION = false
2020-01-28 14:08:07,426 [ajp-bio-8009-exec-749] INFO  core.UserService  - null ROLE_ADMIN = true
2020-01-28 14:08:21,421 [ajp-bio-8009-exec-755] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:27,339 [ajp-bio-8009-exec-755] INFO  filters.AccessLogFilters  - Request duration for (requisition/create): 284ms/5633ms
2020-01-28 14:08:27,807 [ajp-bio-8009-exec-755] INFO  web.Timer  - Cached request for /openboxes/grails/dashboard/megamenu.dispatch took 0:00:00.006
2020-01-28 14:08:27,824 [ajp-bio-8009-exec-737] INFO  filters.AccessLogFilters  - auth.login: [user:null, location:null]
2020-01-28 14:08:27,846 [ajp-bio-8009-exec-755] INFO  core.UserService  - null ROLE_PRODUCT_NOTIFICATION = false
2020-01-28 14:08:27,846 [ajp-bio-8009-exec-755] INFO  core.UserService  - null ROLE_SHIPMENT_NOTIFICATION = false
2020-01-28 14:08:27,846 [ajp-bio-8009-exec-755] INFO  core.UserService  - null ROLE_ADMIN = true
2020-01-28 14:08:28,891 [ajp-bio-8009-exec-757] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:33,152 [ajp-bio-8009-exec-743] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:37,936 [ajp-bio-8009-exec-754] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:38,057 [ajp-bio-8009-exec-728] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:39,288 [ajp-bio-8009-exec-749] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:43,020 [ajp-bio-8009-exec-753] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:43,022 [ajp-bio-8009-exec-752] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:43,024 [ajp-bio-8009-exec-737] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:43,029 [ajp-bio-8009-exec-755] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:46,775 [ajp-bio-8009-exec-757] INFO  filters.AccessLogFilters  - Request duration for (requisition/create): 17ms/17866ms
2020-01-28 14:08:50,806 [ajp-bio-8009-exec-758] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:50,836 [ajp-bio-8009-exec-759] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:51,270 [ajp-bio-8009-exec-760] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:51,296 [ajp-bio-8009-exec-761] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:54,997 [ajp-bio-8009-exec-762] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:08:55,492 [ajp-bio-8009-exec-763] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:09:03,170 [ajp-bio-8009-exec-764] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
2020-01-28 14:09:03,305 [ajp-bio-8009-exec-765] INFO  filters.AccessLogFilters  - requisition.create: [user:demo, location:A01]
Exception in thread "ajp-bio-8009-exec-766" java.lang.OutOfMemoryError: Java heap space
	at java.util.LinkedHashMap.init(LinkedHashMap.java:241)
	at java.util.HashMap.<init>(HashMap.java:263)
	at java.util.HashMap.<init>(HashMap.java:274)
	at java.util.LinkedHashMap.<init>(LinkedHashMap.java:189)
	at org.hibernate.util.IdentityMap.instantiateSequenced(IdentityMap.java:67)
	at org.hibernate.engine.StatefulPersistenceContext.<init>(StatefulPersistenceContext.java:146)
	at org.hibernate.impl.SessionImpl.<init>(SessionImpl.java:236)
	at org.hibernate.impl.SessionFactoryImpl.openSession(SessionFactoryImpl.java:503)
	at org.hibernate.impl.SessionFactoryImpl.openSession(SessionFactoryImpl.java:527)
	at org.hibernate.impl.SessionFactoryImpl.openSession(SessionFactoryImpl.java:535)
	at org.springframework.orm.hibernate3.SessionFactoryUtils.doGetSession(SessionFactoryUtils.java:318)
	at org.springframework.orm.hibernate3.SessionFactoryUtils.getSession(SessionFactoryUtils.java:200)
	at org.codehaus.groovy.grails.orm.hibernate.support.HibernatePersistenceContextInterceptor.getSession(HibernatePersistenceContextInterceptor.java:135)
	at org.codehaus.groovy.grails.orm.hibernate.support.HibernatePersistenceContextInterceptor.isOpen(HibernatePersistenceContextInterceptor.java:102)
	at org.codehaus.groovy.grails.web.sitemesh.GrailsPageFilter.doFilter(GrailsPageFilter.java:163)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at org.codehaus.groovy.grails.web.servlet.mvc.GrailsWebRequestFilter.doFilterInternal(GrailsWebRequestFilter.java:69)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at org.codehaus.groovy.grails.web.filters.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:69)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
Exception in thread "DefaultPluginScheduler_QuartzSchedulerThread" java.lang.OutOfMemoryError: Java heap space
Exception in thread "ajp-bio-8009-exec-719" java.lang.OutOfMemoryError: Java heap space
2020-01-28 14:13:44,171 [ajp-bio-8009-exec-762] ERROR view.GroovyPageView  - Error processing GroovyPageView: Error executing tag <g:form>: Error executing tag <g:selectPerson>: java.lang.OutOfMemoryError: Java heap space at /WEB-INF/grails-app/views/requisition/createNonStock.gsp:117 at /WEB-INF/grails-app/views/requisition/createNonStock.gsp:139
org.codehaus.groovy.grails.web.taglib.exceptions.GrailsTagException: Error executing tag <g:form>: Error executing tag <g:selectPerson>: java.lang.OutOfMemoryError: Java heap space at /WEB-INF/grails-app/views/requisition/createNonStock.gsp:117 at /WEB-INF/grails-app/views/requisition/createNonStock.gsp:139
	at gsp_openboxes_requisitioncreateNonStock_gsp$_run_closure2.doCall(gsp_openboxes_requisitioncreateNonStock_gsp.groovy:148)
	at gsp_openboxes_requisitioncreateNonStock_gsp$_run_closure2.doCall(gsp_openboxes_requisitioncreateNonStock_gsp.groovy)
	at gsp_openboxes_requisitioncreateNonStock_gsp.run(gsp_openboxes_requisitioncreateNonStock_gsp.groovy:151)
	at grails.plugin.springcache.web.GrailsFragmentCachingFilter.doFilter(GrailsFragmentCachingFilter.groovy:66)
	at net.sf.ehcache.constructs.web.filter.Filter.doFilter(Filter.java:86)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.codehaus.groovy.grails.web.taglib.exceptions.GrailsTagException: Error executing tag <g:selectPerson>: java.lang.OutOfMemoryError: Java heap space at /WEB-INF/grails-app/views/requisition/createNonStock.gsp:117
	at gsp_openboxes_requisitioncreateNonStock_gsp$_run_closure2_closure5.doCall(gsp_openboxes_requisitioncreateNonStock_gsp.groovy:129)
	at gsp_openboxes_requisitioncreateNonStock_gsp$_run_closure2_closure5.doCall(gsp_openboxes_requisitioncreateNonStock_gsp.groovy)
	... 8 more
Caused by: org.codehaus.groovy.runtime.InvokerInvocationException: java.lang.OutOfMemoryError: Java heap space
	... 10 more
Caused by: java.lang.OutOfMemoryError: Java heap space
Exception in thread "ajp-bio-8009-exec-775" java.lang.OutOfMemoryError: Java heap space
Exception in thread "ajp-bio-8009-exec-798" java.lang.OutOfMemoryError: Java heap space
Exception in thread "Thread-11" Exception in thread "ajp-bio-8009-exec-800" java.lang.OutOfMemoryError: Java heap space
Exception in thread "ajp-bio-8009-exec-797" java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
Exception in thread "ajp-bio-8009-exec-814" java.lang.OutOfMemoryError: Java heap space
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007f8ee26c203e, pid=2897, tid=140250299295488
#
# JRE version: OpenJDK Runtime Environment (7.0_201) (build 1.7.0_201-b00)
# Java VM: OpenJDK 64-Bit Server VM (24.201-b00 mixed mode linux-amd64 compressed oops)
# Derivative: IcedTea 2.6.17
# Distribution: Ubuntu 14.04 LTS, package 7u211-2.6.17-0ubuntu0.1
# Problematic frame:
# V  [libjvm.so+0x7d103e]
#
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# An error report file with more information is saved as:
# /var/lib/tomcat7/hs_err_pid2897.log
#
# If you would like to submit a bug report, please include
# instructions on how to reproduce the bug and visit:
#   https://icedtea.classpath.org/bugzilla
#
@jmiranda
Copy link
Member Author

jmiranda commented Jan 28, 2020 •
edited

Actually this makes more sense when I view the process snapshot. It appears that there are conflicting heap size settings (-Xmx2048m vs -Xmx512) and I believe the 512m is winning. This would certainly lead to OutOfMemoryErrors even with no memory leaks.

jmiranda@openboxes:~$ ps -ef | grep tomcat
tomcat7  29200     1 99 15:11 ?        00:01:51 /usr/lib/jvm/default-java/bin/java 
-Djava.util.logging.config.file=/var/lib/tomcat7/conf/logging.properties 
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager 
-Djava.awt.headless=true -XX:+UseConcMarkSweepGC 
-Xms2048m -Xmx2048m -XX:MaxPermSize=256m 
-Djava.security.egd=file:/dev/./urandom -Dfile.encoding=UTF-8 
-Xms512m -Xmx512m -XX:MaxPermSize=256m 
-Djava.security.egd=file:/dev/./urandom -Dfile.encoding=UTF-8 
-Djava.endorsed.dirs=/usr/share/tomcat7/endorsed 
-classpath /usr/share/tomcat7/bin/bootstrap.jar:/usr/share/tomcat7/bin/tomcat-juli.jar 
-Dcatalina.base=/var/lib/tomcat7 -Dcatalina.home=/usr/share/tomcat7 
-Djava.io.tmpdir=/tmp/tomcat7-tomcat7-tmp org.apache.catalina.startup.Bootstrap start

The first setting (-Xmx2048m) comes from /etc/default/tomcat while the second one (-Xmx512m) comes from /usr/share/tomcat7/bin/setenv.sh. I commented out the latter configuration and restarted Tomcat. We'll monitor this for now and if we see it again we'll probably need to profile the application while throwing some load at it.

If/when that becomes available I'd recommend using access logs from the period 01-16-2020 to 01-28-2020 for a more accurate snapshot of requests.

cat /var/log/tomcat7/localhost_access_log.2020-01-*.txt | egrep -v "(.gif|.jpg|.png|.swf|.ico|.txt|.xml|.css|.js|.rss)" | awk '{print $6 " " $7}' | cut -d? -f1 | cut -d\; -f1 | sort | uniq -c | sort -nr

@jmiranda
Copy link
Member Author

Seems like this was resolved by setting the configuration properly.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@jmiranda