image_pack_path takes 1/3 - 2/3 of a second to complete?

[LukeClancy]

Hello! Thank you to anyone that is willing to help me out. I am not sure if this is a bug or a mis-configuration, but I am stuck and have no idea what could be causing it. I have a production server I am trying to get ready which is giving worrying performance times due to shakapacker methods (a minute to load a single page! The browser times out, but I see the logs finish with 200 in a minute).

Versioning information

Ruby version: 2.7
Rails version: 7.0.2.2
Webpacker (Shakapacker) version: 6.1.1

Behavior

Expected behavior: relatively quick generation of asset version/host for each path when calling image_pack_path
Actual behavior: takes about 1/3 to 2/3 of a second to load when calling image_pack_path.

Log Output

Overall time for route

Completed 200 OK in 60977ms (Views: 60884.3ms | ActiveRecord: 91.3ms | Allocations: 924389)

Timing for a sample of webpacker methods

D, [2022-04-12T21:07:53.039198 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] [Webpacker] Everything's up-to-date. Nothing to do
D, [2022-04-12T21:07:53.042123 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] asset took 0.352239725 to load
D, [2022-04-12T21:07:53.473291 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] [Webpacker] Everything's up-to-date. Nothing to do
D, [2022-04-12T21:07:53.473992 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] asset took 0.431295868 to load
D, [2022-04-12T21:07:53.971524 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] [Webpacker] Everything's up-to-date. Nothing to do
D, [2022-04-12T21:07:53.984649 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] asset took 0.50113044 to load
D, [2022-04-12T21:07:54.578575 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] [Webpacker] Everything's up-to-date. Nothing to do
D, [2022-04-12T21:07:54.578910 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] asset took 0.593757911 to load
D, [2022-04-12T21:07:55.070302 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] [Webpacker] Everything's up-to-date. Nothing to do
D, [2022-04-12T21:07:55.070637 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] asset took 0.491181328 to load
D, [2022-04-12T21:07:55.477915 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] [Webpacker] Everything's up-to-date. Nothing to do
D, [2022-04-12T21:07:55.478242 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] asset took 0.407086495 to load
D, [2022-04-12T21:07:56.031949 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] [Webpacker] Everything's up-to-date. Nothing to do

As you can see each asset takes 1/3 to 2/3 of a second to generate the path.

Configuration

Here is anything I found that could be relevant to the current situation, this is not the entire config file

relevant config in webpacker.yml

default: &default
  source_path: app/javascript
  source_entry_path: index.js
  public_root_path: public
  public_output_path: assets
  cache_path: tmp/webpacker
  webpack_compile_output: true
  cache_manifest: false
  webpack_loader: 'babel'

production:
  <<: *default
  # Production depends on precompilation of packs prior to booting for performance.
  compile: true
  # Cache manifest.json for performance
  cache_manifest: true

relevant config in application.rb

config.consider_all_requests_local       = false
config.cache_classes = true
config.eager_load = true
config.action_controller.perform_caching = true
# Do not fallback to assets pipeline if a precompiled asset is missed.
config.assets.compile = true
# Enable serving of images, stylesheets, and JavaScripts from an asset server. (see initializers/assets)
config.assets.enabled = false #I think this is for the default rails asset provider (not webpacker)
config.assets.raise_runtime_errors = false
config.action_controller.asset_host = 'cache.product.com' #I use asset_sync gem to throw assets into the cloud after assets:precompile
config.assets.prefix = "/assets"

Extra

This is my diagnostic code for webpacker methods, I have used it before to create better error messages when providing bad file paths (since WebpackerAssetNoFound prints the entire manifest). I am also using it for getting timing information. You can skip this if not interested

[tomdracz]

Hey @LukeClancy Thanks for the repro steps, much appreciated!

Definitely not getting such slowness as you:

D, [2022-04-13T17:01:11.531452 #15012] DEBUG -- : asset took 0.000521 to load
D, [2022-04-13T17:01:11.531937 #15012] DEBUG -- : asset took 0.000291 to load
D, [2022-04-13T17:01:11.532285 #15012] DEBUG -- : asset took 0.000238 to load
D, [2022-04-13T17:02:25.083837 #15012] DEBUG -- : asset took 0.00155 to load
D, [2022-04-13T17:02:25.084874 #15012] DEBUG -- : asset took 0.000596 to load
D, [2022-04-13T17:02:25.085684 #15012] DEBUG -- : asset took 0.000514 to load
D, [2022-04-13T17:02:29.141190 #15012] DEBUG -- : asset took 0.001232 to load
D, [2022-04-13T17:02:29.142468 #15012] DEBUG -- : asset took 0.000822 to load
D, [2022-04-13T17:02:29.144161 #15012] DEBUG -- : asset took 0.001312 to load

One thing stood out to me
D, [2022-04-12T21:07:56.031949 #36129] DEBUG -- : [779a946f-344e-4779-b5ff-bc2a292248c6] [Webpacker] Everything's up-to-date. Nothing to do

This means you're compiling assets on every request as it's hitting this
https://github.com/shakacode/shakapacker/blob/master/lib/webpacker/manifest.rb#L53-L55

If dev server is not running or compile is set to true in webpacker.yml, you will get this behaviour.

I expect this is where the slowdown is, at the moment webpacker gets all the assets and calculates digest for them. I'm working on a PR #97 to speed this up drastically.

How many assets have you got just to get the idea? Have you set additional_path to anything in webpacker.yml?

To see if the digest compilation is the cuplrit, you could benchmark how long this method runs for https://github.com/shakacode/shakapacker/blob/v6.2.0/lib/webpacker/compiler.rb#L54-L73

Finally I see you've got compile: true in your production config? Is there any reason for that? This really isn't suitable for production deploys and looks like a misconfig. You should always precompile assets first and leave compile set to false in prod, otherwise each asset lookup will try and run compile/staleness checks.

In general, try set compile: false and run webpacker:precompile and try to benchmark again. I would expect a massive decrease in time it takes for the assets to load. If it's still slow, we can investigate further.

[LukeClancy]

That solved it! There are so many configuration variables for a rails project I get turned around sometimes. After completing your advice here are the new load times, note that the webpacker log output (which happens during compilation) is gone as well!

asset took 5.4771e-05 to load
asset took 2.4379e-05 to load
asset took 3.8597e-05 to load
asset took 3.1643e-05 to load
asset took 2.9541e-05 to load
asset took 2.6912e-05 to load
asset took 3.1602e-05 to load
asset took 3.7982e-05 to load
asset took 4.1445e-05 to load
asset took 3.7983e-05 to load
asset took 3.4782e-05 to load
asset took 0.000122749 to load

Almost no time at all! Also I made an error in my diagnostic code, and wrote the fix in a gist comment there.

Thank you again for your help!