Bug 450523 - [Profiles] Performance bottleneck and exceptions in StereotypeElementListener
Summary: [Profiles] Performance bottleneck and exceptions in StereotypeElementListener
Status: RESOLVED FIXED
Alias: None
Product: Papyrus
Classification: Modeling
Component: Others (show other bugs)
Version: 1.1.0   Edit
Hardware: All All
: P1 critical (vote)
Target Milestone: M3   Edit
Assignee: Camille Letavernier CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-11-07 08:24 EST by Christian Damus CLA
Modified: 2014-11-07 14:20 EST (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Christian Damus CLA 2014-11-07 08:24:37 EST
Test execution shows severe performance regressions, initially attributed to the StereotypeElementListener.  It does unnecessary work and throws lots of exceptions, which likely also contribute to performance slow-down (all that work of filling in stack traces, unwinding stacks, logging exceptions).

From the mailing list:

!ENTRY org.eclipse.emf.transaction 4 45 2014-11-07 12:53:26.607
!MESSAGE Uncaught exception during post-commit listener notifications
!STACK 0
java.lang.NullPointerException
       at org.eclipse.papyrus.uml.tools.listeners.StereotypeElementListener.handleFilteredNotification(StereotypeElementListener.java:157)
       at org.eclipse.papyrus.uml.tools.listeners.StereotypeElementListener.resourceSetChanged(StereotypeElementListener.java:88)
       at org.eclipse.emf.transaction.impl.TransactionalEditingDomainImpl$1.run(TransactionalEditingDomainImpl.java:781)
       at org.eclipse.emf.transaction.impl.TransactionalEditingDomainImpl.runExclusive(TransactionalEditingDomainImpl.java:328)
       at org.eclipse.emf.transaction.impl.TransactionalEditingDomainImpl.postcommit(TransactionalEditingDomainImpl.java:771)
       at org.eclipse.emf.transaction.impl.TransactionalEditingDomainImpl.deactivate(TransactionalEditingDomainImpl.java:543)
       at org.eclipse.emf.transaction.impl.TransactionImpl.close(TransactionImpl.java:712)
       at org.eclipse.emf.transaction.impl.TransactionImpl.commit(TransactionImpl.java:474)
       at org.eclipse.emf.workspace.AbstractEMFOperation.redo(AbstractEMFOperation.java:463)
       at org.eclipse.core.commands.operations.DefaultOperationHistory.doRedo(DefaultOperationHistory.java:357)
       at org.eclipse.core.commands.operations.DefaultOperationHistory.redo(DefaultOperationHistory.java:1110)
       at org.eclipse.papyrus.commands.CheckedOperationHistory.redo(CheckedOperationHistory.java:220)
       at org.eclipse.gmf.runtime.diagram.ui.parts.DiagramCommandStack.redo(DiagramCommandStack.java:366)
       at org.eclipse.papyrus.sysml.diagram.internalblock.tests.utils.TestUtils.defaultExecutionTest(TestUtils.java:742)
       at org.eclipse.papyrus.sysml.diagram.internalblock.tests.utils.TestUtils.setEncapsulationDeleteConnectorTest(TestUtils.java:591)
       at org.eclipse.papyrus.sysml.diagram.internalblock.tests.set.encapsulation.AbstractSetEncapsulationDeleteConnectorTest.setEncapsulationDeleteConnectorWithTargetProperty(AbstractSetEncapsulationDeleteConnectorTest.java:114)
Comment 1 Christian Damus CLA 2014-11-07 08:25:22 EST
I'll have a look at this with YourKit.
Comment 2 Camille Letavernier CLA 2014-11-07 08:36:21 EST
Initial investigation shows that "getUMLDefinition" in StereotypeExtensionFinder takes ~100ms on each post-commit, because it calls "UMLUtil.getNamedElement", which ends up in UMLUtil.getProfile() (Which is slow because it needs to do some research to find something).

This could probably be improved with a pre-check (Verifying that the current EObject at least "looks like" a Stereotype application before trying to find the associated profile).

I also suspected the new memory leaks to be at fault, since we know that a saturated memory can cause severe performance degradation. However, the performance degration in this case occurred way before the memory was saturated, so this is unrelated.
Comment 3 Christian Damus CLA 2014-11-07 08:42:03 EST
Yes, there are a few simple checks that can be done up-front (e.g., check that the notifier isn't an UML Element) but that doesn't help very much.

We may have to cut some corners, such as not verifying that a property named base_Xyz actually is an ExtensionEnd.
Comment 4 Camille Letavernier CLA 2014-11-07 08:44:37 EST
Actually, checking that there is a base_x property before calling UMLUtil.getDefinition() might help. I've seen UMLUtil.getDefinition() being called on e.g. Notation elements (So simply excluding UML is not sufficient, and explicitely excluding Ecore packages in general is not sufficient)
Comment 5 Camille Letavernier CLA 2014-11-07 08:54:48 EST
Usually, we rely on UMLUtil.getBaseElement() to quickly check whether an EObject is a stereotype application. However, as I understand it, this is not possible in this specific case because we can have an EObject which is an un-applied Stereotype Application (And doesn't have a base_Element)

But what UMLUtil.getBaseElement() does is exactly that: first, check whether the base_X property exists. This fails quickly if the object is not a stereotype application. Otherwise, if it actually is, it will search and load the associated profile and do a complete check.

I've made a quick patch to try this approach and see whether it gives better performances (and still gives accurate results).
Comment 6 Christian Damus CLA 2014-11-07 09:03:02 EST
The memory leak failures are not related to the StereotypeElementListener.  I locally reverted the commit that integrated the StereotypeElementListener but those tests still fail.
Comment 7 Christian Damus CLA 2014-11-07 09:05:25 EST
(In reply to Camille Letavernier from comment #5)
> Usually, we rely on UMLUtil.getBaseElement() to quickly check whether an
> EObject is a stereotype application. However, as I understand it, this is
> not possible in this specific case because we can have an EObject which is
> an un-applied Stereotype Application (And doesn't have a base_Element)

Correct.  That's the point of this new listener implementation.  :-)

Also, UMLUtil.getBaseElement doesn't check that an object actually is a stereotype instance.  Any EReference named base_xyz that happens to reference an Element is interpreted as a metaclass extension, even if it has nothing to do with profiles (e.g., imagine if the Notation metamodel has View::base_element instead of View::element).
Comment 8 Camille Letavernier CLA 2014-11-07 09:13:11 EST
The small patch shows major improvements (6 min to run IBD tests, vs. 1h30 without the patch). I will let the test suite run to completion before I push it, to be sure this doesn't introduce any regression

Checking that the Property is an ExtensionEnd is probably safe (in terms of performances) after that

> Also, UMLUtil.getBaseElement doesn't check that an object actually is a stereotype instance. Any EReference named base_xyz that happens to reference an Element is interpreted as a metaclass extension, even if it has nothing to do with profiles (e.g., imagine if the Notation metamodel has View::base_element instead of View::element).

From what I see, the current implementation checks for the existence of a uml::Stereotype:

[...]
if (baseElement != null && getStereotype(eClass, stereotypeApplication) != null) {
	return baseElement;
}
[...]
Comment 9 Christian Damus CLA 2014-11-07 09:25:07 EST
(In reply to comment #8)
> The small patch shows major improvements (6 min to run IBD tests, vs. 1h30
> without the patch). I will let the test suite run to completion before I push
> it, to be sure this doesn't introduce any regression

You seem to have this well in hand, so I'll leave it to you and shall have a look at some of the other regressions.  :-)


> Checking that the Property is an ExtensionEnd is probably safe (in terms of
> performances) after that
> 
> > Also, UMLUtil.getBaseElement doesn't check that an object actually is a
> stereotype instance. Any EReference named base_xyz that happens to reference an
> Element is interpreted as a metaclass extension, even if it has nothing to do
> with profiles (e.g., imagine if the Notation metamodel has View::base_element
> instead of View::element).
> 
> From what I see, the current implementation checks for the existence of a
> uml::Stereotype:

Indeed.  I must have been thinking of something else.
Comment 10 Camille Letavernier CLA 2014-11-07 09:36:39 EST
Commit c69a56c fixes the performance bottleneck (Pushed to master)

I'll let the test suite run to see whether the NullPointerException still exists (It seems easy to workaround, but I wonder whether it hides something more problematic, such as a Stereotype Application which is not associated to a base_Element... There should be something to notify before this even happens)
Comment 11 Christian Damus CLA 2014-11-07 09:40:27 EST
(In reply to Camille Letavernier from comment #10)
> Commit c69a56c fixes the performance bottleneck (Pushed to master)
> 
> I'll let the test suite run to see whether the NullPointerException still
> exists (It seems easy to workaround, but I wonder whether it hides something
> more problematic, such as a Stereotype Application which is not associated
> to a base_Element... There should be something to notify before this even
> happens)

I think you'll still have that NPE.  The last bit of the handleFilteredNotification method doesn't check that the 'element' on which it is sending a notification is non-null.  It can be null in the case that we are processing a notification from a stereotype instance that has already been unapplied from its former base element.  In such cases, we don't need to send out the extra notification because it doesn't matter once the stereotype has been unapplied.
Comment 12 Camille Letavernier CLA 2014-11-07 09:50:08 EST
The NPE has been fixed in 81811c2, pushed to master
Comment 13 Christian Damus CLA 2014-11-07 14:20:36 EST
I have pushed commit 379adc6f9592ba5da6fdde281da07f3a9bec3bab to fix some more test failures caused by the StereotypeElementListener.

The diagrams expected the stereotype applied/unapplied notifications to report the stereotype *instance* (not the definition) as the new/old value.  As such, they would use the UMLUtil::getStereotype(EObject) API to get the defining stereotype.  Invoking that with a stereotype of course yields null because a stereotype is not a stereotype instance.  Wrong behaviour then ensues.

So, now the custom notifications sent by the StereotypeElementListener conform to the contract expected by diagrams, which makes sense as the stereotype instance is in reality the 'value' of the extension that is changed, and adds a new field that provides the Stereotype.  This will be convenient for new clients of this API.