How to troubleshoot BIRT reports that consume excessive time/CPU ?
RTC 4.0.1, Tomcat J2EE, AIX 6.1
Users have gotten er, creative with BIRT somehow and I see things like this with alarming frequency (from the Active Services)
com.ibm.team.reports.service.internal.ReportRestService.postRenderReport 1 days, 07:23:31:853
com.ibm.team.reports.service.internal.ReportRestService.postRenderReport 1 days, 09:57:03:083
The Statistics Page
Web Services Longest Average Time
Seconds Name
3,888.0728 com.ibm.team.reports.common.internal.service.IReportRestService.postRenderReport()
218.8494 com.ibm.team.reports.service.internal.IReportViewerService.GET()
14.9058 com.ibm.team.workitem.service.internal.rest.IAttachmentRestService.POST()
12.9089 com.ibm.team.reports.common.service.IReportImageService.GET()
11.5733 com.ibm.team.workitem.service.internal.rest.IAttachmentRestService.GET()
10.0012 com.ibm.team.filesystem.common.IFilesystemService.getFileTreeByVersionable4()
We have to restart this repository almost weekly as the JVM heap gets exhausted with ~90% of the active JVM heap being java.lang.LinkedList elements (several HUNDRED thousand). Increasing JVM only extends the time that restart are required. During the time that these active services are seen CPU use on the LPAR is plateaued at ~45%.
Users have gotten er, creative with BIRT somehow and I see things like this with alarming frequency (from the Active Services)
com.ibm.team.reports.service.internal.ReportRestService.postRenderReport 1 days, 07:23:31:853
com.ibm.team.reports.service.internal.ReportRestService.postRenderReport 1 days, 09:57:03:083
The Statistics Page
Web Services Longest Average Time
Seconds Name
3,888.0728 com.ibm.team.reports.common.internal.service.IReportRestService.postRenderReport()
218.8494 com.ibm.team.reports.service.internal.IReportViewerService.GET()
14.9058 com.ibm.team.workitem.service.internal.rest.IAttachmentRestService.POST()
12.9089 com.ibm.team.reports.common.service.IReportImageService.GET()
11.5733 com.ibm.team.workitem.service.internal.rest.IAttachmentRestService.GET()
10.0012 com.ibm.team.filesystem.common.IFilesystemService.getFileTreeByVersionable4()
We have to restart this repository almost weekly as the JVM heap gets exhausted with ~90% of the active JVM heap being java.lang.LinkedList elements (several HUNDRED thousand). Increasing JVM only extends the time that restart are required. During the time that these active services are seen CPU use on the LPAR is plateaued at ~45%.
3 answers
Better solution:
to trace reports, you may want to add the following entry to CCM's log4j.properties:
log4j.logger.com.ibm.team.reports=DEBUG
After that reload log4j.properties for ccm:
https://your-server:9443/ccm/admin?internal=true#action=com.ibm.team.repository.admin.reloadLoggingSettings
to trace reports, you may want to add the following entry to CCM's log4j.properties:
log4j.logger.com.ibm.team.reports=DEBUG
After that reload log4j.properties for ccm:
https://your-server:9443/ccm/admin?internal=true#action=com.ibm.team.repository.admin.reloadLoggingSettings
Hello,
to trace reports, you may want to add the following entry to CCM's log4j.properties:
log4j.rootLogger=DEBUG, file
sample entry will be like:
DEBUG com.ibm.team.reports - User rafik started displaying report workitems.OpenWorkItems
Reference: Unable to trace reports (257363)
Hope it helps,
Eric.
Comments
That works, BUT waay too chatty. logger is writing a forest, I only need a glade.
I obtained the report design that the user claims is being executed. I loaded into Report project and did a preview on the data sets. None were of any significant size (54 rows, iirc was the most).
Yet here I am today facing having to restart this RTC because:
| com.ibm.team.reports.service.internal.ReportRestService.postRenderReport | 1 days, 05:12:04:383 |
Which never leads to any good outcome. <sigh>
Do you mind emailing me a copy of your report template? My email is liuy4@nationwide.com
Thanks.
After almost 1.5y and 2 RTC Upgrades these BIRT users are still in the game. Having the ability to terminate reports after some maximum run time doesn't help ( I don't think the report data is cleaned up ). Since this past Sunday, report runners have successfully crashed RTC with OOM exceptions. The most recent less than 24h following the previous.
I would like to ask what can be inferred from the following:
2014-05-21 21:34:34,765 [http-bio-9.42.60.109-9443-exec-1622 @@ 21:33 tianxing /jazz/service/com.ibm.team.reports.common.internal.service.IReportRestService/renderReport] WARN com.ibm.team.reports - User XING in project area Applications displayed report MSG73_SVT Defect BacklogAged that run a query that exceeded the result set size of 640000: SELECT DISTINCT T0."REC_DATETIME", T1."EXTERNAL_KEY1", T2."NAME", T3."NAME", T4."NAME", T5."NAME", T6."NAME", T7."NAME", T8."NAME", T1."TAGS" FROM "RIODS"."TEAM" T3, "RIODS"."ITERATION" T9, "RIODS"."PROJECT" T2, "RIODS"."REQUEST_TYPE" T5, "RIODS"."REQUEST_STATE" T6, "RICALM"."REQUEST_HISTORY" T1, "RIODS"."REQUEST_PRIORITY" T7, "RIODS"."REQUEST_SEVERITY" T8, "RICALM"."REQUEST_BASELINE" T0, "RIODS"."REQUEST_CATEGORY" T4 WHERE T1."ISSOFTDELETED" = 0 AND T2."NAME" IN ('Applications') AND T2."ISSOFTDELETED" = 0 AND T3."NAME" IN ('/Messaging Agent Team') AND T4."ISSOFTDELETED" = 0 AND T9."ISSOFTDELETED" = 0 AND T5."NAME" IN ('Defect') AND T2."PROJECT_CLASS_ID" = 4 AND T2."SOURCE_ID" LIKE '_iB9jgXVDEd2N-9KLmHeDyQ%' AND T0."REC_DATETIME" >= '2013-01-01 00:00:00.0' AND T0."REQUEST_HISTORY_ID" = T1."REQUEST_HISTORY_ID" AND T1."PROJECT_ID" = T2."PROJECT_ID" AND T1."TEAM_ID" = T3."TEAM_ID" AND T1."REQUEST_CATEGORY_ID" = T4."REQUEST_CATEGORY_ID" AND T1."ITERATION_ID" = T9."ITERATION_ID" AND T1."REQUEST_TYPE_ID" = T5."REQUEST_TYPE_ID" AND T1."REQUEST_STATE_ID" = T6."REQUEST_STATE_ID" AND T1."REQUEST_PRIORITY_ID" = T7."REQUEST_PRIORITY_ID" AND T1."REQUEST_SEVERITY_ID" = T8."REQUEST_SEVERITY_ID".
I can't fathom why the report would want information from almost 2 years gone....
I would like to ask what can be inferred from the following:
2014-05-21 21:34:34,765 [http-bio-9.42.60.109-9443-exec-1622 @@ 21:33 tianxing /jazz/service/com.ibm.team.reports.common.internal.service.IReportRestService/renderReport] WARN com.ibm.team.reports - User XING in project area Applications displayed report MSG73_SVT Defect BacklogAged that run a query that exceeded the result set size of 640000: SELECT DISTINCT T0."REC_DATETIME", T1."EXTERNAL_KEY1", T2."NAME", T3."NAME", T4."NAME", T5."NAME", T6."NAME", T7."NAME", T8."NAME", T1."TAGS" FROM "RIODS"."TEAM" T3, "RIODS"."ITERATION" T9, "RIODS"."PROJECT" T2, "RIODS"."REQUEST_TYPE" T5, "RIODS"."REQUEST_STATE" T6, "RICALM"."REQUEST_HISTORY" T1, "RIODS"."REQUEST_PRIORITY" T7, "RIODS"."REQUEST_SEVERITY" T8, "RICALM"."REQUEST_BASELINE" T0, "RIODS"."REQUEST_CATEGORY" T4 WHERE T1."ISSOFTDELETED" = 0 AND T2."NAME" IN ('Applications') AND T2."ISSOFTDELETED" = 0 AND T3."NAME" IN ('/Messaging Agent Team') AND T4."ISSOFTDELETED" = 0 AND T9."ISSOFTDELETED" = 0 AND T5."NAME" IN ('Defect') AND T2."PROJECT_CLASS_ID" = 4 AND T2."SOURCE_ID" LIKE '_iB9jgXVDEd2N-9KLmHeDyQ%' AND T0."REC_DATETIME" >= '2013-01-01 00:00:00.0' AND T0."REQUEST_HISTORY_ID" = T1."REQUEST_HISTORY_ID" AND T1."PROJECT_ID" = T2."PROJECT_ID" AND T1."TEAM_ID" = T3."TEAM_ID" AND T1."REQUEST_CATEGORY_ID" = T4."REQUEST_CATEGORY_ID" AND T1."ITERATION_ID" = T9."ITERATION_ID" AND T1."REQUEST_TYPE_ID" = T5."REQUEST_TYPE_ID" AND T1."REQUEST_STATE_ID" = T6."REQUEST_STATE_ID" AND T1."REQUEST_PRIORITY_ID" = T7."REQUEST_PRIORITY_ID" AND T1."REQUEST_SEVERITY_ID" = T8."REQUEST_SEVERITY_ID".
I can't fathom why the report would want information from almost 2 years gone....
Comments
Clement Liu
Apr 08 '13, 9:48 a.m.Do you know which report was causing this? We had the same issue before and the problem was happening when more than one of the custom attributes are used as BIRT report parameters.
Kevin Ramer
Apr 08 '13, 9:52 a.m.I do not "own" the report template; it was added by RTC users (I'm their admin, in case it's not already obvious :-) ) Is there a way to slurp the template from the innards of RTC ?
I'll review the article and inquire of the author if there are custom attributes used.
Kevin Ramer
Apr 08 '13, 10:08 a.m.Wow, that is a warehouse extension is a monstrous undertaking....
Krzysztof Kaźmierczyk
Apr 08 '13, 10:12 a.m.Hi Kevin,
You can add following property in log4j.properties for ccm:
log4j.logger.com.ibm.team.repo <wbr> rts.service=DEBUG
After adding please reload your log4j settings by navigating to https://your-server:9443/ccm/admin?internal=true#action=com.ibm.team.repository.admin.reloadLoggingSettings
This option traces which reports already started and which have finished. Once you have the issue again, you can check in the log which report did not finish.
Let me know if it helped for you.
Regards,
Krzysztof Kazmierczyk
Kevin Ramer
Apr 08 '13, 10:36 a.m.Krzysztof,
Is the <wbr> literal in the property setting ?
Clement Liu
Apr 08 '13, 11:05 a.m.Hi Kevin, I thought you were the template owner. :) it's better you discuss the performance issue with the owner first. They probably know how to fix it. Let me know if you need further help. Thanks.
Krzysztof Kaźmierczyk
Apr 09 '13, 4:07 a.m.Hi Kevin,
Sorry for typo. Here is valid property:
log4j.logger.com.ibm.team.reports.service=DEBUG
Kevin Ramer
Apr 22 '13, 7:25 a.m.I obtained the report design file and opened it in RTC Eclipse Report Design perspective. When I preview the data sets the number of rows returned is barely over 50 for the one that does return any data. The other data sets are dependent upon the first. Yet, again today the server is rendered helpless from long running reports.