Any ideas where this could slow down the build process?

[arunoda]

I got a request saying new version of browserify slowdown the process.
See: kadirahq/meteor-react-layout#32 (comment)

Any ideas?

[sahanDissanayake]

👍

[sahanDissanayake]

https://github.com/arunoda/hello-react-meteor/
here are the logs using the following command

env METEOR_PROFILE=50 meteor run

Older version before upgrading from v 0.5.0 > 0.8.1

=> Started proxy.                             
=> Started MongoDB.                           
|  Selecting package versions                |
| JsImage#load: 306.3
|     other JsImage#load: 305.9
| Select Package Versions: 3962.8
|     Input#loadFromCatalog (sqlite): 3257.9
|     Solver#getAnswer: 670.0
|         new Logic.Solver (MiniSat start-up): 57.5
|         generate constraints: 74.2
|         pre-solve: 168.5
|         minimize conflicts: 180.1
|         minimize total_packages: 59.7
| 
| Input#loadFromCatalog (sqlite): 3257.9
| other JsImage#load: 305.9
| minimize conflicts: 180.1
| pre-solve: 168.5
| generate constraints: 74.2
| minimize total_packages: 59.7
| new Logic.Solver (MiniSat start-up): 57.5
| Total: 4103.9
|  Building the application                  -
| JsImage#load: 667.4
|     other JsImage#load: 666.7
| Rebuild App: 6353.3
|     compiler.compile(the app): 4689.2
|         Isopack#ensurePluginsInitialized: 4653.7
|             JsImage#load: 2423.7
|                 files.exists: 796.1
|                 other JsImage#load: 1627.6
|             other Isopack#ensurePluginsInitialized: 2230.0
|     bundler.bundle..makeClientTarget: 924.3
|         Target#make: 924.0
|             Target#_runCompilerPlugins: 566.8
|                 Isopack#ensurePluginsInitialized: 505.6
|                     JsImage#load: 504.0
|                         other JsImage#load: 494.6
|             Target#_emitResources: 151.1
|                 PackageSourceBatch#getResources: 146.6
|                     PackageSourceBatch#_linkJS: 144.7
|                         files.readFile: 77.9
|                         other PackageSourceBatch#_linkJS: 61.7
|             ClientTarget#minifyCss: 161.0
|     bundler.bundle..makeServerTarget: 242.0
|         Target#make: 241.7
|             Target#_runCompilerPlugins: 60.2
|             Target#_emitResources: 158.9
|                 PackageSourceBatch#getResources: 154.0
|                     PackageSourceBatch#_linkJS: 151.6
|                         files.readFile: 90.7
|                         other PackageSourceBatch#_linkJS: 54.9
|     bundler..writeSiteArchive: 487.5
|         bundler..writeTargetToPath: 394.6
|             ClientTarget#write: 149.7
|                 Builder#write: 50.0
|             ServerTarget#write: 241.2
|                 JsImage#write: 222.1
|                     Builder#write: 130.3
|                     other JsImage#write: 85.0
|         Builder#complete: 84.3
|             files.rm_recursive: 84.1
| 
| other JsImage#load: 2788.9
| other Isopack#ensurePluginsInitialized: 2231.5
| files.exists: 829.4
| files.readFile: 214.3
| ClientTarget#minifyCss: 161.0
| other PackageSourceBatch#_linkJS: 116.5
| files.writeFile: 89.5
| files.rm_recursive: 87.1
| other JsImage#write: 85.0
| Total: 6603.2
=> Started your app.  

After upgrade to upgrading from v 0.5.0 > 0.8.1

=> Started proxy.                             
=> Started MongoDB.                           
|  Selecting package versions                |
| JsImage#load: 286.9
|     other JsImage#load: 286.5
| Select Package Versions: 3953.8
|     Input#loadFromCatalog (sqlite): 3264.2
|     Solver#getAnswer: 655.6
|         new Logic.Solver (MiniSat start-up): 63.2
|         generate constraints: 74.9
|         pre-solve: 166.8
|         minimize conflicts: 168.7
|         minimize total_packages: 68.8
| 
| Input#loadFromCatalog (sqlite): 3264.2
| other JsImage#load: 286.5
| minimize conflicts: 168.7
| pre-solve: 166.8
| generate constraints: 74.9
| minimize total_packages: 68.8
| new Logic.Solver (MiniSat start-up): 63.2
| Total: 4093.1
|  Building the application                  |
| JsImage#load: 694.3
|     other JsImage#load: 693.6
| Rebuild App: 19895.0
|     compiler.compile(the app): 4688.7
|         Isopack#ensurePluginsInitialized: 4655.2
|             JsImage#load: 2430.3
|                 files.exists: 809.3
|                 other JsImage#load: 1621.0
|             other Isopack#ensurePluginsInitialized: 2224.9
|     bundler.bundle..makeClientTarget: 8179.9
|         Target#make: 8179.6
|             Target#_runCompilerPlugins: 7851.0
|                 Isopack#ensurePluginsInitialized: 812.1
|                     JsImage#load: 809.8
|                         other JsImage#load: 801.1
|                 processing files with cosmos:browserify (for target web.browser): 6965.9
|                     wrapped.fs.readFileSync: 191.4
|                     other processing files with cosmos:browserify (for target web.browser): 6772.3
|             Target#_emitResources: 234.8
|                 PackageSourceBatch#getResources: 229.2
|                     PackageSourceBatch#_linkJS: 227.2
|                         files.readFile: 116.0
|                         other PackageSourceBatch#_linkJS: 105.3
|     bundler.bundle..makeServerTarget: 6335.5
|         Target#make: 6335.2
|             Target#_runCompilerPlugins: 6055.3
|                 processing files with cosmos:browserify (for target os.osx.x86_64): 5995.9
|                     other processing files with cosmos:browserify (for target os.osx.x86_64): 5994.3
|             Target#_emitResources: 253.6
|                 PackageSourceBatch#getResources: 248.6
|                     PackageSourceBatch#_linkJS: 246.2
|                         files.readFile: 139.0
|                         other PackageSourceBatch#_linkJS: 101.1
|     bundler..writeSiteArchive: 680.7
|         bundler..writeTargetToPath: 602.8
|             ClientTarget#write: 325.0
|                 Builder#write: 51.4
|                 bundler..writeFile: 51.2
|                 other ClientTarget#write: 221.3
|             ServerTarget#write: 274.4
|                 JsImage#write: 246.4
|                     Builder#write: 140.3
|                     other JsImage#write: 99.1
|         Builder#complete: 69.3
|             files.rm_recursive: 68.9
| 
| other processing files with cosmos:browserify (for target web.browser): 6772.3
| other processing files with cosmos:browserify (for target os.osx.x86_64): 5994.3
| other JsImage#load: 3115.6
| other Isopack#ensurePluginsInitialized: 2227.2
| files.exists: 850.5
| files.readFile: 328.6
| other ClientTarget#write: 221.3
| other PackageSourceBatch#_linkJS: 206.4
| wrapped.fs.readFileSync: 191.9
| other JsImage#write: 99.1
| files.writeFile: 89.5
| files.rm_recursive: 71.9
| sha1: 53.3
| other Builder#write: 50.9
| Total: 20273.0
=> Started your app. 

[elidoran]

I don't see cosmos:browserify mentioned in the first profiling to make a comparison.

Version 0.8.1 uses the MultiFileCachingCompiler provided by Meteor's new build API and will have a speed increase when it considers the file unchanged (by its source hash, file options in package.js, and exports in package.js). Checking those, and writing to and reading from the cache, are handled by the new build api in 0.8.1.

I git cloned the repo you referenced, ran it with the command you gave, and then tweaked a few files to cause it to rebuild a few times. It's a lot faster in later rebuilds because it avoids running browserify again by using the cached result.

Also, you're browserifying a file for both the client and the server; which we discussed recently is possible. However, it looks like meteor is sending that file to the plugin twice, once for each scope. That's taking extra time on the initial build as well. I recommend not using browserify on the server side.

I did notice Meteor sometimes runs the plugin when it should use the cached version. Sometimes only the client or only the server and sometimes both. That makes me question the new build api's reliability for detecting whether a file has changed or not.

so:

1. I'll look at more profiling and see why Meteor is rerunning my plugin when it should be using the cached result. And check how long it's taking to perform each part of its work.
2. You could avoid the server scope build time by using a regular file with require's in it for the server scope.
3. run the profiling on 0.5.0 with it running the browserify plugin so a direct comparison can be made
4. when profiling, update various files around the app/package to trigger a rebuild to see how long it takes when it avoids rerunning the plugin
5. could also run the browserify cli to see how long it takes to do the browserifying outside the meteor system.

[sahanDissanayake]

thanks @elidoran

When you say " It's a lot faster in later rebuilds" was it faster than the results I got using the profiling ?

Hope you find something around this issue.

[vladshcherbin]

The build time with this package is insane, removing it speeds up the rebuild time a lot. Please, do something with it.

[elidoran]

@sahanDissanayake Yes, by faster I meant faster than what you show. I should have included the profiler output, so, I'll add some profiler output below. To repeat what I did for yourself, start the app like you did, edit different files so it reruns the build. When the build system identifies the file to browserify doesn't need to be rebuilt it uses the cached result instead. It's basically very similar to what I was doing manually with version 0.5 except it's part of the Meteor build API now. When it avoids the unnecessary work it's fast and it looks like this:

=> Client modified -- refreshing| 
| Select Package Versions: 1806.7
|     Input#loadFromCatalog (sqlite): 1750.1
|     other Select Package Versions: 54.7
| 
| Input#loadFromCatalog (sqlite): 1750.1
| other Select Package Versions: 54.7
| Total: 1804.8
| 
| files.rename: 177.5
| Rebuild App: 419.6
|     bundler.bundle..makeClientTarget: 215.1
|         Target#make: 215.1
|             Target#_emitResources: 136.2
|                 PackageSourceBatch#getResources: 133.5
|                     PackageSourceBatch#_linkJS: 132.1
|                         other PackageSourceBatch#_linkJS: 80.5
|     bundler..writeTargetToPath: 181.1
|         ClientTarget#write: 180.4
|             other ClientTarget#write: 168.3
| 
| files.rename: 177.9
| other ClientTarget#write: 168.3
| other PackageSourceBatch#_linkJS: 80.5
| Total: 426.7
=> Client modified -- refreshing (x2)

When it is being weird and rerunning the browserify plugin when the file hasn't changed it looks like this:

=> Client modified -- refreshing (x2)
|  Selecting package versions                /
| Select Package Versions: 1849.3
|     Input#loadFromCatalog (sqlite): 1784.6
|     other Select Package Versions: 62.7
| 
| Input#loadFromCatalog (sqlite): 1784.6
| other Select Package Versions: 62.7
| Total: 1847.3
|  Building the application                  |
| files.readFile: 128.4
| Rebuild App: 5646.3
|     bundler.bundle..makeClientTarget: 339.7
|         Target#make: 339.6
|             Target#_emitResources: 135.5
|                 PackageSourceBatch#getResources: 133.1
|                     PackageSourceBatch#_linkJS: 131.7
|                         other PackageSourceBatch#_linkJS: 80.7
|             ClientTarget#minifyCss: 123.5
|     bundler.bundle..makeServerTarget: 4722.6
|         Target#make: 4722.4
|             Target#_runCompilerPlugins: 4536.3
|                 processing files with cosmos:browserify (for target os.osx.x86_64): 4498.7
|                     other processing files with cosmos:browserify (for target os.osx.x86_64): 4497.1
|             Target#_emitResources: 166.7
|                 PackageSourceBatch#getResources: 163.0
|                     PackageSourceBatch#_linkJS: 161.3
|                         files.readFile: 57.2
|                         other PackageSourceBatch#_linkJS: 97.3
|     bundler..writeSiteArchive: 557.5
|         bundler..writeTargetToPath: 497.1
|             ClientTarget#write: 184.5
|                 Builder#write: 52.4
|                 bundler..writeFile: 52.3
|                     Builder#write: 51.2
|                 other ClientTarget#write: 78.3
|             ServerTarget#write: 309.8
|                 JsImage#write: 259.0
|                     Builder#write: 122.1
|                     other JsImage#write: 131.3
|         Builder#complete: 55.4
|             files.rm_recursive: 55.3
| 
| other processing files with cosmos:browserify (for target os.osx.x86_64): 4497.1
| files.readFile: 235.9
| other PackageSourceBatch#_linkJS: 178.1
| other JsImage#write: 131.3
| ClientTarget#minifyCss: 123.5
| files.writeFile: 102.6
| other ClientTarget#write: 78.3
| files.rm_recursive: 56.3
| Total: 5403.2
I20151030-16:50:08.625(-4)? server...         
=> Meteor server restarted

I edited an app file and it reran the browserify plugin. That's not what the build API is supposed to do. Look here to see how the new build API decides whether to use the cached version or not. Also, the Meteor Build API for Compilers. And, the explanation of the caching compilers Meteor provides.

[elidoran]

I'm attaching some outputs of both the profile and some console.log() statements with the time it takes the plugin to run its functions. The files to browserify for the app you ref'd are flow-router-ssr/client.browserify.js and react-runtime-dev/react.browserify.js (and its options file). The react file is run twice because it's in both the client and server scope.

When looking at the times it all comes down to the the getString() function representing nearly all the time spent in the plugin. That function is what actually has the Browserify module do its work and produce the output. Considering how much stuff it is processing for the react package I think 4 seconds is good time for Browserify to follow all those requires and gather them together.

Attachments:

(BP means Browserify Plugin, BPT is a fn's time)
(getString is part of getCompileResult which is part of compileOneFile...)

1. timing.txt - this one is with an empty cache so it builds them all.
2. timing_flow-router-client-change.txt - I changed a file in the flow-router-ssr package.
3. timing_app-client-change.txt - I changed one of the app's client files.
4. timing_app-server-change-1.txt - first time I changed one of the app's server files
5. timing_app-server-change-2.txt - second time.

In 2-5 none of the files to browserify were changed, so, they shouldn't have be rerun through the plugin, but, they are. That's a waste of time caused by the cache not being used.

Both 4 and 5 should have been the same because I changed the same file each time. However, the first time it rebuilt one file, the second time it rebuild two files. That's weird.

So, the problem centers around Meteor's build API inexplicably calling the plugin when the result is actually cached. So, I looked at the getCacheKey() function. We definitely want to watch the source's hash and the file's options. The plugin isn't using the exports in its operations. So, I removed that. And, it seems to figure things out correctly now. Why did I include it? When I read in CachingCompiler to do it, it seemed to make sense.

So, why did that make things weird? Well, the react package is browserifying the file for both the client and the server. This way they only need to maintain a single file for both scopes. I understand that. It also means it's using browserify for a server side file, which isn't the usual thing. Most importantly, it exports two vars for both client and server scopes, and then exports a single var for only the server scope. That means file.getDeclaredExports() is different for the client scope and the server scope, so, it generates a different cache key from getCacheKey() for the same file.

So, it seems getCacheKey() doesn't need the exports in there because compileOneFile() isn't using them. And, without the exports being part of the cache key your app properly rebuilds using the cache.

With that changed the rebuild outputs look like:

1. timing_app-server-change-2.txt (286.7 ms)
2. timing_app-client-change-fast.txt (50.7 ms)

Note: the original build will still take time because Browserify is doing its thing to generate the result to cache.

[elidoran]

commit closed the issue, feel free to add comments or reopen.

[sahanDissanayake]

@elidoran Thanks very much for all the explanation and the time.. I get an average ~4s rebuild time now 💃

Keep up the good work