[SERVER-33111] SCons split_dwarf tool can cause spurious object file rebuilds Created: 03/Feb/18 Updated: 29/Oct/23 Resolved: 20/Apr/19 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Build |
| Affects Version/s: | None |
| Fix Version/s: | 4.1.11 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Andrew Morrow (Inactive) | Assignee: | Andrew Morrow (Inactive) |
| Resolution: | Fixed | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||||||||||
| Operating System: | Linux | ||||||||||||||||||||
| Steps To Reproduce: | On a Linux machine:
The second build will rebuild files, but it should not:
|
||||||||||||||||||||
| Sprint: | Dev Tools 2019-01-14, Dev Tools 2019-01-28, Dev Tools 2019-02-11, Dev Tools 2019-03-25, Dev Tools 2019-04-08, Dev Tools 2019-04-22 | ||||||||||||||||||||
| Participants: | |||||||||||||||||||||
| Description |
|
When the split_dwarf tools is enabled, we sometimes observe that some object files get (identically) rebuilt on the second build, though not on subsequent builds. We should figure out why, and fix it. |
| Comments |
| Comment by Githook User [ 20/Apr/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {'name': 'William Deegan', 'username': 'bdbaddog', 'email': 'bill@baddogconsulting.com'}Message: The issue was that builders with more than one target (potentially only when that 2nd or higher target is added in the emitter were not getting their implicit list cleared after a generated source is rebuilt. Thus leading to the implicit list order being incorrect when written to sconsign leaded to spurious rebuilds on second build Closes #1307 Signed-off-by: Andrew Morrow <acm@mongodb.com> | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andrew Morrow (Inactive) [ 02/Apr/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
OK, I went ahead and tested the latest. Here is the script I used:
At the time of testing, the indicated branch was checked out to https://github.com/bdbaddog/mongo/commit/71283f1928ab0023b48686de7d77bfd02e208268. First, the great news is that we observed zero spurious rebuilds:
As an extra check, we can see that SCons believed our one named target was up to date in all rebuilds:
We got the following timing results:
I will put these in a table a little later. But the good news is that it looks like the proposed fix definitely resolves the issue. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by bdbaddog#1 [ 28/Mar/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hmm.. Does that mean that MD5-timestamp fix breaks checking if order of dependencies changed? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by bdbaddog#1 [ 10/Feb/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
@Mathew Robinson If I'm understanding your comment about always running MD5, I think you may be slightly misreading the code. The old logic md5's the executor content (not the file content) always. The executor is more or less the action to build the target. So if the action changes it doesn't matter if the files have, it should still be rebuilt.
In the new and old logic if the timestamps hadn't changed we copy the old md5 (from sconsign load) to what will be written when sconsign is written at the end of the run.
The current issue seems to be tied to which File() object is being used. In one run it's the src dir, and the other it's the variantdir's version of it. Since they are not the same python object (via id() check to dig into this), they compare as not equal. Even though they are in reality referring to the same source file (at least for your build as you have duplicate=0).
Initially it looked like there were two File() nodes referring to the same exact file, but that's theory's been proven incorrect.
So now to investigate why each run is getting different File() and why this (seems) to only happen when there are >= 1 additional targets added in the emitter. So the recipe which seems to cause this (at least at this point in the investigation): variantdir(), duplicate=0, emitter adding target, maybe target suffix unknown to consuming builder (linker consuming object files and also being handed the .dwo file), maybe combined with configure context.
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Mathew Robinson (Inactive) [ 28/Jan/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I'm posting my last message from the Slack channel about this issue here for posterity: It seems to me that in the old way of Deciding with the Timestamp-MD5 checker the MD5 check would always run and essentially overwrite the value of the Timestamp check: https://github.com/SCons/scons/blob/aa8c3a4fe2c22d95f23b0ab52cd483b55c370ae6/src/engine/SCons/Node/__init__.py#L1414 Now in the new way in 3.0.4 we return early if the timestamps match meaning we don't run the MD5 decider: I think this means there is a bug in the MD5 decider since we only see the rebuilds when explicitly using MD5 only now and would explain why we don't see it with the Timestamp-MD5 decider | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andrew Morrow (Inactive) [ 25/Jan/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
As expected, running the above script checked out to 90cd49725f41354509dece813343c62e6ee9f533, which reverts to SCons 2.5.1, gets us the following results:
In other words, we have the following matrix:
So it appears that the changes made in SCons 3.0.4 to address | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andrew Morrow (Inactive) [ 25/Jan/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Some really interesting results after the SCons 3.0.4 upgrade yesterday. It appears that this bug no longer reproduces when using the MD5-Timestamp decider. However, it does reproduce when using the MD5 decider. I used the following script to test this against the MongoDB tree checked out to 5fb83f78b6740dbe3a771735e3629fec2a854a1d.
A quick grep shows us which builds had spurious recompiles:
The conclusion is that:
This strongly suggests that the fix for I am going to re-test this with the commit right before the SCons 3.0.4 upgrade where we are still running SCons 2.5.1. My expectation is that we will see spurious rebuilds for all "split" cases, confirming that the fix for | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Mathew Robinson (Inactive) [ 24/Jan/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bdbaddog You're correct I spoke to acm about this yesterday and I'm going to try and repro with the actual object files first then worry about the .so's later. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by bdbaddog#1 [ 24/Jan/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
@Matthew Robinson I don't think you're repro'd if the only rebuilds you are seeing are the .so's. There should be a .dwo for each object file. Andrew's issue (If I understand correctly) is that he's seeing spurious rebuilds of .o's and .dwo's. In your build are you only seeing .so's rebuild? What does the --explain=debug output say as the reason why? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Mathew Robinson (Inactive) [ 23/Jan/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
When I got the spurious rebuilds I found the files which had been rebuilt on r4.1.4 and master with scons 3.0.1: rebuilt.files.scons-3.0.1.master Sorting and de-duping this files I was able to find the common files which were rebuilt: common.rebuilds If I then search my build dir for a matching dwo file I find that 429 of the 430 common rebuilds do not have a dwo file: no.dwo The split_dwarf site tool is adding a dwo file for every object file but we aren't generating a dwo file for every object file. So either we shouldn't be generating a dwo file for every object file, and the site tool should be able to determine that, or we're running an incorrect compiler command that causes certain files to not generate a dwo file. I'm still new enough to split dwarf that I'm not sure at this point if we should be expecting a dwo for every object. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Mathew Robinson (Inactive) [ 23/Jan/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I was able to repro the issue. After full build switch to r4.1.4 and back to master I note that about 400 - 500 files get rebuilt. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andrew Morrow (Inactive) [ 15/Jan/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
mathew.robinson - Handing this off to you; CC bdbaddog, who can assist with investigation and probably write a fix once we have an RCA. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andrew Morrow (Inactive) [ 20/Dec/18 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
mathew.robinson - Could you please attempt the above repro on your local linux system and see if you get spurious rebuilds on the second build? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andrew Morrow (Inactive) [ 15/Nov/18 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bdbaddog and mathew.robinson - Would be interesting to see if you can repro with the above instructions on your local linux systems. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andrew Morrow (Inactive) [ 15/Nov/18 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bdbaddog - Updated this with repro instructions. CC mathew.robinson. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andrew Morrow (Inactive) [ 04/May/18 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
See the comments in |