Unnecessary recompilations debugging

[pacak]

We have a somewhat complicated build system and every once in a while it starts recompiling stuff that wasn't changed. I'm trying to use shakeVerbosity = Diagnostic,, shakeChange = ChangeModtimeAndDigest and getting this:

% Chunk 602 [len 64] 03005b020000160000007372632f5072656c7564652f4f727068616e732e68730c00000059b441a6ad020000aeae9be5010000000100000014471f3900000000 Id 603 = (src/Prelude/Orphans.hs,Loaded (Result {result = "Y\180A\166\173\STX\NUL\NUL\174\174\155\229", built = Step 1, changed = Step 1, depends = [], execution = 1.51899e-4, traces = []}))
% Loaded -> Waiting, src/Prelude/Orphans.hs
% Waiting -> Ready, src/Prelude/Orphans.hs
% result src/Prelude/Orphans.hs = (Just File {mod=0xA641B457,size=0x2AB,digest=0xE59BAEAC}) (changed)

Later build system will try to recompile this file.

(changed) here get's printed by this code: https://github.com/ndmitchell/shake/blob/master/src/Development/Shake/Internal/Core/Database.hs#L280

where it compares build r (Step 1) with changed r (also Step 1), but the problem is that current step is Step 33 (34, 35, ...) and file wasn't changed at all.

Is it just a cosmetic bug?

[ndmitchell]

Thanks for the report. A little bit more information required to figure out exactly what is going on - I'm guessing src/Prelude/Orphans.hs is a source file? Which version of Shake are you using - is it HEAD? If you are seeing recompilations this seems like a useful trace, and is probably either the ultimate source or a bug in the tracing. The step thing looks fine, but with the answers above I can peer into the other details.

[pacak]

It is latest version on hackage. But the same with HEAD. Prelude/Orphans.hs is indeed a plain file. Full trace is about 1.5Mb and you might want two - clean compilation + one that forces repeated one so I decided not to post it here but rather to figure out what is going on. If you want to look at the trace yourself (that also contains duplicated dependencies bug) I'll be able to send it to you in 2-3 hours. On Mar 24, 2017 3:29 PM, "Neil Mitchell" <notifications@github.com> wrote: Thanks for the report. A little bit more information required to figure out exactly what is going on - I'm guessing src/Prelude/Orphans.hs is a source file? Which version of Shake are you using - is it HEAD? If you are seeing recompilations this seems like a useful trace, and is probably either the ultimate source or a bug in the tracing. The step thing looks fine, but with the answers above I can peer into the other details. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#519 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAECozVHMXDj37K0NffFZiMRY0ZJdAxqks5ro3DigaJpZM4Mnrg3> .

[ndmitchell]

I think I've got enough to investigate, and the trace format also looks like it has regressed relative to what I used to have. I'll take a look this weekend and get back to you.

[pacak]

Please let me know if you need any more info. I'm going to post one more bug soon - case with not enough recompilation - shake database ends up having the same file recorded twice, one with dependencies and one without them and asking it to recompile it even when having dependencies changed results in no-op.

…

On Mar 24, 2017 3:52 PM, "Neil Mitchell" ***@***.***> wrote: I think I've got enough to investigate, and the trace format also looks like it has regressed relative to what I used to have. I'll take a look this weekend and get back to you. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#519 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAECo3l9_AcVRnNSfJ51U7DU3mY2k4yfks5ro3YpgaJpZM4Mnrg3> .

[ndmitchell]

Thanks for the reports. They are most appreciated!

[pacak]

That's the case with insufficient recompilation. I wasn't able to reproduce this info myself and that's as much info as I have:

% Chunk 2080 [len 73] 0300e20600001f0000005f6d6b2f372e31302e312e322f6d61696e2f4f322f6578652f7472616465720c000000ff325087c29646093429a642200000001f0000000969a83f00000000 Id 1762 = (_mk/7.10.1.2/main/O2/exe/trader,Loaded (Result {result = "\255&2P\135\194\150F\t4)\166B", built = Step 32, changed = Step 31, depends = [], execution = 1.3157054, traces = []}))

500006405000065050000660500006f070000670500007007000071070000720700006805000069050000730700006a0500006b0500006c0500006d0500006e0500006f050000040000008206000004000000d40700000b00000098739043d0729543676863 Id 1762 = (_mk/7.10.1.2/main/O2/exe/trader,Loaded (Result {result = "\255&2P\135\194\150F\t4)\166B", built = Step 31, changed = Step 31, depends = [[Id 9],[Id 1114], ...a lot of stuff here... [Id 1666],[Id 2004]], execution = 11.584794, traces = [Trace "ghc" 288.90308 298.89697]}))

Does it makes sense to enforce an invariant of having at most one unique set of dependencies for every target?

[ndmitchell]

Whether dependencies are duplicate or not should make little difference here (you might want to for efficiency, but not correctness). For the insufficient recompilation above, the file exe/trader has no dependencies, so will never rebuild. Any chance you had a Shake script with a bug in it that failed to record changes, and then fixed the Shake script, but the Shake output remains stale? Do note that Shake does not recompile just because you change the build system itself.

[pacak]

We do use runhaskell and it sets shakeVersion to the last commit hash that touched the build system so if there are any changes to it - all the things should get recompiled. The problem is I can't think of any scenarios where exe/trader will have no dependencies at all.

building it looks like this:

    let buildExec :: [FilePath] -> String -> ExecInfo -> Action ()
        buildExec objectFiles source ExecInfo{..} = do
            need objectFiles

            let dir = tempDir </> "link" </> execName
            liftIO $ IO.createDirectoryIfMissing True dir

            writeFile' (dir </> "main.hs") source

            () <- cmd "ghc -c" [dir </> "main.hs"] (Traced "")
                (ghcBuildOptions buildOptions)
                (ghcBuildDirOptions dir)
                ["-i" ++ traderObjectFileDir buildOptions]
                ["-o", dir </> "main.o"]
            packages <- readFileLines allPackagesFile
            linkOpts <- readFileLines $ linkOptionsFile buildOptions execName
            let packageOptions = do
                    pkg <- packages
                    ["-package", pkg]
            () <- cmd "ghc"
                linkOpts
                [dir </> "main.o"]
                ["-o", executableFile buildOptions execName]
                packageOptions objectFiles
            liftIO $ putStrLn $ "Done linking " ++ execName

and even if objectFiles are [] then allPackagesFile and linkOptionsFile buildOptions execName should be added as dependencies.

[pacak]

So there are 3 files. It runs slightly modified git HEAD version:

1.txt - with _mk folder removed - that folder contains all the temporary files and shake database. So it's a clean build.

2.txt - I added an empty line to Tools/Deploy.hs - this file indirectly imports Prelude.Orphans, Prelude/Orphans.hs shouldn't be affected in any way but it and a bunch of dependencies got recompiled.

3.txt - I added one more empty line to Tools/Deploy.hs - that resulted in the same amount of recompilation as in 2.txt plus a strange build error that I can't explain at all.

At the moment I'm trying to debug why Prelude/Orphans.hs got recompiled.

diff --git a/src/Development/Shake/Internal/Core/Database.hs b/src/Development/Shake/Internal/Core/Database.hs
index d4479bb9..ada97283 100644
--- a/src/Development/Shake/Internal/Core/Database.hs
+++ b/src/Development/Shake/Internal/Core/Database.hs
@@ -277,7 +277,7 @@ build pool Database{..} BuildKey{..} stack ks continue =
                         Right (write, bs, r) -> do
                             diagnostic $ return $
                                 "result " ++ showBracket k ++ " = "++ showBracket (result r) ++
-                                " " ++ (if built r == changed r then "(changed)" else "(unchanged)")
+                                " " ++ (if built r == changed r then "(changed)" else "(unchanged)") ++ show (built r, changed r, step)
                             when write $ journal i k r{result=bs}
                         Left _ -> do
                             diagnostic $ return $ "result " ++ showBracket k ++ " = error"

In the middle there's a bit of non-standard output looking like this -

("Report.Basic",["_mk/7.10.1.2/main/O2/obj/Report/Basic.o"])

that's produced by makefile' rule, you can probably ignore it.
logs.zip

[ndmitchell]

Thanks. It will probably be Wednesday evening before I can peer through these in the necessary detail.