Memory leak whilst generating reports?

[eddgrant]

Hi all,

I'm trying to debug a memory related issue with JasperReports 6.1. We're generating reports which are ~9000 pages in length. Each time we generate a report more objects are allocated on to the JVM heap which never get GC'd. After the generation of a number of these reports the JVM eventually dies with an OOME. I initially thought we might just have insufficient headroom on the heap so I've increased the Xmx all the way up to 12GB to no avail.

I have profiled the running JVM and can see that the objects which take up the most memory on the heap are the following Jasper classes:

1. net.sf.jasperreports.engine.fill.JRTemplatePrintText
2. net.sf.jasperreports.engine.fill.JRTemplatePrintLine

They also contain references to various other data types, such as char[], String, short[] and java.util.Date which are taking up considerable amounts of memory.

We are using the FileVirtualizerFactory Virtualiser, configured with a maxSize of 3000.

I have run various tests ranging from single user up to 5 concurrent users, but the issue doesn't seem to have anything to do with the level of concurrency. Rather it seems to be the case that each report generation simply takes up more heap which never gets GC'd.

I'n not familiar with Jasper as a product (yet) so would be most grateful for advice on how to go about resolving this issue.

Many thanks,

Edd

 

 

[joseng62]

Hard to pin point the issue. Need more info. What are the server memory settings you are running? I'll give you an example.
I uses the setenv.bat or setenv.sh to set my java memory allocation to apache tomcat. set JAVA_OPTS=%JAVA_OPTS% -Xms2048m -Xmx4096m -XX:PermSize=128m set JAVA_OPTS=%JAVA_OPTS% -XX:MaxPermSize=512m -Xss20m -XX:+UseConcMarkSweepGC set JAVA_OPTS=%JAVA_OPTS% -XX:+CMSClassUnloadingEnabled You have different type of GarbageC settings you can set depending on your envirn.
Also I noticed in some threads there are recommendations to set -Xss to 2m, This is not enough and causes memory issues. So I set mine to 20m and no issues so far. We generate millions of records in ad hoc reports.

Another issue might be the report.jrxml has a design error and might be looping the data. When you run this report in jasperstudio do you also get so many pages?(Need to test against same datasource) Does it seems that the data is recurring? You might have a SQL query issue in this regard.

Are you running the report in jasperserver or are you making a call via REST services. I have experience issue with reports when requested via REST and then the user moves to another pages. Then the report cancellation is not sent. One should send a report cancellation request when user decide to move to another page, report etc.

Also you could hook up the jvm stats like jstats to jasper and then monitor the memory usage via jv monitoring. This helps me to find and test memory issues. Also set the logging of relevant log class names to debug and then review the jasperserver.log for any issues. Hope this helps

[hozawa]

Virtualizer is only about virtual memory to generate a report so it shouldn't matter.

Which Java version are you using? Oracle Java 8u92? Which application server are you using? Tomcat 8.0.35? I've encountered a memory problem with earlier revision of Tomcat 8.

[eddgrant]

Thanks for the responses folks, sorry I should have thought to mention the various configuration points, we're actually using the Tibco AMI from AWS marketplace, this provides the following:

JVM: OpenJDK "1.7.0_91" 64 bit

Tomcat:  7.0.62

And we've configured our JVM Options as follows: -Xms2048m -Xmx13000m -XX:MaxPermSize=2048m -Xss2m

@joseng62 - I don't have access to jasperstudio but I'll ask the guys who run the reports to do the checks you outlined. Will also check about report cancellation. I notice that we're using -Xss2m, do you think it's worth changing this to 20m as you mentioned?

Cheers,

Edd

 

 

[joseng62]

Hi edd , sorry for the late reply. 

Yes change the amount to 20m. I aslo had issue when set to 2m. Memory issues when large dataset where being generated. 
Setting mine to 20m solve the problem.

[stephen.tjasink]

Hi all, thanks for your suggestions so far.  Edd is away for a couple of weeks, so I am continuing his investigation while he is away.

I have raised the stack size to 20m but still have the same issue.

I found the report's SQL in the logs and ran that against the database directly and it gave the same (or similar) number of results that are in the report, so I don't think that it is a problem with recursion in the report definition.

If I just use JMeter to run the same report over and over, the Tomcat heap eventually just gets used up.  This is the GC log (apologies for the spam):

[GC 4034905K->568824K(5544448K), 0.3368280 secs]

[GC 4440056K->966765K(4985344K), 0.5592830 secs]

[GC 4262509K->1319244K(5264896K), 0.4444350 secs]

[GC 4614988K->1655139K(4642304K), 0.6952570 secs]

[Full GC 1655139K->1550370K(5664768K), 4.3724110 secs]

[GC 4223522K->1740852K(5976064K), 0.3938920 secs]

[GC 4414004K->2268230K(5917184K), 0.4821700 secs]

[GC 4924998K->2587592K(5967872K), 0.6886060 secs]

[Full GC 2587592K->1924127K(7040512K), 4.8828930 secs]

[GC 4580895K->2222480K(6961152K), 0.1937110 secs]

[GC 4922256K->2500060K(7004672K), 0.2865130 secs]

[GC 5199836K->2777469K(6830080K), 0.4208550 secs]

[GC 5268349K->2959652K(6957568K), 0.5378160 secs]

[GC 5450532K->3165996K(6862848K), 0.3127500 secs]

[GC 5581100K->3405117K(6880768K), 0.4082440 secs]

[GC 5820221K->3631438K(6317568K), 0.5493780 secs]

[GC 5405518K->3742543K(6599168K), 0.6126710 secs]

[Full GC 3742543K->3310325K(8375808K), 7.8715060 secs]

[GC 5084405K->3463662K(8361472K), 0.0836920 secs]

[GC 5263342K->3622388K(8381440K), 0.1433420 secs]

[GC 5422068K->3784039K(8281088K), 0.2208780 secs]

[GC 5632359K->3946711K(8331264K), 0.2477260 secs]

[GC 5795031K->4010631K(8462848K), 0.2730820 secs]

[GC 6049927K->4085143K(8489984K), 0.3011720 secs]

[GC 6124439K->4264430K(8351744K), 0.3624840 secs]

[GC 6146030K->4433242K(8274944K), 0.4172300 secs]

[GC 6314842K->4576218K(8148992K), 0.4790470 secs]

[GC 6055386K->4631779K(8228352K), 0.4872590 secs]

[GC 6110947K->4761540K(8228352K), 0.5844380 secs]

[GC 6240708K->4897548K(8228352K), 0.5790970 secs]

[GC 6376716K->5032240K(8228352K), 0.5546170 secs]

[GC 6511408K->5166078K(8228352K), 0.4849780 secs]

[GC 6645246K->5239757K(8228352K), 0.4251070 secs]

[GC 6718925K->5343446K(8228352K), 0.3294840 secs]

[Full GC 5343446K->5140864K(10412544K), 9.4387930 secs]

[GC 6620032K->5271200K(10412544K), 0.0683500 secs]

[GC 6750368K->5404848K(10412544K), 0.1107890 secs]

[GC 6884016K->5539358K(10412544K), 0.2513420 secs]

[GC 7018526K->5672498K(10412544K), 0.1694490 secs]

[GC 7151666K->5801195K(10412544K), 0.1638750 secs]

[GC 7280363K->5932587K(10412544K), 0.1556460 secs]

[GC 7411755K->6061707K(10412544K), 0.1588890 secs]

[GC 7540875K->6195139K(9065984K), 0.1567570 secs]

[GC 7674307K->6324590K(10439168K), 0.1175850 secs]

[GC 7878510K->6554511K(9500160K), 0.2194170 secs]

[GC 8108431K->6716094K(10396160K), 0.2752690 secs]

[GC 8336062K->6789191K(10392064K), 0.3042650 secs]

[GC 8409159K->6789905K(10532864K), 0.2959460 secs]

[GC 8533777K->6820597K(9955840K), 0.3312610 secs]

[GC 8564469K->6821733K(10528768K), 0.3286780 secs]

[GC 8541541K->6816405K(9927680K), 0.3320400 secs]

[GC 8536213K->6843656K(10532352K), 0.3434230 secs]

[GC 8567560K->7163009K(10278400K), 0.5033530 secs]

[GC 8886913K->7355399K(10400256K), 0.5848590 secs]

[GC 8834567K->7448272K(10412544K), 0.6240160 secs]

[GC 8927440K->7478102K(10412544K), 0.6803290 secs]

[GC 8957270K->7692903K(10412544K), 0.7845740 secs]

[GC 9172071K->7813112K(10412544K), 0.7222370 secs]

[GC 9292280K->7981816K(10412544K), 0.8328620 secs]

[GC 9460984K->7973713K(10412544K), 0.6589410 secs]

[GC 9452881K->8105167K(10412544K), 0.5629750 secs]

[Full GC 8105167K->7233912K(11832832K), 8.0494410 secs]

[GC 8713080K->7385048K(11832832K), 0.0936790 secs]

[GC 8864216K->7530168K(11832832K), 0.1458690 secs]

[GC 9009336K->7681751K(11832832K), 0.2592910 secs]

[GC 9160919K->7833392K(11832832K), 0.3077190 secs]

[GC 9312560K->7982317K(11832832K), 0.1994950 secs]

[GC 9461485K->8132273K(11832832K), 0.2011720 secs]

[GC 9611441K->8278774K(11832832K), 0.2022270 secs]

[GC 9757942K->8480532K(11832832K), 0.2237010 secs]

[GC 9959700K->8633676K(11832832K), 0.2492980 secs]

[GC 10112844K->8764137K(11832832K), 0.1964140 secs]

[Full GC 8764137K->8084509K(11832832K), 7.5709440 secs]

[GC 9563677K->8215341K(11832832K), 0.0752560 secs]

[GC 9694509K->8347988K(11832832K), 0.1221960 secs]

[GC 9827156K->8476524K(11717120K), 0.1395310 secs]

[GC 9955692K->8611180K(11774976K), 0.1424800 secs]

[GC 10090348K->8743681K(11624448K), 0.2117340 secs]

[GC 10319617K->8847793K(11700224K), 0.2003250 secs]

[GC 10423729K->8859913K(11700736K), 0.2212730 secs]

[GC 10538761K->8958448K(11734016K), 0.2417630 secs]

[GC 10637296K->9108921K(11801600K), 0.2984520 secs]

[GC 10851769K->9261774K(11854336K), 0.3499950 secs]

[GC 11004622K->9416782K(11720704K), 0.4368060 secs]

[GC 10931790K->9449206K(11490304K), 0.4126580 secs]

[GC 10964214K->9533366K(11832832K), 0.4383690 secs]

[GC 11012534K->9667590K(11832832K), 0.4803880 secs]

[Full GC 9667590K->9588100K(11832832K), 12.3783880 secs]

[Full GC 11067268K->9714934K(11832832K), 15.6042930 secs]

[Full GC 10353614K->9771941K(11832832K), 9.4606700 secs]

[Full GC 10353568K->9824168K(11832832K), 14.4460790 secs]

It seems that there must be some caching or something happening that is not being cleared.  There are a number of ehcache configuration files in WEB-INF which I could experiment with, but I thought that I would ask again before doing that.  Has anyone had any problems with over-caching or other memory consumption in Jasper Reports?

Edit for more information:

The report above returned over 200,000 results.  I ran a test with more restrictive parameters which returned about 1,200 results.  I could run 10 of these concurrently 50 times over without using up the heap.  In fact, it used under 3GB whereas the test above got up to over 10GB very quickly.  So this does seem to be something related to large result sets.  If the users can stick to running reports with smaller result sets (which may not be possible given their business needs), that may avoid this but it still seems that there must be a problem somewhere if running a single large report over and over causes Jasper to exhaust its heap.  Any further suggestions welcomed!

Thanks

Stephen

 

[joseng62]

mmmm? this is strange behavior.

 

You are running a custom build report in jasperstudio. jrxml? and not in ad hoc reports?

Reason I am asking is because standard jrxml should not be taking up so much memory. 3GB or even 10Gb for one report's data returned is definitely not right. Based on my experience Ad hoc reports from Pro uses a lot of cache due to loading the data in memory for manipulation and standard jrxml do not use up a lot of cache. It usually uses disk/file based memory due to filling up the pages one by one.

 

1) So have you test this report in JasperStudio on same data set with same parameters? There might be a loop that just keeps on generating pages based on your db rows size or parameters selected for SQL query. If that when generating the report in studio the pages just keep on piling on until studio runs out of memory.

 

2) Are you using a crosstab in your report? Might be an issue with the bucket list size.

 

3) Try different Garbage collecting settings. example XX:+UseConcMarkSweepGC

 

4) Also have a look at the Diagnostic report under Public to confirm properties set. ( I am not sure if community has this thou)

 

5) When Starting up jasper server with your jvm linked up is it idling memory wise. When I run my memory tests I always made sure in the scenario I am testing, is isolated from any other resources on jasper. Just to ensure there are no underlying issues.

So the memory Heap and Perm should be idling just after 5 minutes when starting up jasper. Then when you run the report you can immediately see the memory being utilized. (I suspect you are doing this, just confirming)

 

6) Also use development tool in the browser, there might be an error popping up.

Even have a look at the http requests with their payloads. You should be able to identify the parameters being sent and also the values being returned.

 

7) In your jasperserver.log what is the heap space error being logged? There might be an indication of what the issues is.

 

After all of this, all I could say is. I know how you feel. I had memory caching issues and spend almost 2 months on/off trying to figure it out. Hooking up JVM, using different JAVA_OPTS settings, Looking for logs errors, using jmeter etc.

 

 

 

[stephen.tjasink]

Thanks for the tips joseng62

I should have said before - these are ad hoc reports running in Pro.  It looks like that changes the type of things that we should be looking for then, based on your comments above?  We have Pro but on an hourly AWS license, so don’t have the full support from what I understand.  I see you mentioned that ad hoc reports use a lot of cache - I suspect it might be this that is not being cleared for some reason.

Other people have set the reports up so I don't know that much about them but have started to look into them. The main report that I have been using for testing looks quite simple - it is selecting from a single table and filtering the results on some of the columns.  I can see the SQL and the bind parameters in the log because I enabled that in the log4j config.

1. Is the JasperStudio test not relevant for ad hoc reports?
   
2. I don’t think there is a cross tab in the report
   
3. I will try some different GC settings, thanks for the suggestion
   
4. I do have the Diagnostic option so I’ll have a look through the settings - not quite sure what to look for in there though!
   
5. I think it idles heap-wise.  There are a few GC logs while it is starting up, but then they stop.  Edd checked this with jconsole before, but I have not been able to connect it.
   
6. Sometimes I do get errors, but not sure if they are related - my JMeter script sometimes generates 404 errors because something that it recorded has disappeared.
   
7. I tried to run a test again to get an OutOfMemoryError but it didn’t happen - it just got into a loop of continual full GC and not reclaiming anything.  I’ll try again later after a few other tests.
   

Thanks again

Stephen

[joseng62]

Hi Stephen, 
Ad hoc report does change my suggestions a bit. 
I acutally had issue with Ad hoc report as well. 
Are you using a securty file in the domain setup? 
I realise when using the securty file, Jasper does not apply the filter based on the security file. Jasper first collect all the data and then applies filter based on security file.
So in my case then data returned from DB was a lot, but it only displayed the filtered data.

Also jasper allocated spesific memory to ad hoc reports.
You need to allocate more memory to ad hoc report if caching a lot of data.   
- So you can go edit ..apache-tomcatwebappsjasperserver-proWEB-INFadhoc-ehcache.xml

<ehcache name="adhocCache"  maxBytesLocalHeap="4G" maxBytesLocalDisk="8G">

maxBytesLocalHeap is recommened to be half your memory allocated to Jasper, but this just depend on your data size in ad hoc and user use.  

maxBytesLocalDisk is recommened to be double maxBytesLocalHeap

- Then you could set the cache timing as well. You can set time that best suits your situation. You can read up more about this in jasper manual. You can even disable cache as well.

<cache name="adhocCache"
timeToIdleSeconds="180"  
timeToLiveSeconds="30"  
overflowToDisk="false"
diskPersistent="false"
statistics="true" >

- Also make sure cache sharing is enable if users are going to use same  datasets. You can aslo find this in jasper manual.
 File: ..apache-tomcatwebappsjasperserver-proWEB-INFapplicationContext-datarator.xml   

So here are answers on your questions:

1. Is the JasperStudio test not relevant for ad hoc reports?
   Yes, jasperstudio will not be relevent for ad hoc reports.
2. I don’t think there is a cross tab in the report
   Ad hoc reports give user the options to display data in table, crosstab or chart format.
3. I will try some different GC settings, thanks for the suggestion
   Pleasure
4. I do have the Diagnostic option so I’ll have a look through the settings - not quite sure what to look for in there though!
   This is just to confirm your settings are applied correclty. Example your memory settings. Also when you get use to the report, it become helpfull due to other data being display as well.
5. I think it idles heap-wise.  There are a few GC logs while it is starting up, but then they stop.  Edd checked this with jconsole before, but I have not been able to connect it.
   In my experience, Perm wise should, not to be more than 512 MB. Heap, if idle then you can generate the report, see the load on the cache. Then based on ad hoc cache settings the cache should clear in time selected. Aslo you can manually clear the cahce via jasper serve as admin. Under "Manage" and then "Ad hoc Cache"   
   You can also use Ad hoc Settings to improve ad hoc. See japser manual. 
   You can also enable Enable View Query in Ad Hoc Editor, So you do not need to get query from log, you can view it in ad hoc report.
6. Sometimes I do get errors, but not sure if they are related - my JMeter script sometimes generates 404 errors because something that it recorded has disappeared.
   Pinpoint a scenarion where you get error every time, then recreate same error, check log, clear & restart tomcat(jasper). Recreate same error, check logs agian. You should be getting same error, other wise you might have underlying errors that are causing a lot of issues.
7. I tried to run a test again to get an OutOfMemoryError but it didn’t happen - it just got into a loop of continual full GC and not reclaiming anything.  I’ll try again later after a few other tests
   Jasper should eventually give you a headspace error. It does take some time after the heap is used up. After the error, jasper will be responsive but very slow, and your heap memory will still be max out. Give it 5 to 10 minutes after you see heap memory is full. 

 

[jonathan.t.higa.ctr]

I don't have a solution, but I did discover a mitigating factor. I configured a JRGzipVirtualizer with four (yes, only four) pages, and my report's JRTemplatePrintText memory leak dropped from 47 MB to 0.16 MB. I propose the hypothesis that pageOut has the convenient side effect of countering the memory leak.

Does that lead me to a suspicious place in the JasperReports code? Not yet. I'm still hunting.