SCons
--debug=explain wrong with MD5-timestamp
Describe the bug --debug=explain gives wrong information when using MD5-timestamp decider.
Required information
- Link to SCons Users thread discussing your issue
- Version of SCons: 3.1.2
- Version of Python: 2.7 and 3.6
- Which python distribution: python.org
- How you installed SCons: pip install scons
- What Platform are you on: Windows 7
I observe a strange behavior of --debug=explain, when the MD5-timestamp decider is used. When I change a single file, --debug=explain marks all the "sibling" dependencies as "changed". It does not affect the build itself though, as expected only the necessary files are recompiled.
Consider this SConstruct:
Decider('MD5-timestamp')
Program('hello', 'hello.c')
And the hello.c:
int main(int argc, char** argv) {
return 0;
}
If I run scons, modify hello.c, and run scons -Q --debug=explain, I get:
scons: rebuilding `hello.obj' because:
`hello.c' changed
`C:\Program Files (x86)\Microsoft Visual Studio\2017\BuildTools\VC\Tools\MSVC\14.16.27023\bin\HostX64\x64\cl.EXE' changed
cl /Fohello.obj /c hello.c /nologo
hello.c
scons: rebuilding `hello.exe' because:
`hello.obj' changed
`C:\Program Files (x86)\Microsoft Visual Studio\2017\BuildTools\VC\Tools\MSVC\14.16.27023\bin\HostX64\x64\link.EXE' changed
link /nologo /OUT:hello.exe hello.obj
Here, cl.exe is marked as changed. But if there was a .h that the .c included, it would be marked as changed too. Only MD5-timestamp causes this problem, the other deciders work correctly.
Issue is still reproducible on current master (183ced59ecbdf2fc5b7c91324c70ab591bb5d042).
Following modification to test suite:
diff --git a/test/explain/basic.py b/test/explain/basic.py
index 6d41496fd..e37b5be44 100644
--- a/test/explain/basic.py
+++ b/test/explain/basic.py
@@ -99,6 +99,7 @@ cat = Builder(action = [[r'%(python)s', r'%(cat_py)s', '$TARGET', '$SOURCES']])
one_cat = Builder( action = [[r'%(python)s', r'%(cat_py)s', '$TARGET', '${SOURCES[0]}']])
env = Environment(tools=[])
+env.Decider('MD5-timestamp')
env.Append(BUILDERS = {'Cat':cat, 'OneCat':one_cat},
SCANNERS = kscan)
env.PrependENVPath('PATHEXT', '.PY')
allows to observe this behavior with:
python3 runtest.py test/explain/basic.py
which among others differences shows python3 as changed:
> `/usr/bin/python3' changed
Actually it shows ALL file dependencies as changed during execution with --debug=explain. This issue hit me when order of arguments was changing.
It seems to be somehow connected with passing None for parameter node in a call to:
def changed_timestamp_then_content(self, target, prev_ni, node=None):
I don't know scons internals enough to know why it cause problems as this case seems to be handled.
Actually value of this parameters seems to be used only in MD5-timestamp decider so maybe it should be passed properly during processing output for --debug=explain.
@bdbaddog would you be able to look at it? It seems it could be introduced by you in 8c588f8baf76c0cd491e0589e9d2122787ef2512
If you change the command line in any way, including changing the order of arguments SCons should rebuild. Unless those parts of the command line which are changing are wrapped in $( $)'s
This issue hit me when order of arguments was changing.
So that rebuild might be valid, though as has been discussed many times --debug=explain is not perfect.
I'll see if I can take a look in the next week or so.
I've mentioned elsewhere, just for recording in this issue: it's "unfortunate" that if the relevant decider decides a rebuild is needed, than the explain logic fires and it tries to decide why - repeating the work. That leads to the potential for inaccuracies in the explaner, since it doesn't have identical code. I believe we've concluded it was done that way for performance reasons, so that unless you specifically asked for explain, you don't pay any of the cost.
If you change the command line in any way, including changing the order of arguments SCons should rebuild.
Yes, I know and I did not mean to question it in any way. Sorry if I wasn't precise.
This issue hit me when order of arguments was changing.
So that rebuild might be valid,
Yes, it was.
though as has been discussed many times --debug=explain is not perfect.
I wasn't aware of it.
In my case I had a link command with few hundreds of input files and receiving information that all of them are changed did not help at all. And moreover there was no information about command being different but it's another problem. That's why I considered it serious and tried to check if it is reproducible in master and after confirmation provided easy to reproduce testcase. Fixing it currently seem to be too much for me.
I'll see if I can take a look in the next week or so.
Great. Thank you.
Here's some trace information: when explain() runs, it ends up using the decider in effect to answer whether a file changed, once it's dealt with dependencies no longer present or newly present. If the decider specifically is the content-timestamp one, it doesn't make good choices for implicit dependencies. A condensed debugger session kind of shows what's happening:
--Call--
> .../SCons/Node/FS.py(3442)changed_timestamp_then_content()
-> def changed_timestamp_then_content(self, target, prev_ni, node=None) -> bool:
(Pdb) a
self = <SCons.Node.FS.File object at 0x5589e45a18d0>
target = <SCons.Node.FS.File object at 0x5589e46dd180>
prev_ni = <SCons.Node.FS.FileNodeInfo object at 0x7fd36fb58be0>
node = None
(Pdb) str(self), str(target)
('/bin/echo', 'foo')
# as node is None, it is set to self - if passed, it's expected to be a repository node
# Backtrace (abridged) here: <<<
-> explanation = self.out_of_date[0].explain()
.../SCons/Node/__init__.py(1679)explain()
-> changed = _decider_map[k.changed_since_last_build](k, self, osig[k])
.../SCons/Node/__init__.py(297)decide_source()
-> return target.get_build_env().decide_source(node, target, prev_ni, repo_node)
.../SCons/Environment.py(1670)_changed_timestamp_then_content()
-> return dependency.changed_timestamp_then_content(target, prev_ni, repo_node)
> .../SCons/Node/FS.py(3442)changed_timestamp_then_content()
-> def changed_timestamp_then_content(self, target, prev_ni, node=None) -> bool:
# >>>
-> rebuilt = False
-> try:
-> dependency_map = bi.dependency_map
AttributeError: 'FileBuildInfo' object has no attribute 'dependency_map'
-> except AttributeError as e:
-> dependency_map = self._build_dependency_map(bi)
-> rebuilt = True
(Pdb) p dependency_map
{}
-> if len(dependency_map) == 0:
-> self.get_csig()
-> return True
# At this point, the True percolates back the call chain to:
-> changed = _decider_map[k.changed_since_last_build](k, self, osig[k])
# so:
-> if changed:
-> lines.append("`%s' changed\n" % stringify(k))
Not shown was the code in _build_dependency_map, which returns an empty dict based on this code:
# For an "empty" binfo, properties like bsources
# do not exist: check this to avoid exception.
if (len(binfo.bsourcesigs) + len(binfo.bdependsigs) +
len(binfo.bimplicitsigs)) == 0:
return {}
It seems like the issue is that the implicit depends should not be passed through this sequence, although if the decider is the default "content" decider, there's no issue. Not sure we have information on what happens if other deciders are used, or where it is things should be adjusted. In the regular code flow using the content-timestamp decider, changed_timestamp_then_content does get called for /bin/echo, but in a way that it decides it hasn't changed; once the overall decision (rebuild) is made, explain is called and when it checks changed_timestamp_then_content, the answer is different. explain has this sequence, again abridged:
old = old.binfo
old_bkids = old.bsources + old.bdepends + old.bimplicit
old_bkidsigs = old.bsourcesigs + old.bdependsigs + old.bimplicitsigs
new = self.get_binfo()
new_bkids = new.bsources + new.bdepends + new.bimplicit
new_bkidsigs = new.bsourcesigs + new.bdependsigs + new.bimplicitsigs
# ... a bunch skipped
for k in new_bkids:
if k not in old_bkids:
lines.append("`%s' is a new dependency\n" % stringify(k))
else:
changed = _decider_map[k.changed_since_last_build](k, self, osig[k])
# changed_since_last_build is 4 here, which is decide_source