Always rebuilds on Windows, even without any changes

[mitranim]

Mage version: v1.8.0-11-g5bc3a8a

OS: Windows 10, 10.0.17763, build 17763

Running mage always rebuilds the program, briefly generating a mage_output_file.go. This happens both in the Windows shell environment (PowerShell), and under WSL (Ubuntu 18.04). This happens even if the directory has no other files and an almost-blank magefile.go without any real code. Nothing on my system is touching those files.

Mage does cache the executable files under $env:USERPROFILE\magefile (please excuse the windows-ism), and fails to clean the old ones, which is its own problem beyond this scope of this request. But it does this every single time, causing the command to be slow.

[mitranim]

As an aside, it would be nice if both the temporary Go file and the executables were placed in the OS-supplied temporary directory. This would solve the cleanup issue, and prevent the Go file from flashing in my editor sidebar and triggering file watchers.

[natefinch]

Thanks for the report. What version of Go are you using? The rebuild behavior is based on Go 1.10's rebuild logic, which should be reliable regardless of OS. If you're using something older than 1.10, then mage does its own caching, but that usually results in not rebuilding often enough, rather than too often.

Don't worry about Windows-isms, I developed on Windows for over a decade, and so I try my best not to treat Windows as a second class citizen (which is why I made sure to have CI tests running on Windows via Appveyor).

The idea of putting the temp file in a temp directory is a good one, but unfortunately, that can't work as far as I know. Mage runs go build to make the binary, and you can't compile files in two different directories into one package. And if I move the magefiles, it might screw up imports.

But, if it didn't need to rebuild, then it wouldn't need to regenerate that file.... so let's try to fix that first :)

[mitranim]

Thanks for the answer. My go version output:

go version go1.12.1 windows/amd64

Continuing the aside, I don't see why the executables couldn't be temporary, but there might be gotchas you know that I don't.

[natefinch]

Hmm that version should be fine. Can you run mage -debug -l in the directory with the magefile and output the results here? That may tell us more.

The magefile binaries could be put in the temp directory, and in fact, you can choose to do that yourself by setting MAGEFILE_CACHE. As for whether to default them there.... I see plusses and minuses both ways. Maybe if I had thought of it when I first built mage, I would have done that. I hesitate to change it now, though.

[mitranim]

Deleted cached executables, made an empty directory with a practically-empty magefile.go. Running mage -debug -l produces the following:

DEBUG: 19:45:41.801484 getting all non-mage files in .
DEBUG: 19:45:41.865386 found non-mage files
DEBUG: 19:45:41.865386 getting all files plus mage files
DEBUG: 19:45:41.930007 time to scan for Magefiles: 128.5235ms
DEBUG: 19:45:41.930007 found magefiles: magefile.go
DEBUG: 19:45:41.960103 output exe is  C:\Users\mitranim\magefile\f2049adc9917238181b6f38b0977f5cbdb704ca3.exe
DEBUG: 19:45:41.991128 build cache exists, will ignore any compiled binary
DEBUG: 19:45:41.991128 parsing files
DEBUG: 19:45:41.991128 time parse Magefiles: 0s
DEBUG: 19:45:41.991128 Creating mainfile at mage_output_file.go
DEBUG: 19:45:41.992096 writing new file at mage_output_file.go
DEBUG: 19:45:41.993126 compiling to C:\Users\mitranim\magefile\f2049adc9917238181b6f38b0977f5cbdb704ca3.exe
DEBUG: 19:45:41.993126 compiling using gocmd: go
DEBUG: 19:45:42.083056 running go build -o C:\Users\mitranim\magefile\f2049adc9917238181b6f38b0977f5cbdb704ca3.exe magefile.go mage_output_file.go
DEBUG: 19:45:43.000159 time to compile Magefile: 914.1082ms
DEBUG: 19:45:43.000159 running binary C:\Users\mitranim\magefile\f2049adc9917238181b6f38b0977f5cbdb704ca3.exe
DEBUG: 19:45:43.000159 running magefile with mage vars:
MAGEFILE_LIST=1
MAGEFILE_DEBUG=1
MAGEFILE_GOCMD=go
Targets:

Second run immediately after:

DEBUG: 19:45:52.281034 getting all non-mage files in .                                                                                                 
DEBUG: 19:45:52.343133 found non-mage files                                                                                                            
DEBUG: 19:45:52.343133 getting all files plus mage files                                                                                               
DEBUG: 19:45:52.408194 time to scan for Magefiles: 127.1602ms                                                                                          
DEBUG: 19:45:52.408194 found magefiles: magefile.go                                                                                                    
DEBUG: 19:45:52.439610 output exe is  C:\Users\mitranim\magefile\f2049adc9917238181b6f38b0977f5cbdb704ca3.exe                                          
DEBUG: 19:45:52.470464 build cache exists, will ignore any compiled binary                                                                             
DEBUG: 19:45:52.470464 parsing files                                                                                                                   
DEBUG: 19:45:52.470464 time parse Magefiles: 0s                                                                                                        
DEBUG: 19:45:52.471267 Creating mainfile at mage_output_file.go                                                                                        
DEBUG: 19:45:52.471267 writing new file at mage_output_file.go                                                                                         
DEBUG: 19:45:52.472234 compiling to C:\Users\mitranim\magefile\f2049adc9917238181b6f38b0977f5cbdb704ca3.exe                                            
DEBUG: 19:45:52.472234 compiling using gocmd: go                                                                                                       
DEBUG: 19:45:52.560193 running go build -o C:\Users\mitranim\magefile\f2049adc9917238181b6f38b0977f5cbdb704ca3.exe magefile.go mage_output_file.go     
DEBUG: 19:45:52.747298 time to compile Magefile: 184.0798ms                                                                                            
DEBUG: 19:45:52.747298 running binary C:\Users\mitranim\magefile\f2049adc9917238181b6f38b0977f5cbdb704ca3.exe                                          
DEBUG: 19:45:52.747298 running magefile with mage vars:                                                                                                
MAGEFILE_LIST=1                                                                                                                                        
MAGEFILE_DEBUG=1                                                                                                                                       
MAGEFILE_GOCMD=go                                                                                                                                      
Targets:                                                                                                                                               

[natefinch]

That second compiled way faster, in only 184ms, compared to the first one's 914ms. That's the built-in go build cache doing the right thing, and not actually rebuilding.

So, i was wrong, I forgot that when we switched to using the go build cache, we always create mage_output_file.go, specifically because we have to run a real go build with all the files, so we can catch any transitive dependencies that might have changed (i.e. if you import a package and change something in that other package, detecting that change is what go build does).

It seems like it's working as intended. The first command ran in about 1.2s, the second command ran in a bit less than a half a second. I think that's about the best we can do... it's kind of a limitation of the fact that mage relies on go build to know if it needs to recompile or not.

[mitranim]

Thanks for the clarification. This makes sense, but is also unfortunate. My actual magefile takes 1.8s to build and 400ms to "rebuild", and this happens when running any task, no matter how trivial. This would be less of a problem under Unix, but on Windows, go build is much slower. My old Makefile-based build only cared about changes in the local source files and reused executables more aggressively, so everything was instant once compiled. I don't have immediate suggestions other than "give me an option", which seems rather weak. Would still appreciate an option though.

On a side note, "how it works" seems to be outdated because it implies immediate executable reuse.

[natefinch]

Ahh yeah, how it works needs some updating. Thanks for pointing that out... I hate having out-of-date docs.

As for giving you an option... that's certainly possible. WIth an environment variable, you could go back to the old way of just running a hash of the local magefiles. It's definitely faster, and avoids running go build at all if the magefiles haven't changed (which might make an even bigger difference on Windows, it sounds like)... but it does present the problem of not automatically rebuilding if a dependency changes.

You might not be the only one who would like that. It's definitely worth thinking about, and since the code is all there, it only requires adding code to check for an environment variable, which is easy and wouldn't clutter things up.... definitely seems doable, and reasonable for environments where go build isn't that fast.

[mitranim]

Sounds good. I'll be happy to test a pre-release version of that. As a side note, remembering all the command options can be hard, and I already have to run mage -v; with even more options, it would be nice to be able to stick them in a local config file.

[natefinch]

You can set an environment variable MAGEFILE_VERBOSE=true to have verbose always on. Most anything I thought someone might want always on, I made available from an environment variable. See https://magefile.org/environment/ for all of them.

What kinds of things would you want in a config file?

[mitranim]

Thanks for the tip. Nice to have the option, though I find it bizarre that Mage suppresses output by default. As for a config file, perhaps it should simply mirror all available CLI flags. This way, the developer doesn't have to think hard, and the user can configure whatever they want, on a project-specific basis, without messing with the system environment.

[mitranim]

Some CLI flag libs let you define a struct type and parse flags into it. The same type could be used for, say, JSON decoding. I like github.com/jessevdk/go-flags, though I'm not suggesting that you include a dependency. I quite appreciate that Mage doesn't pull in megabytes of bloat.

[natefinch]

Mage doesn't suppress all output by default, btw. There's effectively two ways to output - if you use the stdlib log package, that is only displayed if you use the verbose flag. But if you use something like fmt.Printf() then it's always displayed.

I could add a specific non-verbose log value for people to use instead of needing to use fmt directly, that might be useful.

Turning on verbose does print out more information from mage itself, but I didn't want to muddy the output of normal operation with mage's own output.

[mitranim]

Somehow missed the notification for your message.

Are you saying that it suppresses stderr, but not stdout, by default? IMO that's even more bizarre than suppressing everything. Logging to stderr is standard practice, which is why log does that by default.

Definitely 👍 on Mage being silent by default. I just don't see why program logging would have to be victim.

[natefinch]

It doesn't suppress stderr. It sets the log package to use io.Discard by default, and sets it to use stderr when you run with -v. In hindsight, that may have been a mistake. I maybe should have made a separate log instance in one of the mage libraries that turns on and off with -v, and not touch the configuration of the default logger in the log package.

To make that change now would take some very careful consideration, since there's probably a lot of code out there now that assumes log.Printf only shows up with -v. I don't want to break people's CI etc.

[mitranim]

Hmm this explains the build error I got when creating a variable named log with custom logging settings, which is common in my programs. Been meaning to raise an issue about this; the build tool shouldn't mess with my variables. Mage should alias its imports to avoid collisions. Currently in Go, it's not an error to have multiple imports of the same package under different aliases, so Mage wouldn't even have to inspect the existing imports when adding its own.

I'm obviously in favor of breaking any existing build that depends on -v for log logging; I think that behavior is just wrong, but that's my bias talking, since my builds don't depend on it. Stability is nice to have too.

[natefinch]

So, I believe this is fixed using the MAGEFILE_HASHFAST environment variable, which will only rebuild if one of the magefiles changes. This should make running mage much faster on windows. Evidently the go caching mechanism is just not very fast on windows.

Note that this won't rebuild if an imported library changes, in that case you'd need to manually run mage -f to force a rebuild.

[natefinch]

Give that a try and see if it does what you need it to do. (and I'll make a separate issue for the import naming, because that's 100% valid).

[mitranim]

My apologies for super slow responses. Finally back to Windows due to macbook repairs, but by now, I've migrated to Gtg which is Mage-inspired but avoids most of its problems (sorry!), and can be run via Gow. Also back to make for some projects. I'd need to setup a mock project to test this out. Perhaps in the future. Also, perhaps you could see if any ideas in Gtg can be useful for Mage.