Home » Modeling » TMF (Xtext) » Optimizing build performance - observing redundant calls to isAffected and validation
| Optimizing build performance - observing redundant calls to isAffected and validation [message #1758543] |
Wed, 29 March 2017 20:42  |
 Larry LeBron
Messages: 124
Registered: October 2015 |
Senior Member |
|
|
I have an xtext dsl project with 255 dsl files, and I am observing some very long builds.
I have added logging to trace what's going on.
When making a single change (adding a comment) to a single line in one resource, I am experiencing a long build after saving (at least 10 seconds).
During a build like this, I see the the build cycle (including the inferrer and validator) being called more than 20 times. Sometimes as high as 50 or so.
I've done a bit more digging, including inserting traces into XTextBuilder, IXtextBuilderParticipant and IResourceDescription.Manager.isAffected().
For example, on one save I saw 10 calls to XTextBuilder.doBuild(). I then tried it again and saw 18 additional calls.
For all of these, I see the same exact deltas in IXtextBuilderParticipant.doBuild(), corresponding to the one resource file that was altered:
[DefaultResourceDescriptionDelta for platform:/resource/playablEngine/src/ai/playabl/abl/test/TestEntity.abl old :true,new :true]
I guess my main question is - is there any way to optimize this? Why is build and validation being called so many times for this file after a single save?
Some additional info on the deltas being passed to isAffected() is below. Let me know if any additional analysis would be helpful to shed light on this.
Thanks for any advice.
As an example, here is the first set of deltas it's querying about. It includes 3 deltas:
[UnconfirmedStructuralChangesDelta for java:/Objects/assertions._assertionSetter old :true,new :true,
ChangedResourceDescriptionDelta for java:/Objects/testExpressions._bindTestWMEHierarchical old :true,new :false,
ChangedResourceDescriptionDelta for java:/Objects/rules._testTestExpression old :true,new :false]
I see this set passed to isAffected 1,529 times during the build. The validator runs between those two rounds of isAffected calling.
Therefore, each round of calls to isAffected is actually comprised of 764 calls, which corresponds to one call to isAffected per project resource per member of the delta set.
Later in the build logging, 1,020 calls for another delta (exactly 4 times through the project resource set)
[ChangedResourceDescriptionDelta for java:/Objects/rules._testTestExpression old :true,new :false,
ChangedResourceDescriptionDelta for java:/Objects/testExpressions._bindTestWMEHierarchical old :true,new :false,
UnconfirmedStructuralChangesDelta for java:/Objects/assertions._assertionSetter old :true,new :true]
Looking at this set, it looks like the same as the earlier one I quoted, in a different order.
A later set includes these, and isAffected is called for it 510 times (2 times through the resource set)
[ChangedResourceDescriptionDelta for java:/Objects/testExpressions._bindTestWMEHierarchical old :true,new :false,
ChangedResourceDescriptionDelta for java:/Objects/rules._testTestExpression old :true,new :false,
UnconfirmedStructuralChangesDelta for java:/Objects/assertions._assertionSetter old :true,new :true]
This set is again made of the same 3 deltas in a different order.
[Updated on: Fri, 31 March 2017 19:13] Report message to a moderator |
|
| | | | |
| Re: Optimizing build performance - observing redundant calls to isAffected and validation [message #1758706 is a reply to message #1758558] |
Fri, 31 March 2017 19:07  |
Larry LeBron
Messages: 124
Registered: October 2015 |
Senior Member |
|
|
I've done some additional analysis.
Really, the title of this should be "Optimizing build performance - preventing redundant builds".
I first discovered this issue by watching the logging in calls to isAffected() and my validator, but the real issue is that, for my DSL, a single save is calling the builder a number of times.
I have a custom version of
XtextBuilder.doBuild(ToBeBuilt toBeBuilt, IProgressMonitor monitor, BuildType type)
After a save in which I've made changes to multiple language blocks in only a single resource file, the first call to this method receives a toBeBuilt with that single resource in toBeBuilt.toBeUpdated.
After that build completes, I get a seemingly random number of additional calls to XtextBuilder.doBuild(). In each of these calls, toBeUpdated is empty (no entries in toBeUpdated like the first time). However, following the call to the superclass, XtextBuilder's queuedBuildData member DOES have entries in its deltas. This is why the build proceeds. These deltas remain the same to ever subsequent call to doBuild, which basically feels like its churning.
I don't know why its called repeatedly. I'm going to try implementing a workaround where I prevent these seemingly redundant builds from getting passed to XtextBuilder, though that may obviously break things.
I am unfortunately unable to share this project as it's proprietary codebase, but I will try to replicate with a Hello World language at some point in the future.
If anyone has an idea of why this might be happening, please let me know. In the meantime, I'll try the workaround where I prevent these extra builds and see what happens. It occurs to me that these builds may be necessary to build the Java classes being generated by my Xtext DSL. I'm unclear on whether all code generation plus Java building is supposed to occur in a single call to XtextBuilder.doBuild().
|
|
| | |
| Re: Optimizing build performance - observing redundant calls to isAffected and validation [message #1758710 is a reply to message #1758709] |
Fri, 31 March 2017 20:07 |
Larry LeBron
Messages: 124
Registered: October 2015 |
Senior Member |
|
|
Quote:would be interesting why queued build data does not get emptied and which entries it has. thus it would be really interesting to understand what happens.
I agree. queuedBuildData is populated with this list of deltas and then the list doesn't change over the series of redundant builds.
Here's an example list of queuedBuildData deltas from one save. These all correspond to Java classes which are constructed from the language blocks I altered before the save.
[ChangedResourceDescriptionDelta for java:/Objects/assertions._testHierarchicalCreateTestWME old :true,new :false,
ChangedResourceDescriptionDelta for java:/Objects/rules._testAssertionHierarchical old :true,new :false,
ChangedResourceDescriptionDelta for java:/Objects/rules._testTestExpression old :true,new :false,
ChangedResourceDescriptionDelta for java:/Objects/testExpressions._bindTestWMEHierarchical old :true,new :false,
UnconfirmedStructuralChangesDelta for java:/Objects/assertions._testCreateTestWME old :true,new :true,
UnconfirmedStructuralChangesDelta for java:/Objects/behaviors._testClauseBlocksWithRuleMemories_2282634343 old :true,new :true,
UnconfirmedStructuralChangesDelta for java:/Objects/rules._testHierarchicalClauseBlocksWithMemoryArguments old :true,new :true,
UnconfirmedStructuralChangesDelta for java:/Objects/rules._testHierarchicalClauseBlocksWithMemoryArguments old :true,new :true,
UnconfirmedStructuralChangesDelta for java:/Objects/testExpressions._testFindRuleMemWME old :true,new :true,
UnconfirmedStructuralChangesDelta for java:/Objects/testExpressions._testHierarchicalFindFlaggedTestWME old :true,new :true]
Quote:at least 2 calls are expected if you use xbase (which i assume)
but the second one should no have any effect cause nothing to be built
Great to know, thanks. Yes, I'm using xbase. For my workaround, I may just set a flag after the "real" build completes, ignoring any subsequent builds. I'll let you know what happens.
|
|
| | |
| Re: Optimizing build performance - observing redundant calls to isAffected and validation [message #1758864 is a reply to message #1758713] |
Mon, 03 April 2017 22:12 |
Larry LeBron
Messages: 124
Registered: October 2015 |
Senior Member |
|
|
Ok, I have attempted and failed to replicate this with the DomainModel example. I've only made a minor alteration to the DomainModel example to try
to trigger this so it's possible that I just need to add something else to the example to make this behavior occur.
More likely is that something is wrong with my DSL implementation which is causing the behavior.
A little more insight from my new hours of tracing/debugging. Any additional help is much appreciated!
At the end of the first doBuild(), during the call to Workspace.checkpoint(), I see various java deltas get queued (via the broadcastChanges() pipeline).
I see this behavior in DomainModel as well, after certain changes.
Then, during the second build, these deltas get cleared during the call to QueuedBuildData.getAndRemovePendingDeltas().
In DomainModel, this ends the process, as no further deltas are created during Workspace.checkpoint().
In my language, for some reason, the same deltas get created AGAIN during Workspace.checkpoint().
I don't know why.
Any advice is certainly appreciated. I don't see any difference in the generated Java files from build to build.
|
|
| |
Goto Forum:
Current Time: Thu Apr 25 00:46:26 GMT 2024
Powered by FUDForum. Page generated in 0.05315 seconds |
] 
Search
Help
Register
Login
Home
