Bug 115042 - Versionig Code Bottlenecks CMS Publishing
Versionig Code Bottlenecks CMS Publishing
Status: CLOSED RAWHIDE
Product: Red Hat Enterprise CMS
Classification: Retired
Component: other (Show other bugs)
nightly
All Linux
medium Severity medium
: ---
: ---
Assigned To: Vadim Nasardinov
Jon Orris
:
Depends On: 113696
Blocks: 113496
  Show dependency treegraph
 
Reported: 2004-02-05 14:56 EST by Bryan Che
Modified: 2007-04-18 13:02 EDT (History)
0 users

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2004-02-17 15:03:12 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)
OptimizeIt Profiling Results (20.36 KB, application/octet-stream)
2004-02-05 14:57 EST, Bryan Che
no flags Details

  None (edit)
Description Bryan Che 2004-02-05 14:56:25 EST
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:
Comment 1 Bryan Che 2004-02-05 14:57:12 EST
Created attachment 97497 [details]
OptimizeIt Profiling Results
Comment 2 Vadim Nasardinov 2004-02-05 18:17:33 EST
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.
Comment 3 Bryan Che 2004-02-05 19:29:46 EST
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.
Comment 4 Vadim Nasardinov 2004-02-06 18:28:36 EST
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.
Comment 5 Vadim Nasardinov 2004-02-06 18:30:12 EST
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)
Comment 6 Bryan Che 2004-02-09 11:00:52 EST
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.
Comment 7 Vadim Nasardinov 2004-02-12 16:27:25 EST
The java hot spot fixed on the trunk in change 40336.  (The DB-bound
bottleneck remains.)
Comment 8 Bryan Che 2004-02-16 11:22:55 EST
Confirmed that this page is no longer a bottleneck in the publishing
process.

Note You need to log in before you can comment on or make changes to this bug.