NormalModule.needRebuild cache calculations seem to be wrong for filesystems that don't support millisecond precision mtimes

[timmfin]

I was writing some integrations tests for broccoli-webpack-cached (trying to test that broccoli and webpack caching were working well together) and I was getting pretty unexpected, seemingly non-deterministic behavior. That lead me to digging into how Webpack caches things, namely how:

• NormalModule saves a buildTimestamp every time a file is built
• At the start of a new compile, Webpack gathers the mtimes from the filesystem for of every file in the dependency tree via CachePlugin
• And then during the next compile, compares the new mtime against the previously saved buildTimestamp for each file in needsRebuilt

That all makes sense, but the problem I see is that buildTimestamp is saved with millisecond-level precision. However, many filesystems out there (in my case, HFS on OSX) only support second-level precision. So this can happen:

• A compile starts, let's say at at 13:50:00 and 100ms (hour, min, second, and ms). That is saved to this.buildTimestamp.
• The compile ends, the file is modified immediately at 13:50:00 and 500ms. But the timestamp saved in the compiler.fileTimestamps object has no millisecond precision, so is only 13:50:00 and 0ms
• Another compile is kicked off soon after and checks if that file needs to be rebuilt. It compares to see if the new filesystem timestamp (13:50:00 and 0ms) is >= the previous buildTimestamp (13:50:00 and 500ms) and decides there has not been a file modification. Even though there definitely was a change to the file, it just happened within the same second and was ignored.

I verified this problem goes away when I force NormalModule to truncate milliseconds from saved the buildTimestamp, like so:

this.buildTimestamp = Math.floor(new Date().getTime() / 1000) * 1000;

But that likely isn't a good change. Ideally, I think that truncation would only happen if we can detect that the input filesystem only has second-level precision (but I didn't look deep how hard/easy that is).

I realize that I am much more likely to run into this issue when writing test code, and that is pretty different than a typical local dev server/watch/build script use-case. But I gotta think that this bug even rears its head in normal scenarios from time to time... well that is unless I've missed something.

ps: Above Webpack github links are to 1.x not 2.x-beta source.

pps: Node didn't always, but now does support millisecond precision for filesystems that support it.

[sokra]

This is pretty critical...

[sokra]

okey, I tried to fix it... but unsure if it's working correctly. Could you run your test agains the webpack master branch with updated watchpack dependency.

[timmfin]

Awesome, thanks.

To test I first backported your fix on top of v1.12.13, since there were several other things I'd need to change to get on webpack 2.x.

After that, things were almost working, except for a couple small things. I needed this this fix to ensure the timestamps were actual timestamps and summed into ints rather than a concatenated string.

And also, I needed to make sure that the timestamp adjustment happened after the async.forEach loop was finished.

After that tiny fix, things are golden 😸. Though I thought I could make the FS_ACCURENCY heuristic a bit better:

Tweak calculation of FS_ACCURENCY

Before this accuracy detection code would end up leaving FS_ACCURENCY equal to 10000 or 2000 on my machine (depending on whether the time stamp was something like 1455197568000 or 1455197569000). Which was pretty far away from the actual precision of one second… and concerning to me if that would make us cache too few things.

So my attempt here was to assume that FS accuracy was always an order of magnitude—1, 10, 100, or 1000 milliseconds—and be a little more aggressive to set the FS_ACCURENCY lower. For example, in the new code, any time a timestamp is seen with 3 trailing zeros (mtime % 10000), I assume that the precision is 1000ms.

Those changes look good to you? Let me know if you'd like to me make an actual PR.

[timmfin]

@sokra, I continued to run into more issues†, so I tried a different approach. Instead of accounting for filesystem accuracy, I tried to instead improve webpack to only refer to and compare actual file mtimes and content hashes‡. I spiked on that, with a couple tests to confirm, over in my fork's mtime-for-caching branch: v1.12.13...timmfin:mtime-for-caching (note it is on Webpack 1.x and also requires these webpack-core changes.

Additionally, to more concretely illustrate this issue (and another I found with CachePlugin), I created a webpack-cache-issues example repo with scripts to replicate the cache issues.

Note, my proposed code changes are far from perfect. Not only do I not have a full understanding of the whole Webpack code base (for example, are NormalModules the only thing I need to worry about?), I also ended up needing to make the needRebuild function async and refactor some core methods. And I'm reading the file from the inputFileSystem in two separate spots. So consider my code a prototype, but not recommendation of the exact implementation. Fortunately, I do have four new tests to test these issues and I've made sure my prototype passes the rest of the test suite. Plus, I'd be very glad to work on this more given some pointers and recommendations.

†: The other issue I was running into was that Webpack's previous caching logic (in particular, the logic when directly using the Webpack node API) assumed that the there was little-to-no time elapsed between when he original file modification occurs and when Webpack starts to build the file. Since the buildTimestamp is merely a new Date it can be problematic to compare it to the file's mtime. Because if Webpack doesn't actually start to build (and save a new buildTimestamp) immediately after the file is modified, another modification could sneak in and never get built.

Here's one (but not the only) example of how this goes wrong, even if the filesystem has millisecond-level precision:

1. I run broccoli server to start my build (let's say it started at 12:00pm and 0 seconds)
2. Various things happen, maybe taking a few seconds to do other broccoli build tasks.
3. (Sometime during this build, I modify X.js again—new mtime of 12:00pm and 2 seconds—but since the broccoli server/watcher is blocking, that change only queues up another build for when the current one finishes.)
4. Then my Brocfile.js delegates to the Webpack compiler (via broccoli-webpack-cached)
5. A new buildTimestamp is created for X.js (let's say at 12:00pm and 5 seconds) and Webpack builds against the original content (aka, those modifications made at 12:00pm and 2 seconds were not passed on by broccoli yet)
6. The Webpack compile finishes, and then the broccoli build finishes.
7. Broccoli kicks off the queued rebuild from X.js's earlier change.
8. Broccoli again does other build steps, which may take a few seconds before getting to the Webpack step.
9. The Webpack compile is kicked off and the CachePlugin runs before the compile, saving the mtime from X.js for later use (it saves 12:00pm and 2 seconds)
10. Webpack then sees if X.js needs to rebuild, and to do so compares the files's mtime, 12:00pm and 2 seconds, and the buildTimestamp, which was set to 12:00pm and 5 seconds. Since the buildTimestamp is greater than that saved mtime, needRebuild returns false. Which is incorrect because the file has been modified.

‡: The main reason why a file mtime is not sufficient for a needRebuild check, is because when the filesystem only has second-level precision you can pretty easily modify & build a file multiple times in the same second. So without anything else, needRuild has to return newMtime >= oldTime—in other words if the newMtime == oldMime, you have to assume that there might be a change. When you check the file's content hashes too (only if the newMtime >= oldMtime) you can be sure that you are not unnecessarily rebuilding file. (I created these tests to check for this sort of unnecessary rebuilding)

[sokra]

Thanks for the testcases. I added your test case and also added my own tests to the webpack test suite. But they pass without any change to the code (on my computer and on travis). (master branch)

So either this was already fixed, or is something specify to your platform.

I want to note here that while developing watchpack I already considered file system accurency. I tries to detect accurency automatically and fires more event if it is unsure if a change could have occured.

Could you run the webpack tests on your computer to check if this is a platform specific issue? (you need to npm link webpack into webpack, see package.json scripts for the CI)

[timmfin]

K, here is an example of those master tests failing on my macbook pro (I think that one of these problems is specific to filesystems with second level precision which is very often/always the case on macs these days). Note, I did a fresh, separate clone and clean npm install:

tfinley at BOSMM2N693QG3QD in ~/src/temp/webpack-master on master
± mocha --harmony --full-trace --check-leaks test/Compiler-caching.test.js


  Compiler (caching)
    ✓ should cache single file (with manual 1s wait)  (1171ms)
    ✓ should cache single file (even with no timeout)  (1123ms)
    1) should only build when modified (with manual 1s wait)
    2) should only build when modified (even with no timeout)


  2 passing (2s)
  2 failing

  1) Compiler (caching) should only build when modified (with manual 1s wait):

      Uncaught AssertionError: a.js should have been built
      + expected - actual

      -false
      +true

      at Assertion.fail (/Users/tfinley/src/temp/webpack-master/node_modules/should/lib/assertion.js:92:17)
      at Assertion.Object.defineProperty.value (/Users/tfinley/src/temp/webpack-master/node_modules/should/lib/assertion.js:164:19)
      at /Users/tfinley/src/temp/webpack-master/test/Compiler-caching.test.js:242:39
      at /Users/tfinley/src/temp/webpack-master/test/Compiler-caching.test.js:63:5
      at Compiler.<anonymous> (/Users/tfinley/src/temp/webpack-master/lib/Compiler.js:224:14)
      ...

  2) Compiler (caching) should only build when modified (even with no timeout):

      Uncaught AssertionError: a.js should have been built
      + expected - actual

      -false
      +true

      at Assertion.fail (/Users/tfinley/src/temp/webpack-master/node_modules/should/lib/assertion.js:92:17)
      at Assertion.Object.defineProperty.value (/Users/tfinley/src/temp/webpack-master/node_modules/should/lib/assertion.js:164:19)
      at /Users/tfinley/src/temp/webpack-master/test/Compiler-caching.test.js:284:39
      at /Users/tfinley/src/temp/webpack-master/test/Compiler-caching.test.js:63:5
      at Compiler.<anonymous> (/Users/tfinley/src/temp/webpack-master/lib/Compiler.js:224:14)
      ...

[timmfin]

Also, a couple other things:

• Do you follow my logic at all regarding the issue with using webpack via the API instead of the cli tools? I very well may be missing something, but one of the problems I've noticed is that a module's buildTimestamp can become "disconnected" from the actual file modification time when webpack is merely a part of an existing build toolchain (and not actually doing the filesystem watching itself).
• Did you take a peek at the separate test scripts I made in the webpack-cache-issues repo? There are a little different than the unit tests in my fork (which I think you based your new master tests off of).

Thanks again for looking into this. And @sokra please do not hesitate to let me know how I and my team at HubSpot can help Webpack out! We are incredibly appreciative of all your efforts, and want to do our part to help push community/project forward.

[sokra]

Ok I was able to reproduce the caching issue by formating a usb stick with FAT32 (2s fs). I also enabled osx build on travis (seem to be new 👍 ), which also shows this issue.

Now investigating.

---

If using Compiler.run instead of Compiler.watch, webpack will read timestamps of all files of the last build before starting the build to determine what can be reused. When watching webpack get these timestamps from the watcher, so the build is faster.

[timmfin]

Nice. I'm going to go ahead and try and get travis to build my webpack-cache-issues repo too.

[sokra]

ok I fixed some issues (purge before cache, typos in CachePlugin).

Some stuff was expected to fail (module rebuilds more often on inaccurate file system, because we rebuild if we are unsure if the file was changed).

Some stuff is still not working (2 watchpack tests fail, but I need to grab a Mac to fix it (don't own one)).

The webpack tests now pass on OSX too and CI runs on OXS too.

[bebraw]

@timmfin Can you still see this issue?

[timmfin]

I'm no longer seeing this specific issue. But that's because we (HubSpot internal build tools) have moved away from a broccoli-based build that calls webpack and are using the webpack cli and/or dev middleware directly.

So while this is not specifically an issue for me anymore I'm pretty sure that there is still a core problem with webpack if you are manually starting a compilation via the API (when there is a significant delay between the file's modification time and when some build code manually kicks off a compiler.run(...)). And I don't think there is a good way to solve that other than tracking file content hashes for invalidation (which I tried to implement in a fork).

I leave it up to the maintainers if this issue should be closed or not. Even though I do think there is a problem, I don't know how many people are dealing with that case. And I certainly won't be offended, I can't offer up as much time trying to debug/validate an issue that isn't pressing for me anymore.

ps: Though, I'm still often running into awkwardness with second-level filesystem precision. However I'm pretty sure that is illustrated and well described by this watchpack issue (this comment in particular).

[sokra]

see watchpack issue