Red Hat Bugzilla – Bug 115042
Versionig Code Bottlenecks CMS Publishing
Last modified: 2007-04-18 13:02:34 EDT
Description of problem: The Java code for CMS Publishing is slow. In particular, it is bottlenecked by Versioning code. Publishing an article through the CMS UI quickly consumes 100% of the front-end CPU. I'll attach OptimizeIt profiling results for this. Version-Release number of selected component (if applicable): rickshaw How reproducible: Steps to Reproduce: 1. create a new Article and take it through the simple lifecycle 2. go to the publishing page for the article and hit "Publish content item." The Java code that does the form processing for this is the bottleneck Actual results: slow performance, high front-end CPU Expected results: instantaneous response with no CPU usage at all. ;) Additional info:
Created attachment 97497 [details] OptimizeIt Profiling Results
Bryan, I may be reading this wrong, but I don't see any versioning bottlenecks here: http://lambda.boston.redhat.com/scratch/bottleneck.html#hotspots The top five offenders are oracle.jdbc.oci8.OCIDBAccess.parseExecuteDescribe (OCIDBAccess.java:1249) 9.55 5000 ms oracle.jdbc.oci8.OCIDBAccess.executeFetch (OCIDBAccess.java:1735) 6.53 3418 ms com.redhat.persistence.metadata.Model.getQualifiedName (Model.java:87) 5.99 3137 ms oracle.jdbc.oci8.OCIDBAccess.fetch (OCIDBAccess.java:2009) 3.32 1742 ms com.redhat.persistence.metadata.ObjectType.getQualifiedName (ObjectType.java:70) 3.18 1667 Three of these are in the Oracle JDBC driver. The remaining two are in persistence. Of these two, getQualifiedName() is the same bottleneck that Dan reported in bug 113696, and looks like the easiest to fix. I don't any versioning stuff here. Just I want to make sure I am not missing anything.
The hotspots list at the bottom is misleading. The oracle methods show up because the profiler can't see deeper into them. Anyway, search for the line "48.07% - 25154 ms - com.arsdigita.cms.ContentItem.createPendingVersion() (ContentItem.java:1605)" in the execution tree. That's where the versioning bottleneck starts (createPendingVersion() and its child methods take up 48.07% of the CPU). All the stuff under that method is what takes up time in creating the pending version.
Ah, ok. So, my first question is answered. When you say, "Versioning is a bottleneck", what you really mean is, createPendingVersion() is a bottleneck. That's publishing, not versioning. It just happens to have the word "version" in the method name. Secondly, it's misleading to say that the list of hot spots is misleading. I don't think there is anything wrong with the list of hot spots. We _are_ spending an inordinate amount of time in Model.getQualifiedName(). Dan's profiling (bug 113696) corroborates this. The fact that we are spending a lot of time in the Oracle JDBC driver seems accurate, too. It takes a couple hundred queries to publish an item. There's gotta be a lot of time spent in the JDBC driver. Thirdly, I think it's misleading to say createPendingVersion is a bottleneck. By the same token, we could say that TcpConnection.run() is the major bottleneck, because that's where we spend 100% of our time. Fourthly, it is not totally accurate to say that "createPendingVersion takes up 48.07% of the CPU". The entire request is served by running com.caucho.server.TcpConnection.run(). 48% of the time it takes to run the run() method from entry to exit is spent inside the createPendingVersion method. What percent of the total CPU resources is taken up by this is anybody's guess. OptimizeIt surely doesn't care and doesn't report it. I instrumented the following three classes with NestedCounter and hit "Create Content Item": //cms/dev/src/com/arsdigita/cms/ContentItem.java //core-platform/dev/src/com/arsdigita/web/BaseServlet.java //core-platform/dev/src/com/redhat/persistence/engine/rdbms/RDBMSEngine.java The (somewhat cleaned up) log4j output is as follows: [000-2] popped createPendingVersion: 33 [000-2] popped createPendingVersion: 69 [000-2] popped createPendingVersion: 33 [000-2] popped createPendingVersion: 227 [000-2] popped internalService: 240 [000-0] popped internalService: 40 [000-2] popped internalService: 0 [000-3] popped internalService: 42 [000-0] popped internalService: 28 [000-3] popped internalService: 28 The [000-0] tokens are the names of threads as output by log4j. The numbers on the right side show how many queries the method exucuted. So, a single submit results in BaseServlet's internalService method being called six times. That means six requests. Let's if we account for six requests. There is the original request initiated by me, when I click "submit". Then there are probably requests initiated by P2FS code, when it retrieves the published items over HTTP. The most expensive call to createPendingVersion is the one that took 227 queries to execute. Its matching internalService method is probably the one that executed 240 queries. We probably looking at the call that created the pending version of the Article type. The other, less expensive, calls are probably ones that create the pending versions of the article's text asset, image, etc. Anyhow, the main observation is that the percentage spent inside createPendingVersion, as reported by OptimizeIt, is in very good correlation with the number of queries that the method has to execute. In the above example of 227/240, we spend a total of 467 queries. Out of these, 227 are spent inside createPendingVersion. The other 240 are spent inside internalService, but outside createPendingVersion. (That's how NestedCounter works.) My Emacs says that (/ 227.0 (+ 227.0 240.0)) is 0.486 or 48.6%. So, to reiterate, the relative time spent inside createPendingVersion is proportional to the number of queries this method has to execute relative to the total number of queries executed inside TcpConnection.run(). If everybody agrees with this analysis, I'm going to concentrate on fixing Model.getQualifiedName(). If I'm missing something, please straighten me out.
Bryan's attachment in a slightly more readable form: +----------------------------------------------------------------------------------------+ |Hot spots |Time %| ms | |--------------------------------------------------------------------------+------+------| |o.j.oci8.OCIDBAccess.parseExecuteDescribe (OCIDBAccess.java:1249) |9.55 |5000 | |--------------------------------------------------------------------------+------+------| |o.j.oci8.OCIDBAccess.executeFetch (OCIDBAccess.java:1735) |6.53 |3418 | |--------------------------------------------------------------------------+------+------| |c.r.persistence.metadata.Model.getQualifiedName (Model.java:87) |5.99 |3137 | |--------------------------------------------------------------------------+------+------| |o.j.oci8.OCIDBAccess.fetch (OCIDBAccess.java:2009) |3.32 |1742 | |--------------------------------------------------------------------------+------+------| |c.r.persistence.metadata.ObjectType.getQualifiedName (ObjectType.java:70) |3.18 |1667 | |--------------------------------------------------------------------------+------+------| |c.r.persistence.metadata.Mist.get (Mist.java:148) |1.76 |921 ms| |--------------------------------------------------------------------------+------+------| Call tree: 67.04% service() (JavaPage.java:75) 66.89% _item__jsp (2)._jspService() (_item__jsp.java:72) 66.89% dispatch() (CMSPage.java:296) 66.89% run() (CMSExcursion.java:75) 66.89% run() (KernelExcursion.java:57) 66.89% excurse() (CMSExcursion.java:80) 66.17% excurse() (CMSPage.java:281) 66.17% buildDocument() (Page.java:758) 66.13% process() (Page.java:686) 65.71% process() (Page.java:714) 65.71% respond() (PageState.java:370) 65.55% respond() (Form.java:281) 65.51% process() (Form.java:440) 65.27% process() (FormModel.java:356) 65.27% fireFormProcess() (FormModel.java:494) 65.27% process() (FormSection.java:464) 65.27% fireProcess() (FormSection.java:490) 53.5% process() (ItemLifecycleSelectForm.java:430) 48.07% publish() (ContentItem.java:1247) 48.07% createPendingVersion() (ContentItem.java:1605) 45.72% copyItem() (VersionCopier.java:95) 45.55% createVersion() (VersionCopier.java:243) 45.55% copy() (VersionCopier.java:137) 45.01% copy() (DomainCopier.java:120) 40.45% copyData() (DomainCopier.java:179) 24.8% copyProperty() (ObjectCopier.java:115) 15.65% copyProperty() (ObjectCopier.java:126) 15.65% copyProperty() (DomainCopier.java:226) 12.08% copyRole() (DomainCopier.java:324) 11.43% copy() (VersionCopier.java:200) 11.3% createVersion() (VersionCopier.java:243) 11.3% copy() (VersionCopier.java:137) 10.96% copy() (DomainCopier.java:120) 9.01% copyData() (DomainCopier.java:179) 4.77% copyProperty() (ObjectCopier.java:126) 4.77% copyProperty() (DomainCopier.java:226) 2.35% copyRole() (DomainCopier.java:324) 2.19% set() (DomainService.java:73) 2.19% set() (ContentItem.java:385) 2.19% set() (DomainObject.java:340) 2.19% set() (DataObjectImpl.java:282) 1.97% set() (Session.java:314) 0.22% set() (Session.java:288) 0.15% domain() (DomainCopier.java:455) 0.15% newInstance() (DomainObjectFactory.java:149) 0.15% doNewInstance() (ReflectionInstantiator.java:94) 0.15% newInstance() 0.15% <init>() (Article.java:68) 0.15% <init>() (Article.java:83) 0.15% <init>() (TextPage.java:78) 0.15% <init>() (ContentPage.java:99) 0.15% <init>() (ContentItem.java:309) 0.15% <init>() (VersionedACSObject.java:63) 0.15% <init>() (ACSObject.java:101) 0.15% <init>() (ObservableDomainObject.java:48) 0.15% <init>() (DomainObject.java:148) 0.15% initialize() (ContentItem.java:333) 0.15% retrieveForACSObject() (BasicAuditTrail.java:67) 0.15% next() (DataQueryImpl.java:465) 0.15% next() (Cursor.java:108) 0.15% execute() (Cursor.java:124) 0.15% execute() (RDBMSEngine.java:252) 0.11% execute() (RDBMSEngine.java:261) 0.03% execute() (RDBMSEngine.java:260) 1.65% copyRole() (DomainCopier.java:315) 1.65% get() (DomainService.java:42) 1.65% get() (ContentItem.java:378) 1.65% get() (DomainObject.java:436) 1.65% get() (DataObjectImpl.java:224) 1.65% get() (DataObjectImpl.java:516) 1.61% get() (Session.java:145) 0.03% get() (Session.java:142) 0.45% copyRole() (DomainCopier.java:318) 0.22% copyRole() (DomainCopier.java:320) 0.03% copyRole() (DomainCopier.java:322) 0.03% copyRole() (DomainCopier.java:287) 4.24% copyProperty() (ObjectCopier.java:115) 4.24% copyProperty() (ContentItem.java:1808) 4.24% getParent() (ContentItem.java:511) 3.93% newInstance() (DomainObjectFactory.java:149) 3.93% doNewInstance() (ReflectionInstantiator.java:94) 3.93% newInstance() 3.93% <init>() (Article.java:68) 3.93% <init>() (Article.java:83) 3.93% <init>() (TextPage.java:78) 3.93% <init>() (ContentPage.java:99) 3.93% <init>() (ContentItem.java:309) 3.93% <init>() (VersionedACSObject.java:63) 3.93% <init>() (ACSObject.java:101) 3.93% <init>() (ObservableDomainObject.java:48) 3.93% <init>() (DomainObject.java:148) 3.84% initialize() (ContentItem.java:333) 0.04% initialize() (ContentItem.java:361) 0.03% initialize() (ContentItem.java:332) 0.22% get() (ContentItem.java:378) 0.03% newInstance() (DomainObjectFactory.java:146) 0.03% newInstance() (DomainObjectFactory.java:134) 1.49% copyData() (DomainCopier.java:185) 1.49% copyProperty() (ObjectCopier.java:126) 1.49% copyProperty() (DomainCopier.java:226) 1.45% copyRole() (DomainCopier.java:299) 0.03% copyRole() (DomainCopier.java:287) 0.45% copyData() (DomainCopier.java:173) 0.34% copy() (DomainCopier.java:99) 0.12% createVersion() (VersionCopier.java:249) 0.34% set() (DomainService.java:73) 0.3% domain() (DomainCopier.java:455) 1.68% copyRole() (DomainCopier.java:320) 1.39% copyRole() (DomainCopier.java:315) 0.45% copyRole() (DomainCopier.java:318) 0.03% copyRole() (DomainCopier.java:294) 3.62% copyData() (DomainCopier.java:185) 3.62% copyProperty() (ObjectCopier.java:126) 3.62% copyProperty() (DomainCopier.java:226) 3.62% copyRole() (DomainCopier.java:299) 3.54% copyCollection() (DomainCopier.java:364) 0.07% copyCollection() (DomainCopier.java:360) 0.93% copyData() (DomainCopier.java:173) 0.53% copy() (DomainCopier.java:99) 0.09% createVersion() (VersionCopier.java:249) 0.03% createVersion() (VersionCopier.java:248) 0.03% createVersion() (VersionCopier.java:240) 2.35% copyItem() (VersionCopier.java:100) 1.93% setLifecycle() (LifecycleService.java:155) 0.21% setLifecycle() (LifecycleService.java:160) 0.17% setLifecycle() (LifecycleService.java:166) 0.03% setLifecycle() (LifecycleService.java:165) 4.61% publish() (ContentItem.java:1239) 2.11% createFullLifecycle() (LifecycleDefinition.java:242) 1.24% createFullLifecycle() (LifecycleDefinition.java:223) 0.65% createFullLifecycle() (LifecycleDefinition.java:235) 0.25% createFullLifecycle() (LifecycleDefinition.java:227) 0.22% createFullLifecycle() (LifecycleDefinition.java:221) 0.07% createFullLifecycle() (LifecycleDefinition.java:245) 0.03% createFullLifecycle() (LifecycleDefinition.java:226) 0.49% publish() (ContentItem.java:1231) 0.24% publish() (ContentItem.java:1230) 0.07% publish() (ContentItem.java:1255) 6.47% process() (ItemLifecycleSelectForm.java:507) 6.18% finish() (UserTask.java:283) 5.56% finish() (CMSTask.java:483) 2.37% finish() (Task.java:1044) 2.37% notifyFinished() (Task.java:1153) 1.48% updateState() (Workflow.java:566) 1.29% finish() (Task.java:1027) 0.15% finish() (Task.java:1036) 0.03% finish() (Task.java:1026) 0.36% updateState() (Workflow.java:557) 0.33% updateState() (Workflow.java:544) 0.15% updateState() (Workflow.java:578) 0.03% updateState() (Workflow.java:548) 1.55% finish() (Task.java:1028) 1.48% finishEvt() (UserTask.java:330) 0.07% finishEvt() (UserTask.java:327) 1.05% finish() (Task.java:1027) 0.5% finish() (Task.java:1036) 0.07% finish() (Task.java:1026) 0.61% finish() (CMSTask.java:485) 0.29% finish() (UserTask.java:277) 1.5% process() (ItemLifecycleSelectForm.java:499) 1.08% getEnabledTasks() (Engine.java:254) 0.38% getEnabledTasks() (Engine.java:244) 0.03% getEnabledTasks() (Engine.java:238) 1.02% process() (ItemLifecycleSelectForm.java:424) 1.02% isPublished() (ContentItem.java:1349) 0.79% getLifecycle() (ContentItem.java:1318) 0.22% getLifecycle() (ContentItem.java:1312) 0.83% process() (ItemLifecycleSelectForm.java:493) 0.82% process() (ItemLifecycleSelectForm.java:476) 0.58% process() (ItemLifecycleSelectForm.java:474) 0.32% process() (ItemLifecycleSelectForm.java:368) 0.15% process() (ItemLifecycleSelectForm.java:505) 0.03% process() (ModalPanel.java:332) 0.2% process() (FormModel.java:329) 0.03% process() (FormModel.java:345) 0.03% process() (Form.java:434) 0.16% respond() (Form.java:286) 0.34% process() (Page.java:702) 0.07% process() (Page.java:709) 0.03% process() (Page.java:683) 0.72% excurse() (CMSPage.java:272) 0.15% _item__jsp (2)._jspService() (_item__jsp.java:56)
Hi, you are correct that I meant "thread", not "CPU" in my paranthetical comment. However, I do have data for the total CPU usage, and that thread takes up about 94% of the total CPU usage during my profiling. So, you can scale the numbers by 0.94 if you wish. When I say the hotspots are misleading, I mean that they are not the real problem. For example, c.r.persistence.metadata.Model.getQualifiedName() only takes up 6% of the thread. But, the front-end performance is already slow and bottlenecked at just 5 concurrent users for this page (over 6 seconds for the page during a publishing test). Now, my publishing test encompasses more than this publishing page as it has to go through the process of creating the article before it can publish it. But, the other pages during this test all return quickly, except for the page in bugzilla 115041. At 30 users, other pages still return within a couple seconds. But, this page takes about 23 seconds at that load level. Optimizing a method that takes just 6% of the thread doesn't really fix the performance problem. That's why I pointed you to createPendingVersion() (and it's subsequent calls to VersionCopier.createVersion()), which is where most of the work occurs. We need to improve the high-level process of what that code accomplishes, not just optimize a hotspot method in order to get performance to a more reasonable level.
The java hot spot fixed on the trunk in change 40336. (The DB-bound bottleneck remains.)
Confirmed that this page is no longer a bottleneck in the publishing process.