Bug 113696 - c.r.persistence.metadata.Model.getQualifiedName is a performance hotspot
c.r.persistence.metadata.Model.getQualifiedName is a performance hotspot
Status: CLOSED CURRENTRELEASE
Product: Red Hat Web Application Framework
Classification: Retired
Component: persistence (Show other bugs)
nightly
All Linux
medium Severity medium
: ---
: ---
Assigned To: Vadim Nasardinov
:
Depends On:
Blocks: 113496 115042
  Show dependency treegraph
 
Reported: 2004-01-16 11:39 EST by Daniel Berrange
Modified: 2007-04-18 13:01 EDT (History)
2 users (show)

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


Attachments (Terms of Use)
proof-of-concept patch that greatly reduces calls to getQualifiedName (5.99 KB, patch)
2004-02-10 19:21 EST, Vadim Nasardinov
no flags Details | Diff
implementation of what Rafi suggested in comment 17 (2.63 KB, patch)
2004-02-11 17:08 EST, Vadim Nasardinov
no flags Details | Diff

  None (edit)
Description Daniel Berrange 2004-01-16 11:39:14 EST
Description of problem:
The c.r.persistence.metadata.Model.getQualifiedName method is a
performance hotspot when iterating over a cursor, fetching the
returned data.

See bug 113680 #1 for more details

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:
Comment 1 Richard Li 2004-01-20 15:26:59 EST
do you have the actual profile data handy?
Comment 2 Daniel Berrange 2004-01-20 15:30:39 EST
Unfortunately not because the tool i was using didn't let me save its
output. If you profile the Category.removeChild method with optimizeit
or equiv on a database with 15,000 rows in acs_objects you'll quickly
reproduce it.
Comment 3 Jon Orris 2004-02-09 11:36:40 EST
The simplest solution is likely to replace the constant concatenation
of m_parent.getQualfiedName() + "." + m_name with a constant member
m_qualifedName, created on construction.

My only concern is that while the current method is inefficient, the
isolated performance overhead in a simple test is barely measurable,
on the order of 150ms 15000 calls.

I could believe that the number of calls may be much higher for the
Category.removeChild example, or that it's JVM dependent. Dan, which
JVM did you take these measurements with? And do you memember how many
calls to getQualifiedName it shows?
Comment 4 Vadim Nasardinov 2004-02-09 11:40:36 EST
I instrumented getQualifiedName() (and RDBMSEngine) to collect data
for bug 115042.  When publishing an Article with the simple workflow,
one of the requests clocks 608 queries and a quarter of a million
calls to Model.getQualifiedName().  (The exact number is 238230.)
Comment 5 Rafael H. Schloming 2004-02-09 11:50:52 EST
Is there any way of figuring out who's calling it that much?
Comment 6 Vadim Nasardinov 2004-02-09 11:56:15 EST
I'll work on it.
Comment 7 Jon Orris 2004-02-09 12:20:40 EST
Using my poor man's analyzer, I get the following when publishing:
2004-02-09 12:16:04,154 [004-1] INFO  metadata.Model -
-------------Outputting qualified name callers-------
2004-02-09 12:16:04,155 [004-1] INFO  metadata.Model -
com.arsdigita.persistence.metadata.Model.getName(Model.java:67) called
25 times.
2004-02-09 12:16:04,155 [004-1] INFO  metadata.Model -
com.redhat.persistence.metadata.ObjectType.getQualifiedName(ObjectType.java:70)
called 67952 times.
2004-02-09 12:16:04,155 [004-1] INFO  metadata.Model -
com.redhat.persistence.metadata.Model.getQualifiedName(Model.java:115)
called 155664 times.
2004-02-09 12:16:04,155 [004-1] INFO  metadata.Model -
-------------DONE Outputting qualified name callers-------

It looks like ObjectType.getQualifiedName causes the bulk of entries,
with 67,952. getQualifiedName calls itself 155,664 times.

So yes, that constant calling up the parent hierarchy is nasty :)
It also suggests that ObjectType.getQualifiedName should a final
variable instead of computed.

I have similar suspicions about OID.toString() and OID.hashCode(), but
no measurements yet.
Comment 8 Jon Orris 2004-02-09 12:50:01 EST
Caching the results of getQualifiedName for model & object type
drastically cuts down on these calls. Almost all of them occur during
system initialization now:

2004-02-09 12:45:58,258 [ main] INFO  metadata.Model -
com.arsdigita.persistence.metadata.Model.getName(Model.java:67) called
117 times.
2004-02-09 12:45:58,258 [ main] INFO  metadata.Model -
com.redhat.persistence.pdl.PDL.linkName(PDL.java:129) called 53 times.
2004-02-09 12:45:58,258 [ main] INFO  metadata.Model -
com.redhat.persistence.metadata.Model.<init>(Model.java:84) called 37
times.
2004-02-09 12:45:58,258 [ main] INFO  metadata.Model -
com.redhat.persistence.metadata.ObjectType.<init>(ObjectType.java:48)
called 373 times.


After running the system for a bit and publishing, the calls
model.getName drift up a tiny amount.
2004-02-09 12:48:00,616 [ead-5] INFO  metadata.Model -
com.arsdigita.persistence.metadata.Model.getName(Model.java:67) called
152 times.
2004-02-09 12:48:00,616 [ead-5] INFO  metadata.Model -
com.redhat.persistence.pdl.PDL.linkName(PDL.java:129) called 53 times.
2004-02-09 12:48:00,616 [ead-5] INFO  metadata.Model -
com.redhat.persistence.metadata.Model.<init>(Model.java:84) called 37
times.
2004-02-09 12:48:00,616 [ead-5] INFO  metadata.Model -
com.redhat.persistence.metadata.ObjectType.<init>(ObjectType.java:48)
called 373 times.

Comment 9 Daniel Berrange 2004-02-09 13:09:35 EST
When removing a Category<->Object mapping with 8000 rows in
acs_objects, the cartesian join problem (bug  113680) results in
1,600,000 invocation s of getQualifiedName. Out of 13 seconds total
execution time, for removeChild(Category), getQualifiedName was listed
as taking 17.6%, or 2.5 seconds.

17.6% - 1624695 inv. -
com.redhat.persistence.metadata.Model.getQualifiedName()Ljava/lang/String;
- 2407 net ms
  11.6% - 519831 inv. -
com.redhat.persistence.metadata.ObjectType.getQualifiedName()Ljava/lang/String;
- 1580 net ms
  7.4% - 1702851 inv. -
com.redhat.persistence.metadata.Mist.get(Ljava/lang/Object;)Ljava/lang/Object;
- 1016 net ms
  7.0% - 1 inv. -
com.redhat.persistence.engine.rdbms.RDBMSEngine.execute(Lcom/redhat/persistence/engine/rdbms/Operation;Lcom/redhat/persistence/engine/rdbms/SQLWriter;)Lcom/redhat/persistence/engine/rdbms/ResultCycle;
- 956 net ms
  3.8% - 8379 inv. -
com.redhat.persistence.RecordSet.load(Lcom/redhat/persistence/Session;)Ljava/util/Map;
- 514 net ms
  2.0% - 134148 inv. -
com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Ljava/lang/Object;)Lcom/redhat/persistence/PropertyMap;
- 266 net ms
  1.8% - 663208 inv. -
com.redhat.persistence.metadata.Mist.containsKey(Ljava/lang/Object;)Z
- 240 net ms
  1.7% - 108954 inv. -
com.redhat.persistence.Session.getObjectData(Ljava/lang/Object;)Lcom/redhat/persistence/ObjectData;
- 228 net ms
  1.5% - 1820251 inv. -
com.redhat.persistence.metadata.ObjectType.getBasetype()Lcom/redhat/persistence/metadata/ObjectType;
- 202 net ms
  1.5% - 33516 inv. -
com.redhat.persistence.pdl.adapters.BigDecimalAd.fetch(Ljava/sql/ResultSet;Ljava/lang/String;)Ljava/lang/Object;
- 202 net ms
  1.5% - 167662 inv. -
com.redhat.persistence.metadata.Adapter.getSessionKey(Lcom/redhat/persistence/metadata/ObjectType;Lcom/redhat/persistence/PropertyMap;)Ljava/lang/Object;
- 202 net ms
Comment 10 Vadim Nasardinov 2004-02-09 15:04:46 EST
In response to comment #5 (rafi's question):

This shows the number of times Model.getQualifiedName(Model.java:87)
was called, as well as the number of times its callers were called.
(I only looked 10 levels into the stack trace.)

This is data is for the "Authoring tab"
page. (/ccm/content/admin/item.jsp?item_id=5003).


111563: com.redhat.persistence.metadata.Model.getQualifiedName(Model.java:87)
 37063: com.redhat.persistence.metadata.ObjectType.getQualifiedName(ObjectType.java:70)
  36866: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:71)
   34168: com.arsdigita.persistence.C.type(C.java:44)
    17: com.arsdigita.persistence.C.pmap(C.java:59)
     17: com.arsdigita.persistence.Session.retrieve(Session.java:344)
      3: com.arsdigita.domain.DomainObjectFactory.newInstance(DomainObjectFactory.java:181)
       1: com.arsdigita.kernel.User.retrieve(User.java:104)
       1: com.arsdigita.cms.dispatcher.CMSPage$1.excurse(CMSPage.java:272)
       1: com.arsdigita.kernel.ui.ACSObjectSelectionModel.loadACSObject(ACSObjectSelectionModel.java:331)
      1: com.arsdigita.web.Application.retrieveApplication(Application.java:219)
       1: com.arsdigita.web.Application.retrieveApplication(Application.java:215)
      13: com.arsdigita.domain.DomainObject.<init>(DomainObject.java:128)
       10: com.arsdigita.auditing.BasicAuditTrail.<init>(BasicAuditTrail.java:92)
       3: com.arsdigita.domain.ObservableDomainObject.<init>(ObservableDomainObject.java:100)
    34151: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:757)
     1915: com.redhat.persistence.Session.getObjectType(Session.java:424)
      11: com.redhat.persistence.Session.retrieve(Session.java:106)
       11: com.arsdigita.persistence.Session.retrieve(Session.java:344)
      1895: com.redhat.persistence.Session.get(Session.java:142)
       1865: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:516)
       28: com.arsdigita.persistence.DataAssociationCursorImpl.<init>(DataAssociationCursorImpl.java:38)
       2: com.redhat.persistence.Session.get(Session.java:240)
      7: com.redhat.persistence.DynamicQuerySource.getQuery(DynamicQuerySource.java:108)
       7: com.redhat.persistence.engine.rdbms.RDBMSQuerySource.getQuery(RDBMSQuerySource.java:213)
      2: com.redhat.persistence.Session.get(Session.java:233)
       2: com.redhat.persistence.Cursor.getInternal(Cursor.java:61)
     10444: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
      10444: com.redhat.persistence.Session.getSessionKey(Session.java:777)
       2253: com.redhat.persistence.Session.hasObjectData(Session.java:817)
       6233: com.redhat.persistence.Session.getObjectData(Session.java:825)
       1867: com.redhat.persistence.EventStream.getKey(EventStream.java:84)
       91: com.redhat.persistence.Session.addObjectData(Session.java:833)
     10498: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:742)
      10444: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
       10444: com.redhat.persistence.Session.getSessionKey(Session.java:777)
      5: com.redhat.persistence.Session.releaseObject(Session.java:792)
       5: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
      49: com.redhat.persistence.Session.getProperties(Session.java:437)
       49: com.redhat.persistence.engine.rdbms.RDBMSEngine.get(RDBMSEngine.java:614)
     10652: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:746)
      10598: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
       10598: com.redhat.persistence.Session.getSessionKey(Session.java:777)
      5: com.redhat.persistence.Session.releaseObject(Session.java:792)
       5: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
      49: com.redhat.persistence.Session.getProperties(Session.java:437)
       49: com.redhat.persistence.engine.rdbms.RDBMSEngine.get(RDBMSEngine.java:614)
     5: com.redhat.persistence.Session.releaseObject(Session.java:791)
      5: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
       1: com.arsdigita.domain.DomainObject.disconnect(DomainObject.java:548)
       1: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:496)
       3: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:215)
     110: com.redhat.persistence.Session.use(Session.java:799)
      5: com.redhat.persistence.Session.releaseObject(Session.java:793)
       5: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
      105: com.redhat.persistence.RecordSet.load(RecordSet.java:126)
       96: com.redhat.persistence.Cursor.next(Cursor.java:112)
       9: com.redhat.persistence.Session.fetchPropertyData(Session.java:885)
     25: com.redhat.persistence.Session.getObjectMap(Session.java:432)
      25: com.redhat.persistence.engine.rdbms.RDBMSQuerySource.getQuery(RDBMSQuerySource.java:211)
       22: com.redhat.persistence.Session.fetchPropertyData(Session.java:882)
       3: com.redhat.persistence.Session.fetchPropertyData(Session.java:876)
     502: com.redhat.persistence.RecordSet.load(RecordSet.java:109)
      11: com.redhat.persistence.Session.fetchPropertyData(Session.java:885)
       11: com.redhat.persistence.Session$1.onRole(Session.java:147)
      491: com.redhat.persistence.Cursor.next(Cursor.java:112)
       491: com.arsdigita.persistence.DataQueryImpl.next(DataQueryImpl.java:465)
   1908: com.arsdigita.persistence.C.prop(C.java:54)
    1833: com.arsdigita.persistence.DataObjectImpl.convert(DataObjectImpl.java:161)
     1829: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:224)
      7: com.arsdigita.kernel.ACSObjectInstantiator.resolveInstantiator(ACSObjectInstantiator.java:124)
       7: com.arsdigita.domain.DomainObjectFactory.newInstance(DomainObjectFactory.java:134)
      1817: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
       339: com.arsdigita.kernel.ACSObject.getSpecificObjectType(ACSObject.java:373)
       12: com.arsdigita.cms.ContentSection.get(ContentSection.java:203)
       41: com.arsdigita.cms.ContentItem.get(ContentItem.java:379)
       1: com.arsdigita.kernel.SiteNode.getURLNoContext(SiteNode.java:196)
       24: com.arsdigita.cms.ContentType.getAuthoringKit(ContentType.java:238)
       24: com.arsdigita.cms.ContentType.getClassName(ContentType.java:187)
       51: com.arsdigita.cms.ContentType.getAssociatedObjectType(ContentType.java:132)
       42: com.arsdigita.cms.AuthoringStep.getLabel(AuthoringStep.java:102)
       84: com.arsdigita.cms.AuthoringStep.getLabelKey(AuthoringStep.java:117)
       42: com.arsdigita.cms.AuthoringStep.getLabelBundle(AuthoringStep.java:125)
       126: com.arsdigita.cms.AuthoringStep.getDescription(AuthoringStep.java:133)
       126: com.arsdigita.cms.AuthoringStep.getDescriptionKey(AuthoringStep.java:145)
       42: com.arsdigita.cms.AuthoringStep.getComponent(AuthoringStep.java:161)
       276: com.arsdigita.mimetypes.MimeType.getJavaClass(MimeType.java:137)
       138: com.arsdigita.mimetypes.MimeType.getSpecificObjectType(MimeType.java:151)
       138: com.arsdigita.mimetypes.MimeType.getLabel(MimeType.java:108)
       102: com.arsdigita.formbuilder.MetaObject.getPrettyName(MetaObject.java:291)
       102: com.arsdigita.formbuilder.MetaObject.getPropertiesFormName(MetaObject.java:387)
       102: com.arsdigita.formbuilder.MetaObject.getWidgetClassName(MetaObject.java:342)
       2: com.arsdigita.workflow.simple.Workflow.initialize(Workflow.java:162)
       1: com.arsdigita.workflow.simple.Task.getStateString(Task.java:256)
       1: com.arsdigita.web.ApplicationType.getPackageType(ApplicationType.java:261)
       1: com.arsdigita.kernel.PackageType.getKey(PackageType.java:168)
      5: com.arsdigita.kernel.ACSObjectInstantiator.resolveInstantiator(ACSObjectInstantiator.java:136)
       5: com.arsdigita.domain.DomainObjectFactory.newInstance(DomainObjectFactory.java:134)
     4: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:210)
      4: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
       1: com.arsdigita.kernel.SiteNode.getPackageInstance(SiteNode.java:262)
       1: com.arsdigita.kernel.PackageInstance.getLocale(PackageInstance.java:273)
       1: com.arsdigita.kernel.PackageInstance.getType(PackageInstance.java:127)
       1: com.arsdigita.kernel.User.getPersonName(User.java:289)
    32: com.arsdigita.persistence.DataObjectImpl.doDisconnect(DataObjectImpl.java:258)
     26: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:199)
      26: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
       11: com.arsdigita.kernel.ACSObject.getSpecificObjectType(ACSObject.java:373)
       6: com.arsdigita.kernel.PackageType.getDispatcherClass(PackageType.java:264)
       6: com.arsdigita.kernel.User.getPersonName(User.java:289)
       3: com.arsdigita.kernel.PersonName.getGivenName(PersonName.java:84)
     6: com.arsdigita.persistence.DataObjectImpl.invalidate(DataObjectImpl.java:323)
      6: com.arsdigita.persistence.Session.invalidateDataObjects(Session.java:551)
       6: com.arsdigita.persistence.TransactionContext.commitTxn(TransactionContext.java:89)
    28: com.arsdigita.persistence.DataAssociationCursorImpl.<init>(DataAssociationCursorImpl.java:38)
     15: com.arsdigita.persistence.DataAssociationImpl.<init>(DataAssociationImpl.java:39)
      15: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:191)
       15: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
     13: com.arsdigita.persistence.DataAssociationImpl.getDataAssociationCursor(DataAssociationImpl.java:62)
      13: com.arsdigita.persistence.DataAssociationImpl.cursor(DataAssociationImpl.java:69)
       1: com.arsdigita.cms.ContentItem.getLiveVersion(ContentItem.java:996)
       12: com.arsdigita.cms.AuthoringKit.getSteps(AuthoringKit.java:282)
    15: com.arsdigita.persistence.DataAssociationImpl.<init>(DataAssociationImpl.java:44)
     15: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:191)
      15: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
       1: com.arsdigita.cms.ContentItem.get(ContentItem.java:379)
       1: com.arsdigita.kernel.PackageType.getInstances(PackageType.java:571)
       1: com.arsdigita.kernel.PackageInstance.getMountPoints(PackageInstance.java:260)
       12: com.arsdigita.cms.AuthoringKit.getSteps(AuthoringKit.java:281)
   711: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:52)
    348: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
     348: com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
      348: com.arsdigita.domain.ObservableDomainObject.initializeGlobalObservers(ObservableDomainObject.java:113)
       346: com.arsdigita.domain.ObservableDomainObject.<init>(ObservableDomainObject.java:49)
       2: com.arsdigita.domain.ObservableDomainObject.<init>(ObservableDomainObject.java:101)
    363: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
     348: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
      348: com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
       348: com.arsdigita.domain.ObservableDomainObject.initializeGlobalObservers(ObservableDomainObject.java:113)
     15: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
      9: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
       9: com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
      6: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
       6: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
   79: com.arsdigita.persistence.Session.retrieve(Session.java:377)
    79: com.arsdigita.persistence.Session.retrieve(Session.java:430)
     1: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:488)
      1: com.arsdigita.web.PathMapCache.get(PathMapCache.java:89)
       1: com.arsdigita.kernel.SiteNode$Cache.getNode(SiteNode.java:518)
     1: com.arsdigita.web.Host.retrieveAll(Host.java:112)
      1: com.arsdigita.caching.CacheServlet.notifyPeers(CacheServlet.java:171)
       1: com.arsdigita.caching.CacheServlet.removeOutdatedFromPeers(CacheServlet.java:147)
     1: com.arsdigita.kernel.PackageType.getTypeByKey(PackageType.java:605)
      1: com.arsdigita.kernel.PackageType.findByKey(PackageType.java:590)
       1: com.arsdigita.cms.dispatcher.Utilities.getSingletonPackageURL(Utilities.java:170)
     3: com.arsdigita.cms.ContentType.getAllContentTypes(ContentType.java:371)
      3: com.arsdigita.cms.ContentType.getAllContentTypes(ContentType.java:354)
       3: com.arsdigita.cms.ui.authoring.AuthoringKitSelector.<init>(AuthoringKitSelector.java:67)
     24: com.arsdigita.mimetypes.MimeType.searchMimeTypes(MimeType.java:372)
      24: com.arsdigita.cms.ui.FileUploadSection.addMimeOptions(FileUploadSection.java:434)
       21: com.arsdigita.cms.ui.FileUploadSection.<init>(FileUploadSection.java:190)
       3: com.arsdigita.cms.ui.authoring.TextAssetBody.setMimeTypeOptions(TextAssetBody.java:152)
     24: com.arsdigita.formbuilder.BebopObjectType.findByClassName(BebopObjectType.java:146)
      24: com.arsdigita.formbuilder.BebopObjectType.findByClass(BebopObjectType.java:130)
       24: com.arsdigita.formbuilder.MetaObject.getWidgets(MetaObject.java:236)
     24: com.arsdigita.formbuilder.MetaObject.getWidgets(MetaObject.java:249)
      24: com.arsdigita.formbuilder.MetaObject.getWidgets(MetaObject.java:236)
       6: com.arsdigita.formbuilder.ui.NewControl.loadComponents(NewControl.java:81)
       12: com.arsdigita.formbuilder.ui.MetaObjectProperties.addForms(MetaObjectProperties.java:54)
       6: com.arsdigita.formbuilder.ui.NewAction.loadComponents(NewAction.java:75)
     1: com.arsdigita.cms.ContentItem.getPathInfo(ContentItem.java:749)
      1: com.arsdigita.cms.ContentItem.getPathNoJsp(ContentItem.java:696)
       1: com.arsdigita.cms.ContentItem.getPath(ContentItem.java:685)
  87: com.arsdigita.persistence.Session$DataObjectAdapter.getObject(Session.java:716)
   3: com.redhat.persistence.Session.releaseObject(Session.java:792)
    3: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
     1: com.arsdigita.domain.DomainObject.disconnect(DomainObject.java:548)
      1: com.arsdigita.kernel.security.UserContext.getUser(UserContext.java:311)
       1: com.arsdigita.web.BaseServlet$1.excurse(BaseServlet.java:164)
     1: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:496)
      1: com.arsdigita.web.PathMapCache.get(PathMapCache.java:89)
       1: com.arsdigita.kernel.SiteNode$Cache.getNode(SiteNode.java:518)
     1: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:215)
      1: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
       1: com.arsdigita.kernel.SiteNode.getPackageInstance(SiteNode.java:262)
   84: com.redhat.persistence.RecordSet.load(RecordSet.java:124)
    77: com.redhat.persistence.Cursor.next(Cursor.java:112)
     75: com.arsdigita.persistence.DataQueryImpl.next(DataQueryImpl.java:465)
      2: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:494)
       2: com.arsdigita.web.PathMapCache.get(PathMapCache.java:89)
      69: com.arsdigita.domain.DomainQuery.next(DomainQuery.java:94)
       1: com.arsdigita.cms.dispatcher.Utilities.getSingletonPackageURL(Utilities.java:174)
       1: com.arsdigita.cms.dispatcher.Utilities.getSingletonPackageURL(Utilities.java:185)
       2: com.arsdigita.cms.ui.authoring.AuthoringKitSelector.processKit(AuthoringKitSelector.java:91)
       28: com.arsdigita.cms.ui.authoring.AuthoringKitWizard.<init>(AuthoringKitWizard.java:223)
       20: com.arsdigita.cms.ui.FileUploadSection.addMimeOptions(FileUploadSection.java:436)
       12: com.arsdigita.formbuilder.ui.NewControl.loadComponents(NewControl.java:85)
       5: com.arsdigita.formbuilder.ui.NewAction.loadComponents(NewAction.java:79)
      2: com.arsdigita.persistence.DataQueryDecorator.next(DataQueryDecorator.java:75)
       2: com.arsdigita.domain.DomainQuery.next(DomainQuery.java:94)
      2: com.arsdigita.formbuilder.BebopObjectType.findByClassName(BebopObjectType.java:150)
       2: com.arsdigita.formbuilder.BebopObjectType.findByClass(BebopObjectType.java:130)
     2: com.redhat.persistence.Session.retrieve(Session.java:118)
      2: com.arsdigita.persistence.Session.retrieve(Session.java:344)
       1: com.arsdigita.domain.DomainObjectFactory.newInstance(DomainObjectFactory.java:181)
       1: com.arsdigita.domain.DomainObject.<init>(DomainObject.java:128)
    7: com.redhat.persistence.Session.fetchPropertyData(Session.java:885)
     7: com.redhat.persistence.Session$1.onRole(Session.java:147)
      7: com.redhat.persistence.metadata.Role.dispatch(Role.java:92)
       7: com.redhat.persistence.Session.get(Session.java:145)
  110: com.arsdigita.persistence.Session$DataObjectAdapter.getObject(Session.java:727)
   5: com.redhat.persistence.Session.releaseObject(Session.java:792)
    5: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
     1: com.arsdigita.domain.DomainObject.disconnect(DomainObject.java:548)
      1: com.arsdigita.kernel.security.UserContext.getUser(UserContext.java:311)
       1: com.arsdigita.web.BaseServlet$1.excurse(BaseServlet.java:164)
     1: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:496)
      1: com.arsdigita.web.PathMapCache.get(PathMapCache.java:89)
       1: com.arsdigita.kernel.SiteNode$Cache.getNode(SiteNode.java:518)
     3: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:215)
      3: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
       1: com.arsdigita.kernel.SiteNode.getPackageInstance(SiteNode.java:262)
       1: com.arsdigita.kernel.PackageInstance.getType(PackageInstance.java:127)
       1: com.arsdigita.kernel.User.getPersonName(User.java:289)
   105: com.redhat.persistence.RecordSet.load(RecordSet.java:124)
    96: com.redhat.persistence.Cursor.next(Cursor.java:112)
     90: com.arsdigita.persistence.DataQueryImpl.next(DataQueryImpl.java:465)
      2: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:494)
       2: com.arsdigita.web.PathMapCache.get(PathMapCache.java:89)
      1: com.arsdigita.kernel.PackageType.getTypeByKey(PackageType.java:610)
       1: com.arsdigita.kernel.PackageType.findByKey(PackageType.java:590)
      83: com.arsdigita.domain.DomainQuery.next(DomainQuery.java:94)
       1: com.arsdigita.cms.dispatcher.Utilities.getSingletonPackageURL(Utilities.java:174)
       1: com.arsdigita.cms.dispatcher.Utilities.getSingletonPackageURL(Utilities.java:185)
       2: com.arsdigita.cms.ui.authoring.AuthoringKitSelector.processKit(AuthoringKitSelector.java:91)
       42: com.arsdigita.cms.ui.authoring.AuthoringKitWizard.<init>(AuthoringKitWizard.java:223)
       20: com.arsdigita.cms.ui.FileUploadSection.addMimeOptions(FileUploadSection.java:436)
       12: com.arsdigita.formbuilder.ui.NewControl.loadComponents(NewControl.java:85)
       5: com.arsdigita.formbuilder.ui.NewAction.loadComponents(NewAction.java:79)
      2: com.arsdigita.persistence.DataQueryDecorator.next(DataQueryDecorator.java:75)
       2: com.arsdigita.domain.DomainQuery.next(DomainQuery.java:94)
      2: com.arsdigita.formbuilder.BebopObjectType.findByClassName(BebopObjectType.java:150)
       2: com.arsdigita.formbuilder.BebopObjectType.findByClass(BebopObjectType.java:130)
     6: com.redhat.persistence.Session.retrieve(Session.java:118)
      6: com.arsdigita.persistence.Session.retrieve(Session.java:344)
       5: com.arsdigita.domain.DomainObject.<init>(DomainObject.java:128)
       1: com.arsdigita.domain.DomainObjectFactory.newInstance(DomainObjectFactory.java:181)
    9: com.redhat.persistence.Session.fetchPropertyData(Session.java:885)
     9: com.redhat.persistence.Session$1.onRole(Session.java:147)
      9: com.redhat.persistence.metadata.Role.dispatch(Role.java:92)
       9: com.redhat.persistence.Session.get(Session.java:145)
 74500: com.redhat.persistence.metadata.Model.getQualifiedName(Model.java:92)
  36976: com.redhat.persistence.metadata.ObjectType.getQualifiedName(ObjectType.java:70)
   36866: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:71)
    34168: com.arsdigita.persistence.C.type(C.java:44)
     17: com.arsdigita.persistence.C.pmap(C.java:59)
      17: com.arsdigita.persistence.Session.retrieve(Session.java:344)
       3: com.arsdigita.domain.DomainObjectFactory.newInstance(DomainObjectFactory.java:181)
       1: com.arsdigita.web.Application.retrieveApplication(Application.java:219)
       13: com.arsdigita.domain.DomainObject.<init>(DomainObject.java:128)
     34151: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:757)
      1915: com.redhat.persistence.Session.getObjectType(Session.java:424)
       11: com.redhat.persistence.Session.retrieve(Session.java:106)
       1895: com.redhat.persistence.Session.get(Session.java:142)
       7: com.redhat.persistence.DynamicQuerySource.getQuery(DynamicQuerySource.java:108)
       2: com.redhat.persistence.Session.get(Session.java:233)
      10444: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
       10444: com.redhat.persistence.Session.getSessionKey(Session.java:777)
      10498: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:742)
       10444: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
       5: com.redhat.persistence.Session.releaseObject(Session.java:792)
       49: com.redhat.persistence.Session.getProperties(Session.java:437)
      10652: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:746)
       10598: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
       5: com.redhat.persistence.Session.releaseObject(Session.java:792)
       49: com.redhat.persistence.Session.getProperties(Session.java:437)
      5: com.redhat.persistence.Session.releaseObject(Session.java:791)
       5: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
      110: com.redhat.persistence.Session.use(Session.java:799)
       5: com.redhat.persistence.Session.releaseObject(Session.java:793)
       105: com.redhat.persistence.RecordSet.load(RecordSet.java:126)
      25: com.redhat.persistence.Session.getObjectMap(Session.java:432)
       25: com.redhat.persistence.engine.rdbms.RDBMSQuerySource.getQuery(RDBMSQuerySource.java:211)
      502: com.redhat.persistence.RecordSet.load(RecordSet.java:109)
       11: com.redhat.persistence.Session.fetchPropertyData(Session.java:885)
       491: com.redhat.persistence.Cursor.next(Cursor.java:112)
    1908: com.arsdigita.persistence.C.prop(C.java:54)
     1833: com.arsdigita.persistence.DataObjectImpl.convert(DataObjectImpl.java:161)
      1829: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:224)
       7: com.arsdigita.kernel.ACSObjectInstantiator.resolveInstantiator(ACSObjectInstantiator.java:124)
       1817: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
       5: com.arsdigita.kernel.ACSObjectInstantiator.resolveInstantiator(ACSObjectInstantiator.java:136)
      4: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:210)
       4: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
     32: com.arsdigita.persistence.DataObjectImpl.doDisconnect(DataObjectImpl.java:258)
      26: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:199)
       26: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
      6: com.arsdigita.persistence.DataObjectImpl.invalidate(DataObjectImpl.java:323)
       6: com.arsdigita.persistence.Session.invalidateDataObjects(Session.java:551)
     28: com.arsdigita.persistence.DataAssociationCursorImpl.<init>(DataAssociationCursorImpl.java:38)
      15: com.arsdigita.persistence.DataAssociationImpl.<init>(DataAssociationImpl.java:39)
       15: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:191)
      13: com.arsdigita.persistence.DataAssociationImpl.getDataAssociationCursor(DataAssociationImpl.java:62)
       13: com.arsdigita.persistence.DataAssociationImpl.cursor(DataAssociationImpl.java:69)
     15: com.arsdigita.persistence.DataAssociationImpl.<init>(DataAssociationImpl.java:44)
      15: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:191)
       15: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
    711: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:52)
     348: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
      348: com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
       348: com.arsdigita.domain.ObservableDomainObject.initializeGlobalObservers(ObservableDomainObject.java:113)
     363: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
      348: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
       348: com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
      15: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
       9: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
       6: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
    79: com.arsdigita.persistence.Session.retrieve(Session.java:377)
     79: com.arsdigita.persistence.Session.retrieve(Session.java:430)
      1: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:488)
       1: com.arsdigita.web.PathMapCache.get(PathMapCache.java:89)
      1: com.arsdigita.web.Host.retrieveAll(Host.java:112)
       1: com.arsdigita.caching.CacheServlet.notifyPeers(CacheServlet.java:171)
      1: com.arsdigita.kernel.PackageType.getTypeByKey(PackageType.java:605)
       1: com.arsdigita.kernel.PackageType.findByKey(PackageType.java:590)
      3: com.arsdigita.cms.ContentType.getAllContentTypes(ContentType.java:371)
       3: com.arsdigita.cms.ContentType.getAllContentTypes(ContentType.java:354)
      24: com.arsdigita.mimetypes.MimeType.searchMimeTypes(MimeType.java:372)
       24: com.arsdigita.cms.ui.FileUploadSection.addMimeOptions(FileUploadSection.java:434)
      24: com.arsdigita.formbuilder.BebopObjectType.findByClassName(BebopObjectType.java:146)
       24: com.arsdigita.formbuilder.BebopObjectType.findByClass(BebopObjectType.java:130)
      24: com.arsdigita.formbuilder.MetaObject.getWidgets(MetaObject.java:249)
       24: com.arsdigita.formbuilder.MetaObject.getWidgets(MetaObject.java:236)
      1: com.arsdigita.cms.ContentItem.getPathInfo(ContentItem.java:749)
       1: com.arsdigita.cms.ContentItem.getPathNoJsp(ContentItem.java:696)
   110: com.arsdigita.persistence.Session$DataObjectAdapter.getObject(Session.java:727)
    5: com.redhat.persistence.Session.releaseObject(Session.java:792)
     5: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
      1: com.arsdigita.domain.DomainObject.disconnect(DomainObject.java:548)
       1: com.arsdigita.kernel.security.UserContext.getUser(UserContext.java:311)
      1: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:496)
       1: com.arsdigita.web.PathMapCache.get(PathMapCache.java:89)
      3: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:215)
       3: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
    105: com.redhat.persistence.RecordSet.load(RecordSet.java:124)
     96: com.redhat.persistence.Cursor.next(Cursor.java:112)
      90: com.arsdigita.persistence.DataQueryImpl.next(DataQueryImpl.java:465)
       2: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:494)
       1: com.arsdigita.kernel.PackageType.getTypeByKey(PackageType.java:610)
       83: com.arsdigita.domain.DomainQuery.next(DomainQuery.java:94)
       2: com.arsdigita.persistence.DataQueryDecorator.next(DataQueryDecorator.java:75)
       2: com.arsdigita.formbuilder.BebopObjectType.findByClassName(BebopObjectType.java:150)
      6: com.redhat.persistence.Session.retrieve(Session.java:118)
       6: com.arsdigita.persistence.Session.retrieve(Session.java:344)
     9: com.redhat.persistence.Session.fetchPropertyData(Session.java:885)
      9: com.redhat.persistence.Session$1.onRole(Session.java:147)
       9: com.redhat.persistence.metadata.Role.dispatch(Role.java:92)
  37524: com.redhat.persistence.metadata.Model.getQualifiedName(Model.java:92)
   36976: com.redhat.persistence.metadata.ObjectType.getQualifiedName(ObjectType.java:70)
    36866: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:71)
     34168: com.arsdigita.persistence.C.type(C.java:44)
      17: com.arsdigita.persistence.C.pmap(C.java:59)
       17: com.arsdigita.persistence.Session.retrieve(Session.java:344)
      34151: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:757)
       1915: com.redhat.persistence.Session.getObjectType(Session.java:424)
       10444: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
       10498: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:742)
       10652: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:746)
       5: com.redhat.persistence.Session.releaseObject(Session.java:791)
       110: com.redhat.persistence.Session.use(Session.java:799)
       25: com.redhat.persistence.Session.getObjectMap(Session.java:432)
       502: com.redhat.persistence.RecordSet.load(RecordSet.java:109)
     1908: com.arsdigita.persistence.C.prop(C.java:54)
      1833: com.arsdigita.persistence.DataObjectImpl.convert(DataObjectImpl.java:161)
       1829: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:224)
       4: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:210)
      32: com.arsdigita.persistence.DataObjectImpl.doDisconnect(DataObjectImpl.java:258)
       26: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:199)
       6: com.arsdigita.persistence.DataObjectImpl.invalidate(DataObjectImpl.java:323)
      28: com.arsdigita.persistence.DataAssociationCursorImpl.<init>(DataAssociationCursorImpl.java:38)
       15: com.arsdigita.persistence.DataAssociationImpl.<init>(DataAssociationImpl.java:39)
       13: com.arsdigita.persistence.DataAssociationImpl.getDataAssociationCursor(DataAssociationImpl.java:62)
      15: com.arsdigita.persistence.DataAssociationImpl.<init>(DataAssociationImpl.java:44)
       15: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:191)
     711: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:52)
      348: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
       348: com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
      363: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
       348: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
       15: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
     79: com.arsdigita.persistence.Session.retrieve(Session.java:377)
      79: com.arsdigita.persistence.Session.retrieve(Session.java:430)
       1: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:488)
       1: com.arsdigita.web.Host.retrieveAll(Host.java:112)
       1: com.arsdigita.kernel.PackageType.getTypeByKey(PackageType.java:605)
       3: com.arsdigita.cms.ContentType.getAllContentTypes(ContentType.java:371)
       24: com.arsdigita.mimetypes.MimeType.searchMimeTypes(MimeType.java:372)
       24: com.arsdigita.formbuilder.BebopObjectType.findByClassName(BebopObjectType.java:146)
       24: com.arsdigita.formbuilder.MetaObject.getWidgets(MetaObject.java:249)
       1: com.arsdigita.cms.ContentItem.getPathInfo(ContentItem.java:749)
    110: com.arsdigita.persistence.Session$DataObjectAdapter.getObject(Session.java:727)
     5: com.redhat.persistence.Session.releaseObject(Session.java:792)
      5: com.arsdigita.persistence.DataObjectImpl.disconnect(DataObjectImpl.java:336)
       1: com.arsdigita.domain.DomainObject.disconnect(DomainObject.java:548)
       1: com.arsdigita.kernel.SiteNode$Cache.retrieve(SiteNode.java:496)
       3: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:215)
     105: com.redhat.persistence.RecordSet.load(RecordSet.java:124)
      96: com.redhat.persistence.Cursor.next(Cursor.java:112)
       90: com.arsdigita.persistence.DataQueryImpl.next(DataQueryImpl.java:465)
       6: com.redhat.persistence.Session.retrieve(Session.java:118)
      9: com.redhat.persistence.Session.fetchPropertyData(Session.java:885)
       9: com.redhat.persistence.Session$1.onRole(Session.java:147)
   548: com.redhat.persistence.metadata.Model.getQualifiedName(Model.java:92)
    548: com.redhat.persistence.metadata.ObjectType.getQualifiedName(ObjectType.java:70)
     2: com.arsdigita.persistence.Session$DataObjectAdapter.getObject(Session.java:727)
      2: com.redhat.persistence.RecordSet.load(RecordSet.java:124)
       2: com.redhat.persistence.Cursor.next(Cursor.java:112)
     546: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:71)
      538: com.arsdigita.persistence.C.type(C.java:44)
       535: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:757)
       3: com.arsdigita.persistence.C.pmap(C.java:59)
      4: com.arsdigita.persistence.C.prop(C.java:54)
       4: com.arsdigita.persistence.DataObjectImpl.convert(DataObjectImpl.java:161)
      4: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:52)
       2: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
       2: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
Comment 11 Jon Orris 2004-02-09 15:24:28 EST
Checked in a fix 40204 that should help much of the performance overhead.
Comment 12 Daniel Berrange 2004-02-09 16:04:13 EST
Here are the results of removeCategory(Category child) once Jon's
patch is applied:

8.2% - 1 inv. -
com.redhat.persistence.engine.rdbms.RDBMSEngine.execute(Lcom/redhat/persistence/engine/rdbms/Operation;Lcom/redhat/persistence/engine/rdbms/SQLWriter;)Lcom/redhat/persistence/engine/rdbms/ResultCycle;
- 615 net ms
  6.2% - 8379 inv. -
com.redhat.persistence.RecordSet.load(Lcom/redhat/persistence/Session;)Ljava/util/Map;
- 463 net ms
  4.2% - 1702851 inv. -
com.redhat.persistence.metadata.Mist.get(Ljava/lang/Object;)Ljava/lang/Object;
- 315 net ms
  3.2% - 134148 inv. -
com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Ljava/lang/Object;)Lcom/redhat/persistence/PropertyMap;
- 243 net ms
  3.1% - 1642968 inv. -
com.redhat.persistence.metadata.ObjectType.getRoot()Lcom/redhat/persistence/metadata/Root;
- 237 net ms
  3.1% - 368814 inv. -
org.apache.log4j.Category.getEffectiveLevel()Lorg/apache/log4j/Level;
- 232 net ms
  2.8% - 108954 inv. -
com.redhat.persistence.Session.getObjectData(Ljava/lang/Object;)Lcom/redhat/persistence/ObjectData;
- 213 net ms
  2.7% - 663208 inv. -
com.redhat.persistence.metadata.Mist.containsKey(Ljava/lang/Object;)Z
- 205 net ms
  2.5% - 33516 inv. -
com.redhat.persistence.pdl.adapters.BigDecimalAd.fetch(Ljava/sql/ResultSet;Ljava/lang/String;)Ljava/lang/Object;
- 191 net ms
  2.4% - 176043 inv. -
com.redhat.persistence.PropertyMap.<init>(Lcom/redhat/persistence/metadata/ObjectType;)V
- 181 net ms
  2.3% - 167662 inv. -
com.redhat.persistence.metadata.Adapter.getSessionKey(Lcom/redhat/persistence/metadata/ObjectType;Lcom/redhat/persistence/PropertyMap;)Ljava/lang/Object;
- 176 net ms
  2.1% - 83855 inv. -
com.redhat.persistence.common.Path.add(Lcom/redhat/persistence/common/Path;Lcom/redhat/persistence/common/Path;)Lcom/redhat/persistence/common/Path;
- 161 net ms
  1.9% - 1820251 inv. -
com.redhat.persistence.metadata.ObjectType.getBasetype()Lcom/redhat/persistence/metadata/ObjectType;
- 146 net ms
  1.9% - 259909 inv. -
com.redhat.persistence.PropertyMap.put(Lcom/redhat/persistence/metadata/Property;Ljava/lang/Object;)V
- 139 net ms
  1.8% - 511479 inv. -
com.arsdigita.persistence.metadata.ObjectType.wrap(Lcom/redhat/persistence/metadata/ObjectType;)Lcom/arsdigita/persistence/metadata/ObjectType;
- 136 net ms
  1.8% - 159395 inv. -
com.redhat.persistence.common.Path.get(Ljava/lang/String;)Lcom/redhat/persistence/common/Path;
- 133 net ms
  1.7% - 25137 inv. -
com.redhat.persistence.pdl.adapters.StringAd.fetch(Ljava/sql/ResultSet;Ljava/lang/String;)Ljava/lang/Object;
- 126 net ms
  1.5% - 646447 inv. -
com.redhat.persistence.metadata.ObjectType.getProperty(Ljava/lang/String;)Lcom/redhat/persistence/metadata/Property;
- 112 net ms
  1.5% - 117306 inv. -
com.redhat.persistence.metadata.ObjectType.getImmediateProperties()Ljava/util/Collection;
- 110 net ms
  1.4% - 259750 inv. -
com.redhat.persistence.metadata.ObjectType.isKeyed()Z - 105 net ms
  1.3% - 310120 inv. -
com.redhat.persistence.Signature.getProperty(Lcom/redhat/persistence/common/Path;)Lcom/redhat/persistence/metadata/Property;
- 101 net ms
  1.2% - 167773 inv. -
com.redhat.persistence.common.Path.getPath()Ljava/lang/String; - 93.4
net ms
  1.1% - 368811 inv. - org.apache.log4j.Category.isDebugEnabled()Z -
85.4 net ms
  1.1% - 654810 inv. -
com.redhat.persistence.metadata.ObjectMap.getKeyProperties()Ljava/util/List;
- 84.3 net ms
  1.1% - 75411 inv. -
com.redhat.persistence.engine.rdbms.RDBMSRecordSet.get(Lcom/redhat/persistence/common/Path;)Ljava/lang/Object;
- 82.6 net ms
  1.1% - 503084 inv. -
com.arsdigita.persistence.C.type(Lcom/redhat/persistence/metadata/Root;Lcom/arsdigita/persistence/metadata/ObjectType;)Lcom/redhat/persistence/metadata/ObjectType;
- 81.7 net ms
  1.1% - 519851 inv. -
com.arsdigita.persistence.metadata.DataType.<init>(Lcom/redhat/persistence/metadata/ObjectType;)V
- 79.7 net ms
Comment 13 Vadim Nasardinov 2004-02-10 14:13:42 EST
In change 40204, Jon changed the implementation of
com.redhat.persistence.metadata.Model.getQualifiedName() and
com.redhat.persistence.metadata.ObjectType.getQualifiedName() such
that they are only computed once.

This makes these methods execute faster, but it doesn't make them get
called less frequently.

If you look at the "upside-down" call tree in comment #10, you'll
notice that the most frequent caller of ObjectType.getQualified() name
(and, by extension, of Model.getQualifiedName()) is
c.a.persistence.metadata.DataType.getQualifiedName().

I improved com.arsdigita.developersupport.CallRecord so that it trims
down the tree shown in comment #10 and makes it readable.  You can now
tell CallRecord to only output those subtrees that account for more
than N percent of the calls to the parent.  When loading
/ccm/content/admin/index.jsp with N set to 25%, I get a trace (well,
two traces, to be precise) that indicates that the majority of the
calls to getQualifiedName() originate in
com.redhat.persistence.Session.getSessionKey(Session.java:777)

The two traces (for a single page load) are as follows:

2004-02-10 14:05:20,571 [000-0] DEBUG developersupport.CallRecord - Context path: ''
Request URI: '/__ccm__/servlet/content-section/admin/index.jsp'
Query string: 'app-id=1012'
; threshold: 25
2004-02-10 14:05:20,572 [000-0] DEBUG developersupport.CallRecord - DataType.getQualifiedName:
DataType.getQualifiedName
 3714: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:72)
  3461: com.arsdigita.persistence.C.type(C.java:44)
   3442: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:757)
    1030: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
     1030: com.redhat.persistence.Session.getSessionKey(Session.java:777)
      633: com.redhat.persistence.Session.getObjectData(Session.java:825)
       160: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
        160: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
         160: com.redhat.persistence.Session$1.onRole(Session.java:147)
          160: com.redhat.persistence.metadata.Role.dispatch(Role.java:92)
       372: com.redhat.persistence.Session.load(Session.java:716)
        363: com.redhat.persistence.RecordSet.load(RecordSet.java:165)
         286: com.redhat.persistence.Cursor.next(Cursor.java:112)
          280: com.arsdigita.persistence.DataQueryImpl.next(DataQueryImpl.java:465)
    1055: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:742)
     1030: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
      1030: com.redhat.persistence.Session.getSessionKey(Session.java:777)
       633: com.redhat.persistence.Session.getObjectData(Session.java:825)
        160: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
         160: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
          160: com.redhat.persistence.Session$1.onRole(Session.java:147)
        372: com.redhat.persistence.Session.load(Session.java:716)
         363: com.redhat.persistence.RecordSet.load(RecordSet.java:165)
          286: com.redhat.persistence.Cursor.next(Cursor.java:112)
    1055: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:746)
     1030: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
      1030: com.redhat.persistence.Session.getSessionKey(Session.java:777)
       633: com.redhat.persistence.Session.getObjectData(Session.java:825)
        160: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
         160: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
          160: com.redhat.persistence.Session$1.onRole(Session.java:147)
        372: com.redhat.persistence.Session.load(Session.java:716)
         363: com.redhat.persistence.RecordSet.load(RecordSet.java:165)
          286: com.redhat.persistence.Cursor.next(Cursor.java:112)

2004-02-10 14:05:20,573 [000-0] DEBUG developersupport.CallRecord - Context path: ''
Request URI: '/ccm/content/admin/index.jsp'
Query string: 'null'
; threshold: 25
2004-02-10 14:05:20,573 [000-0] DEBUG developersupport.CallRecord - DataType.getQualifiedName:
DataType.getQualifiedName
 3714: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:72)
  3461: com.arsdigita.persistence.C.type(C.java:44)
   3442: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:757)
    1030: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
     1030: com.redhat.persistence.Session.getSessionKey(Session.java:777)
      633: com.redhat.persistence.Session.getObjectData(Session.java:825)
       160: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
        160: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
         160: com.redhat.persistence.Session$1.onRole(Session.java:147)
          160: com.redhat.persistence.metadata.Role.dispatch(Role.java:92)
       372: com.redhat.persistence.Session.load(Session.java:716)
        363: com.redhat.persistence.RecordSet.load(RecordSet.java:165)
         286: com.redhat.persistence.Cursor.next(Cursor.java:112)
          280: com.arsdigita.persistence.DataQueryImpl.next(DataQueryImpl.java:465)
    1055: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:742)
     1030: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
      1030: com.redhat.persistence.Session.getSessionKey(Session.java:777)
       633: com.redhat.persistence.Session.getObjectData(Session.java:825)
        160: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
         160: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
          160: com.redhat.persistence.Session$1.onRole(Session.java:147)
        372: com.redhat.persistence.Session.load(Session.java:716)
         363: com.redhat.persistence.RecordSet.load(RecordSet.java:165)
          286: com.redhat.persistence.Cursor.next(Cursor.java:112)
    1055: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:746)
     1030: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
      1030: com.redhat.persistence.Session.getSessionKey(Session.java:777)
       633: com.redhat.persistence.Session.getObjectData(Session.java:825)
        160: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
         160: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
          160: com.redhat.persistence.Session$1.onRole(Session.java:147)
        372: com.redhat.persistence.Session.load(Session.java:716)
         363: com.redhat.persistence.RecordSet.load(RecordSet.java:165)
          286: com.redhat.persistence.Cursor.next(Cursor.java:112)
Comment 14 Vadim Nasardinov 2004-02-10 15:28:12 EST
By instrumenting Session.java as follows:

==== //core-platform/dev/src/com/redhat/persistence/Session.java#11
@@ -15,6 +15,7 @@
 
 package com.redhat.persistence;
 
+import com.arsdigita.developersupport.Counter;
 import com.redhat.persistence.common.Path;
 import com.redhat.persistence.metadata.Adapter;
 import com.redhat.persistence.metadata.Alias;
@@ -774,7 +775,11 @@
 
     Object getSessionKey(Object obj) {
         Adapter ad = getAdapter(obj);
-        return ad.getSessionKey(obj);
+        final Object result = ad.getSessionKey(obj);
+        Counter.getCounter().increment
+            (obj.getClass().getName() + "@" + System.identityHashCode(obj) +
+             "; key=" + result);
+        return result;
     }
 
     /**

I get the trace shown at the bottom of this comment.

What the trace tells me is that we needlessly (?) recompute session
key for DataObjectImpl objects.  For some data objects, their session
key is recomputed over a hundred times during a single transaction.
See, for example, DataObjectImpl@1040082 below.

The declared return value of
com.redhat.persistence.Session.getSessionKey(Object) is Object.  The
actual returned value seems always be a CompoundKey.  This value is
recomputed on every call to getSessionKey.  So, for example, if you
look at DataObjectImpl@1040082, its session key is always
key(com.arsdigita.kernel.ACSObject, 1012).  However, if you look at
the actual CompoundKey values returned, you'll see that they are
recomputed afresh on every call to getSessionKey.

If we could find a place to cache session keys for DataObjectImpl
objects for the duration of the transaction, we would reduce the
number of calls to DataType.getQualifiedName by an order of magnitude.

================================================================================
Context path: ''
Request URI: '/ccm/content/admin/index.jsp'
Query string: 'null'
:
    com.arsdigita.persistence.DataObjectImpl@1040082; key=key(com.arsdigita.kernel.ACSObject, 1012): 23
    com.arsdigita.persistence.DataObjectImpl@4229054; key=key(com.arsdigita.kernel.ResourceType, 1005): 8
    com.arsdigita.persistence.DataObjectImpl@4291212; key=key(com.arsdigita.kernel.ACSObject, 17): 20
    com.arsdigita.persistence.DataObjectImpl@5545742; key=key(com.arsdigita.kernel.ACSObject, 17): 1
    com.arsdigita.persistence.DataObjectImpl@6615067; key=key(com.arsdigita.kernel.security.KeyStore, 0): 8

Context path: ''
Request URI: '/__ccm__/servlet/content-section/admin/index.jsp'
Query string: 'app-id=1012'
:
      com.arsdigita.persistence.DataObjectImpl@1040082; key=key(com.arsdigita.kernel.ACSObject, 1012): 86
      com.arsdigita.persistence.DataObjectImpl@1212565; key=key(com.arsdigita.kernel.ACSObject, 53): 21
      com.arsdigita.persistence.DataObjectImpl@1840227; key=key(com.arsdigita.kernel.ACSObject, 1013): 25
      com.arsdigita.persistence.DataObjectImpl@2438443; key=key(com.arsdigita.kernel.ACSObject, 1008): 183
      com.arsdigita.persistence.DataObjectImpl@2581254; key=key(com.arsdigita.kernel.PackageType, 48): 19
      com.arsdigita.persistence.DataObjectImpl@2610607; key=key(com.arsdigita.kernel.ACSObject, 87): 30
      com.arsdigita.persistence.DataObjectImpl@3029181; key=key(com.arsdigita.kernel.permissions.ObjectContext, 1008): 13
      com.arsdigita.persistence.DataObjectImpl@3169328; key=key(com.arsdigita.kernel.PersonName, 18): 31
      com.arsdigita.persistence.DataObjectImpl@3388325; key=key(com.arsdigita.kernel.ACSObject, 1014): 12
      com.arsdigita.persistence.DataObjectImpl@3954857; key=key(com.arsdigita.kernel.ACSObject, 1014): 3
      com.arsdigita.persistence.DataObjectImpl@4063113; key=key(com.arsdigita.kernel.ACSObject, 1113): 30
      com.arsdigita.persistence.DataObjectImpl@4076652; key=key(com.arsdigita.kernel.ACSObject, 9003): 72
      com.arsdigita.persistence.DataObjectImpl@4123985; key=key(com.arsdigita.kernel.ACSObject, 17): 14
      com.arsdigita.persistence.DataObjectImpl@4229054; key=key(com.arsdigita.kernel.ResourceType, 1005): 4
      com.arsdigita.persistence.DataObjectImpl@4291212; key=key(com.arsdigita.kernel.ACSObject, 17): 15
      com.arsdigita.persistence.DataObjectImpl@4523777; key=key(com.arsdigita.kernel.PersonName, 0): 104
      com.arsdigita.persistence.DataObjectImpl@5042349; key=key(com.arsdigita.cms.TemplateContext, alternate): 14
      com.arsdigita.persistence.DataObjectImpl@5046327; key=key(com.arsdigita.cms.TemplateContext, summary): 14
      com.arsdigita.persistence.DataObjectImpl@5053951; key=key(com.arsdigita.kernel.ResourceType, 31): 30
      com.arsdigita.persistence.DataObjectImpl@5082113; key=key(com.arsdigita.kernel.PackageType, 50): 13
      com.arsdigita.persistence.DataObjectImpl@509864; key=key(com.arsdigita.kernel.ACSObject, 81): 71
      com.arsdigita.persistence.DataObjectImpl@5545742; key=key(com.arsdigita.kernel.ACSObject, 17): 29
      com.arsdigita.persistence.DataObjectImpl@5815330; key=key(com.arsdigita.kernel.PackageType, 48): 27
      com.arsdigita.persistence.DataObjectImpl@6273564; key=key(com.arsdigita.kernel.ACSObject, 16): 4
      com.arsdigita.persistence.DataObjectImpl@6502834; key=key(com.arsdigita.kernel.ACSObject, 1009): 38
      com.arsdigita.persistence.DataObjectImpl@6511241; key=key(com.arsdigita.cms.TemplateContext, public): 14
      com.arsdigita.persistence.DataObjectImpl@6537522; key=key(com.arsdigita.auditing.BasicAuditTrail, 9003): 13
      com.arsdigita.persistence.DataObjectImpl@7029221; key=key(com.arsdigita.kernel.ACSObject, 33): 44
      com.arsdigita.persistence.DataObjectImpl@7351978; key=key(com.arsdigita.kernel.ACSObject, 52): 14
      com.arsdigita.persistence.DataObjectImpl@7686543; key=key(com.arsdigita.kernel.PersonName, 18): 16
      com.arsdigita.persistence.DataObjectImpl@7781402; key=key(com.arsdigita.categorization.UseContext, 1015): 13
      com.arsdigita.persistence.DataObjectImpl@8244021; key=key(com.arsdigita.auditing.BasicAuditTrail, 1008): 7
      com.arsdigita.persistence.DataObjectImpl@8293337; key=key(com.arsdigita.kernel.ACSObject, 1013): 7
      com.redhat.persistence.PropertyMap@1005522; key=key(com.arsdigita.cms.getPrivileges, null): 1
      com.redhat.persistence.PropertyMap@1035110; key=key(com.arsdigita.cms.getPrivileges, null): 1
      com.redhat.persistence.PropertyMap@1166571; key=key(com.arsdigita.kernel.permissions.ObjectPermissionCollection, null): 1
      [76 more similar PropertyMap traces omitted for brevity's sake]
Comment 15 Vadim Nasardinov 2004-02-10 15:30:55 EST
After applying the following _naive_ patch (which is meant to
illustrate a point rather than be a real fix), I see a 80% reduction
in the number of calls to DataType#getQualifiedName().


==== //core-platform/dev/src/com/arsdigita/persistence/DataObjectImpl.java#20
@@ -35,7 +35,7 @@
  * @version $Revision: #20 $ $Date: 2004/01/15 $
  **/
 
-class DataObjectImpl implements DataObject {
+public class DataObjectImpl implements DataObject {
 

 
@@ -50,6 +50,7 @@
     private boolean m_valid = true;
     // originating transaction has terminated
     private boolean m_transactionDone = false;
+    public Object sessionKey;
 
     private final class ObserverEntry {
 
==== //core-platform/dev/src/com/redhat/persistence/Session.java#11
@@ -15,6 +15,7 @@
 
 package com.redhat.persistence;
 
+import com.arsdigita.persistence.DataObjectImpl;
 import com.redhat.persistence.common.Path;
 import com.redhat.persistence.metadata.Adapter;
 import com.redhat.persistence.metadata.Alias;
@@ -773,8 +774,15 @@
     }
 
     Object getSessionKey(Object obj) {
-        Adapter ad = getAdapter(obj);
-        return ad.getSessionKey(obj);
+        if ( obj instanceof DataObjectImpl ) {
+            DataObjectImpl dobj = (DataObjectImpl) obj;
+            if ( dobj.sessionKey==null ) {
+                dobj.sessionKey = getAdapter(dobj).getSessionKey(dobj);
+            }
+            return dobj.sessionKey;
+        } else {
+            return getAdapter(obj).getSessionKey(obj);
+        }
     }
 
     /**



Compare the following trace to the one shown above in comment #13.
The number of calls to DataType#getQualifiedName() went down from 3714
to 708 (for the same page).


2004-02-10 15:26:46,091 [000-0] DEBUG developersupport.CallRecord - DataType.getQualifiedName:
DataType.getQualifiedName
 708: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:73)
  455: com.arsdigita.persistence.C.type(C.java:44)
   436: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:757)
    192: com.redhat.persistence.Session.getObjectType(Session.java:425)
     160: com.redhat.persistence.Session.get(Session.java:143)
      142: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:517)
       113: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:225)
        97: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
         39: com.arsdigita.cms.ContentItem.get(ContentItem.java:378)
          10: com.arsdigita.kernel.ACSObject.getSpecificObjectType(ACSObject.java:373)
          10: com.arsdigita.versioning.VersionedACSObject.initialize(VersionedACSObject.java:102)
          17: com.arsdigita.cms.ContentItem.getVersion(ContentItem.java:801)
Comment 16 Vadim Nasardinov 2004-02-10 19:21:58 EST
Created attachment 97572 [details]
proof-of-concept patch that greatly reduces calls to getQualifiedName

With this patch applied, the number of calls to
DataType#getQualifiedName() goes from 3714 (cf.comment #13) down to
225.  In other words, the number of calls is reduced by a factor of
16.

I would be interested to see Dan and/or Bryan re-profile CMS with this
patch applied.


The following callers are now responsible for the majority of calls to
DataType#getQualifiedName():



2004-02-10 19:17:59,431 [000-0] DEBUG developersupport.CallRecord -
DataType.getQualifiedName:
DataType.getQualifiedName
 225:
com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:73)
  82: com.arsdigita.persistence.C.prop(C.java:54)
   41:
com.arsdigita.persistence.DataObjectImpl.convert(DataObjectImpl.java:168)
    37: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:234)
     30: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
   25:
com.arsdigita.persistence.DataObjectImpl.doDisconnect(DataObjectImpl.java:268)
    19: com.arsdigita.persistence.DataObjectImpl.get(DataObjectImpl.java:209)
     19: com.arsdigita.domain.DomainObject.get(DomainObject.java:436)
      6:
com.arsdigita.kernel.PackageType.getDispatcherClass(PackageType.java:264)
       6:
com.arsdigita.kernel.PackageInstance.getTargetBundle(PackageInstance.java:243)
	6:
com.arsdigita.sitenode.SiteNodeRequestContext.<init>(SiteNodeRequestContext.java:137)

	 6:
com.arsdigita.web.BaseApplicationServlet.makeLegacyContext(BaseApplicationServlet.java:206)

	  6:
com.arsdigita.web.BaseApplicationServlet.doService(BaseApplicationServlet.java:97)

      6: com.arsdigita.kernel.User.getPersonName(User.java:289)
       6: com.arsdigita.kernel.User.getName(User.java:301)
	6: com.arsdigita.kernel.Party.getDisplayName(Party.java:142)
	 6:
com.arsdigita.cms.dispatcher.CMSPage.generateXMLHelper(CMSPage.java:306)
	  6: com.arsdigita.bebop.Page.generateXML(Page.java:635)
  83: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:52)
   28: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
    28:
com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
     28:
com.arsdigita.domain.ObservableDomainObject.initializeGlobalObservers(ObservableDomainObject.java:113)

      26:
com.arsdigita.domain.ObservableDomainObject.<init>(ObservableDomainObject.java:49)

       26: com.arsdigita.kernel.ACSObject.<init>(ACSObject.java:101)
	8: com.arsdigita.cms.ContentType.<init>(ContentType.java:105)
	 8:
com.arsdigita.cms.ContentTypeCollection.getDomainObject(ContentTypeCollection.java:66)

	  8:
com.arsdigita.cms.ContentTypeCollection.getContentType(ContentTypeCollection.java:75)

   55: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
    28: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
     28:
com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
      28:
com.arsdigita.domain.ObservableDomainObject.initializeGlobalObservers(ObservableDomainObject.java:113)

       26:
com.arsdigita.domain.ObservableDomainObject.<init>(ObservableDomainObject.java:49)

	26: com.arsdigita.kernel.ACSObject.<init>(ACSObject.java:101)
	 8: com.arsdigita.cms.ContentType.<init>(ContentType.java:105)
	  8:
com.arsdigita.cms.ContentTypeCollection.getDomainObject(ContentTypeCollection.java:66)

    27: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
     14: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
      14:
com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
       14:
com.arsdigita.domain.ObservableDomainObject.initializeGlobalObservers(ObservableDomainObject.java:113)

	12:
com.arsdigita.domain.ObservableDomainObject.<init>(ObservableDomainObject.java:49)

	 12: com.arsdigita.kernel.ACSObject.<init>(ACSObject.java:101)
	  5: com.arsdigita.kernel.Resource.<init>(Resource.java:50)
	  6:
com.arsdigita.versioning.VersionedACSObject.<init>(VersionedACSObject.java:63)
     13: com.arsdigita.search.lucene.Registry.getAdapter(Registry.java:55)
      13: com.arsdigita.search.lucene.Registry.hasAdapter(Registry.java:48)
       13:
com.arsdigita.search.SearchObserver.shouldObserve(SearchObserver.java:61)
	13:
com.arsdigita.domain.ObservableDomainObject.initializeGlobalObservers(ObservableDomainObject.java:113)

	 11:
com.arsdigita.domain.ObservableDomainObject.<init>(ObservableDomainObject.java:49)

	  11: com.arsdigita.kernel.ACSObject.<init>(ACSObject.java:101)
Comment 17 Rafael H. Schloming 2004-02-11 15:43:58 EST
One thing you can do which might have a similar effect would be to
change the DataObjectAdapter class in
com.arsdigita.persistence.Session to store a PropertyMap inside
DataObjectImpl. Currently it always builds a new PropertyMap and
returns it. Since both these classes are in the same package it would
not require making DataObjectImpl public, and since I suspect most of
the getQualifiedName() calls are coming from this conversion process
which is part of constructing the session key it should have a similar
effect.
Comment 18 Vadim Nasardinov 2004-02-11 16:56:58 EST
Good call.  By caching PropertyMap in DataObjectImpl instead of
recomputing it anew every time, we reduce the frequency of calls to
DataObject#getQualifiedName() by 38%.

My proof-of-concept thingy (patch 97572) reduces it by 94%. So, I need
a couple more bright ideas like that.

Here's the stats before your PropertyMap patch:

|Request URI: '/ccm/content/admin/index.jsp'
|Query string: 'null'
|; threshold: 25
|2004-02-11 16:40:19,174 [000-3] DEBUG developersupport.CallRecord - getQualifiedName:
|getQualifiedName
| 2575: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:72)
|  2380: com.arsdigita.persistence.C.type(C.java:44)
|   2363: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:757)
|    704: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
|     704: com.redhat.persistence.Session.getSessionKey(Session.java:777)
|      406: com.redhat.persistence.Session.getObjectData(Session.java:825)
|       124: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
|        124: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
|       207: com.redhat.persistence.Session.load(Session.java:716)
|        198: com.redhat.persistence.RecordSet.load(RecordSet.java:165)
|    722: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:742)
|     704: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
|      704: com.redhat.persistence.Session.getSessionKey(Session.java:777)
|       406: com.redhat.persistence.Session.getObjectData(Session.java:825)
|        124: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
|         124: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
|        207: com.redhat.persistence.Session.load(Session.java:716)
|    722: com.arsdigita.persistence.Session$DataObjectAdapter.getProperties(Session.java:746)
|     704: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
|      704: com.redhat.persistence.Session.getSessionKey(Session.java:777)
|       406: com.redhat.persistence.Session.getObjectData(Session.java:825)
|        124: com.redhat.persistence.Session.fetchObjectData(Session.java:858)
|         124: com.redhat.persistence.Session.fetchPropertyData(Session.java:867)
|        207: com.redhat.persistence.Session.load(Session.java:716)


Here's are the stats after the patch:

|getQualifiedName
| 1601: com.arsdigita.persistence.metadata.DataType.getQualifiedName(DataType.java:72)
|  1347: com.arsdigita.persistence.C.type(C.java:44)
|   1330: com.arsdigita.persistence.Session$DataObjectAdapter.getObjectType(Session.java:763)
|    1000: com.redhat.persistence.metadata.Adapter.getSessionKey(Adapter.java:49)
|     1000: com.redhat.persistence.Session.getSessionKey(Session.java:777)
|      638: com.redhat.persistence.Session.getObjectData(Session.java:825)
|       397: com.redhat.persistence.Session.load(Session.java:716)
|        388: com.redhat.persistence.RecordSet.load(RecordSet.java:165)
|         313: com.redhat.persistence.Cursor.next(Cursor.java:112)
|          307: com.arsdigita.persistence.DataQueryImpl.next(DataQueryImpl.java:465)
Comment 19 Vadim Nasardinov 2004-02-11 17:08:52 EST
Created attachment 97597 [details]
implementation of what Rafi suggested in comment 17

See comment 18 for further comments on this patch.
Comment 20 Rafael H. Schloming 2004-02-11 17:33:40 EST
I'd suggest trying the same trick with
Session$DataObjectAdapter.getObjectType(). In fact it might be
reasonable to just implement it as getProperties().getObjectType().
The only thing you need to make sure of is that the type it returns
correctly reflects whether or not specialize has been called on the
data object, i.e. you need to make sure that if DataObject.specialize
gets called the property map is reconstructed with the correctly
specialized type.
Comment 21 Vadim Nasardinov 2004-02-11 17:40:38 EST
> The only thing you need to make sure of is that the type it returns
> correctly reflects whether or not specialize has been called on the
> data object

I was going to ask you about that.  I ran into this in my
proof-of-concept patch.  If you take a look at attachment 97572 [details],
you'll notice that I special-case the handling of the object type
"ResourceType".  Without this special-casing, the patch blows up on
instances of ApplicationType.  That's probably because they are
obtained by specializing from ResourceType to ApplicationType.
Comment 22 Vadim Nasardinov 2004-02-12 16:28:10 EST
Fixed on the trunk in change 40336
Comment 23 Vadim Nasardinov 2004-02-19 17:45:25 EST
I propose we mark this ticket as WONTFIX for the following reasons.

 1. This is not the most frequently used page.

 2. The slowness is due to the large number of db queries and there is
    not really any single Java bottleneck that stands out.

Our code accounts for about 37% of the total execution time, as shown
in comment #10.

Oracle's JDBC driver accounts for 31% of the total execution time:
    |Total:                                       31.20%   46963 ms
    |--------------------------------------------------------------
    |OCIDBAccess.parseExecuteDescribe             9.82%   14369 ms
    |OCIDBAccess.executeFetch                     7.05%   10314 ms
    |OCIDBAccess.fetch                            6.37%    9337 ms
    |OracleSql.handleODBC                         0.80%    1210 ms
    |OCIDBAccess.open                             0.76%    1121 ms
    |OCIDBAccess.parseExecuteFetch                0.57%     852 ms
    |OCIDBAccess.close                            0.43%     650 ms
    |OCIDBAccess.copy_back_to_next_stream         0.42%     642 ms
    |OCIDBAccess.commit                           0.39%     574 ms
      [107 more lines omitted for brevity]

Standard Java libraries:
    |Total:                                       15.56%   24467 ms
    |--------------------------------------------------------------
    |StreamEncoder$ConverterSE.<init>             2.53%    3708 ms
    |SocketInputStream.read                       1.63%    2388 ms
    |IOException.<init>                           0.95%    1395 ms
    |SocketOutputStream.socketWrite               0.78%    1146 ms
    |ResourceBundle.getLoader                     0.76%    1114 ms
    |URLEncoder.encode                            0.54%     864 ms
    |ZipFile.getEntry                             0.54%     812 ms
    |AbstractList$Itr.hasNext                     0.50%     734 ms
     [136 more lines omitted for brevity]

Saxon:
    |Total:                                     3.41%    6077 ms
    |-----------------------------------------------------------
    |DOMDriver.walkNode                         0.23%     430 ms
    |NamePool.allocate                          0.17%     290 ms
    |StyleElement.processChildren               0.17%     283 ms
    |HTMLEmitter.escapeURL                      0.14%     217 ms
    |NamePool.allocateNamespaceCode             0.10%     170 ms

Various Jakarta libraries:
    |Total:                                    2.13%    3563 ms
    |----------------------------------------------------------
    |Category.isDebugEnabled                   0.45%     670 ms
    |ParentNode.internalInsertBefore           0.29%     472 ms
    |AttributeMap.setNamedItem                 0.13%     201 ms
    |  [44 more lines]

Resin:
    |Total:                                        1.91%    3214 ms
    |--------------------------------------------------------------
    |TcpServer.accept                              0.44%     645 ms
    |UTF8Writer.write                              0.24%     393 ms
    |WriteStream$StreamWriter.write                0.16%     258 ms
    |WriteStream.print                             0.13%     217 ms
    |FilePath.canRead                              0.10%     149 ms
     [47 more lines]


So, 68% of the total execution time is DB-driven.  It's split almost
evenly between persistence and the JDBC driver.  Overall, persistence
takes up quite a lot of resources.  Unfortunately, this slowness is
diffused more or less evenly across a number of classes.

The two worst offenders are Path.get and Session.getSessionKey.

I don't see any way to reduce the number of calls to Path.get.

As far as Session.getSessionKey goes, I don't see a good way to avoid
redundant calls.  (In bug 113696 comment #16, I posted a
proof-of-concept patch that shows that the frequency of calls to
getSessionKey _can_ be reduced, but not in a sound way.)

So, one of the takeways from this ticket is that persistence is not a
thin layer on top of JDBC.  It roughly doubles the time of our
interactions with the database.  It may be worth it to tune
persistence a little further.  This would have to happen after the
land of Archit and Rafi's OQL/sqlgen branch.
Comment 24 Vadim Nasardinov 2004-02-19 17:52:03 EST
Disregard my last post (comment #23).  I meant to post it to bug 115041.

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