2006 IR Open Discussion Posted August 19, 2006 Share Posted August 19, 2006 By: Claudio Pi - claudiopi Long Reports Timing and Profiler Results 2003-07-12 07:51 Long Reports Timing and Profiler Results Hi: We have developed a web application that contains aprox. 40 JasperReports. We are going into production soon and we are having performance problems regarding the large ones (between 5000 and 10000 rows and 15 columns). I have already read the thread http://sourceforge.net/forum/message.php?msg_id=1746461, but found no answer to the problem. So I decided to use JProfiler to see what was going on. Test enviroment: PIV 1.7Ghz, 512Mb RAM, WinXP SP 1 Sun JDK 1.4.2 JasperReports 0.5.0 itext 0.96 Tomcat 4.1.24 MS SQLServer 2000 SP3. Test case: Report with 5360 Rows and 14 columns. Timing Results (in average): Total Time (without profiler running) 44183ms (70ms parameters, 260ms query and resultset load, 43853 report filling). Partial Invocation Tree View (Percentage of time in each method, I hope this is posted ok, if not I have an HTML version of it): -------------------------------------------------------------------------------- 93.0% - 260082 ms - 1 inv. dori.jasper.engine.JasperRunManager.runReportToPdf 82.7% - 231269 ms - 1 inv. dori.jasper.engine.JasperFillManager.fillReport 82.4% - 230289 ms - 1 inv. dori.jasper.engine.JasperFillManager.fillReport 82.3% - 230147 ms - 1 inv. dori.jasper.engine.fill.JRFiller.fillReport 81.2% - 227118 ms - 1 inv. dori.jasper.engine.fill.JRBaseFiller.fill 81.2% - 227099 ms - 1 inv. dori.jasper.engine.fill.JRVerticalFiller.fillReport 69.8% - 195070 ms - 5359 inv. dori.jasper.engine.fill.JRVerticalFiller.fillReportContent 68.1% - 190500 ms - 5359 inv. dori.jasper.engine.fill.JRVerticalFiller.fillDetail 61.2% - 171169 ms - 5359 inv. dori.jasper.engine.fill.JRVerticalFiller.fillColumnBand 39.6% - 110598 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.fill 39.6% - 110582 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.fill 36.2% - 101259 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.prepareElements 35.5% - 99353 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.prepare 34.0% - 95163 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.chopTextElement 10.5% - 29275 ms - 75026 inv. java.awt.font.LineBreakMeasurer.<init> 10.3% - 28708 ms - 75026 inv. java.awt.font.LineBreakMeasurer.nextLayout 5.4% - 15076 ms - 150052 inv. java.awt.font.TextLayout.getLeading 2.6% - 7361 ms - 75026 inv. java.text.AttributedString.<init> 0.5% - 1280 ms - 75026 inv. java.text.AttributedString.getIterator 0.3% - 934 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.setStretchHeight 0.2% - 577 ms - 75026 inv. java.util.StringTokenizer.nextToken 0.2% - 451 ms - 75026 inv. java.util.StringTokenizer.<init> 0.2% - 429 ms - 300104 inv. java.awt.font.LineBreakMeasurer.getPosition 0.1% - 415 ms - 225078 inv. java.lang.String.length 0.1% - 408 ms - 150052 inv. java.util.StringTokenizer.hasMoreTokens 0.1% - 376 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.getWidth 0.1% - 309 ms - 225078 inv. dori.jasper.engine.fill.JRFillTextField.getText 0.1% - 240 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.getHeight 0.1% - 232 ms - 150052 inv. java.awt.font.TextLayout.getAscent 0.1% - 212 ms - 150052 inv. dori.jasper.engine.fill.JRFillTextElement.getTextEnd 0.1% - 179 ms - 150052 inv. java.awt.font.TextLayout.getDescent 0.1% - 163 ms - 75026 inv. java.lang.String.substring 0.1% - 151 ms - 75026 inv. java.lang.String.equals 0.1% - 144 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.getFloatLineSpacing 0.1% - 143 ms - 75026 inv. java.awt.font.LineBreakMeasurer.setPosition 0.0% - 131 ms - 150052 inv. dori.jasper.engine.fill.JRFillTextElement.getTextHeight 0.0% - 107 ms - 75026 inv. java.text.AttributedCharacterIterator.getBeginIndex 0.0% - 98 ms - 75026 inv. dori.jasper.engine.base.JRBaseFont.getAttributes 0.0% - 97 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.getFontRenderContext 0.0% - 84 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.getFont 0.0% - 78 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.setAbsoluteLineSpacing 0.0% - 71 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.setTextHeight 0.0% - 64 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.setTextStart 0.0% - 63 ms - 75026 inv. java.text.AttributedCharacterIterator.getEndIndex 0.0% - 56 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.getTextStart 0.0% - 44 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.setTextEnd 0.2% - 607 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.prepare 0.1% - 350 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.isRemoveLineWhenBlank 0.1% - 318 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getEvaluationTime 0.1% - 255 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.isPrintRepeatedValues 0.1% - 226 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.getY 0.1% - 220 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.isStretchWithOverflow 0.0% - 91 ms - 75026 inv. java.lang.String.length 0.0% - 86 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getText 0.0% - 81 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.setReprinted 0.0% - 76 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.getBandBottomY 0.0% - 67 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.isToPrint 0.0% - 66 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.isPrintWhenExpressionNull 0.0% - 59 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.getRelativeY 0.0% - 58 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.setToPrint 0.0% - 51 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.getTextEnd 0.2% - 510 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.moveDependantElements 0.1% - 338 ms - 80385 inv. dori.jasper.engine.fill.JRFillBand.getHeight 0.0% - 128 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.isToPrint 0.0% - 50 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.getStretchHeight 0.0% - 49 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.getRelativeY 3.0% - 8364 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.fillElements 0.2% - 672 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.resetElements 0.0% - 74 ms - 5359 inv. java.util.HashMap.<init> 0.0% - 33 ms - 5359 inv. java.lang.Thread.isInterrupted 0.0% - 18 ms - 5359 inv. java.lang.Thread.currentThread 0.0% - 6 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.moveBandBottomElements 0.0% - 5 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.stretchElements 0.0% - 3 ms - 5359 inv. dori.jasper.engine.fill.JRBaseFiller.isInterrupted 0.0% - 3 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.removeBlankElements 21.1% - 58917 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.evaluate 21.0% - 58698 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.evaluate 20.3% - 56785 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.evaluateText 15.8% - 44309 ms - 375130 inv. dori.jasper.engine.fill.JRCalculator.evaluate 15.4% - 43061 ms - 375130 inv. dori.jasper.engine.fill.JRCalculator.evaluate 7.2% - 20260 ms - 75026 inv. ActivosAVencerOficial.evaluate 0.0% - 58 ms - 75026 inv. dori.jasper.engine.base.JRBaseExpression.getId 2.9% - 8126 ms - 75026 inv. dori.jasper.engine.util.JRStringUtil.treatNewLineChars 0.1% - 418 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getExpression 0.1% - 368 ms - 75026 inv. java.lang.String.valueOf 0.1% - 307 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getHyperlinkPageExpression 0.1% - 306 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getHyperlinkAnchorExpression 0.1% - 287 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getAnchorNameExpression 0.1% - 258 ms - 75026 inv. java.lang.String.equals 0.1% - 257 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getHyperlinkReferenceExpression 0.0% - 81 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getText 0.0% - 70 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.setTextEnd 0.0% - 64 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.setTextStart 0.2% - 635 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.evaluatePrintWhenExpression 0.2% - 580 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextElement.reset 0.1% - 180 ms - 75026 inv. dori.jasper.engine.fill.JRFillTextField.getEvaluationTime 0.0% - 64 ms - 75026 inv. dori.jasper.engine.fill.JRFillElement.isPrintWhenExpressionNull 0.0% - 4 ms - 5359 inv. dori.jasper.engine.fill.JRFillElementGroup.getElements 0.5% - 1508 ms - 5359 inv. dori.jasper.engine.fill.JRVerticalFiller.fillBand 0.0% - 23 ms - 5359 inv. dori.jasper.engine.fill.JRFillBand.getHeight 0.0% - 7 ms - 10718 inv. dori.jasper.engine.fill.JRFillBand.willOverflow 0.0% - 6 ms - 5359 inv. dori.jasper.engine.fill.JRPrintBand.getHeight 5.7% - 15847 ms - 148 inv. dori.jasper.engine.fill.JRVerticalFiller.fillColumnBreak 1.2% - 3261 ms - 5359 inv. dori.jasper.engine.fill.JRCalculator.calculateVariables 0.0% - 60 ms - 10718 inv. dori.jasper.engine.fill.JRFillBand.isPrintWhenExpressionNull 0.0% - 59 ms - 10718 inv. dori.jasper.engine.fill.JRFillBand.isToPrint 0.0% - 11 ms - 5359 inv. dori.jasper.engine.JRAbstractScriptlet.callBeforeDetailEval 0.0% - 10 ms - 5507 inv. dori.jasper.engine.fill.JRFillBand.getHeight 0.0% - 9 ms - 5359 inv. dori.jasper.engine.JRAbstractScriptlet.callAfterDetailEval 1.5% - 4066 ms - 5359 inv. dori.jasper.engine.fill.JRCalculator.estimateGroupRuptures 0.1% - 317 ms - 5359 inv. dori.jasper.engine.fill.JRCalculator.initializeVariables 0.0% - 21 ms - 5359 inv. dori.jasper.engine.fill.JRVerticalFiller.fillGroupFooters 0.0% - 17 ms - 5359 inv. dori.jasper.engine.fill.JRBaseFiller.resolveGroupBoundTexts 0.0% - 17 ms - 5359 inv. dori.jasper.engine.JRAbstractScriptlet.callAfterGroupInit 0.0% - 15 ms - 5359 inv. dori.jasper.engine.JRAbstractScriptlet.callBeforeGroupInit 0.0% - 14 ms - 5359 inv. dori.jasper.engine.fill.JRBaseFiller.resolveGroupBoundImages 0.0% - 10 ms - 5359 inv. dori.jasper.engine.fill.JRVerticalFiller.fillGroupHeaders 10.8% - 30099 ms - 5361 inv. dori.jasper.engine.fill.JRBaseFiller.next 0.5% - 1346 ms - 1 inv. dori.jasper.engine.fill.JRVerticalFiller.fillReportStart 0.2% - 555 ms - 1 inv. dori.jasper.engine.fill.JRVerticalFiller.fillReportEnd 0.0% - 1 ms - 12 inv. java.util.HashMap.<init> 0.0% - 0 ms - 2 inv. java.util.Map.put 0.0% - 0 ms - 2 inv. dori.jasper.engine.fill.JRFillGroup.getName 0.0% - 0 ms - 1 inv. dori.jasper.engine.fill.JRBaseFiller.setParameters 0.0% - 0 ms - 6 inv. dori.jasper.engine.JasperPrint.addFont 0.0% - 0 ms - 1 inv. dori.jasper.engine.JasperPrint.<init> 0.0% - 0 ms - 3 inv. java.util.Map.get 0.0% - 0 ms - 3 inv. java.util.Map.put 0.0% - 0 ms - 3 inv. dori.jasper.engine.fill.JRBaseFiller.setParameter 0.8% - 2298 ms - 1 inv. dori.jasper.engine.fill.JRBaseFiller.<clinit> 0.2% - 673 ms - 1 inv. dori.jasper.engine.fill.JRVerticalFiller.<init> 0.0% - 0 ms - 1 inv. dori.jasper.engine.fill.JRVerticalFiller.<clinit> 0.0% - 0 ms - 1 inv. dori.jasper.engine.base.JRBaseReport.getPrintOrder 0.3% - 875 ms - 1 inv. dori.jasper.engine.util.JRLoader.loadObject 0.0% - 73 ms - 1 inv. dori.jasper.engine.util.JRLoader.<clinit> 0.0% - 0 ms - 1 inv. java.io.File.<init> 10.3% - 28736 ms - 1 inv. dori.jasper.engine.JasperExportManager.exportReportToPdf -------------------------------------------------------------------------------- In the above results you can see what methods are taking more time in the filling process. I hope this information helps you and any solution to lower the loading time of large reports is welcomed. Regards, Claudio. Link to comment Share on other sites More sharing options...
Recommended Posts
Create an account or sign in to comment
You need to be a member in order to leave a comment
Create an account
Sign up for a new account in our community. It's easy!
Register a new accountSign in
Already have an account? Sign in here.
Sign In Now