search

rails / sprockets

Rack-based asset packaging system
MIT License
951 stars 789 forks source link

compile seems to be dead on fairly large codebase with v4 #534

Open plrthink opened 6 years ago

plrthink commented 6 years ago

Expected behavior

Compile assets successfully even with slow speed.

Actual behavior

The process of compiling seems to be frozen after a few seconds. The CPU usage downgrade to 0, then it can't receive keyboard signal(can't quite).

screen shot 2017-12-11 at 10 51 42 pm the beginning of the build

screen shot 2017-12-11 at 10 51 21 pm just a few seconds past

System configuration

Example App

I can't reproduce this issue with a sample project because it may relate to large assets the codebase has.

It can compile without any problem with v3, but with no luck using v4. Our configuration is just simple as described in the readme.

I find that if I try several times it may build out as expected, I think this probably because it uses the cache generated before.

Any suggestions are appreciated.

rafaelfranca commented 6 years ago

Can you try to use strace in your process to find out where it is stuck and why? My guess is that it is waiting for some IO.

plrthink commented 6 years ago

here is the log which generated using dtruss on macOS log.txt

plrthink commented 6 years ago

any updates? we're blocked by this issue

mariusandra commented 6 years ago

Hi, @plrthink - I recently had to find out which part of my app was getting slower and slower after each reload. I found a gem called rack-mini-profiler that let me visualise where my app is stuck like you can see from this issue. Perhaps it can help you find the source of your problems as well. This dtruss trace is quite unreadable :)...

plrthink commented 6 years ago

@mariusandra thx for the mentioning, will try that.

schneems commented 6 years ago

I'm not terribly familiar with the output of dtruss, however I can pick out some things.

It looks like this call is the last attempt to load any gems around line 38674

69917/0x24acdd:  open("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/thread_safe-0.3.6/lib/mockingbot1603/guides_helper.bundle\0", 0x1000004, 0x0)       = -1 Err#2

Then not much below that, there seems to be some kind a of loop that repeatedly tries to call getattrlist on files, but it fails

69917/0x24ae41:  getattrlist("/Users\0", 0x7000088E1C98, 0x7000088E1CB0)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink\0", 0x7000088E1AC8, 0x7000088E1AE0)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm\0", 0x7000088E18F8, 0x7000088E1910)       = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems\0", 0x7000088E1728, 0x7000088E1740)      = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1\0", 0x7000088E1558, 0x7000088E1570)       = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems\0", 0x7000088E1388, 0x7000088E13A0)      = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0\0", 0x7000088E11B8, 0x7000088E11D0)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app\0", 0x7000088E0FE8, 0x7000088E1000)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets\0", 0x7000088E0E18, 0x7000088E0E30)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets/stylesheets\0", 0x7000088E0C48, 0x7000088E0C60)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets/stylesheets/active_admin\0", 0x7000088E0A78, 0x7000088E0A90)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets/stylesheets/active_admin/mixins\0", 0x7000088E08A8, 0x7000088E08C0)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets/stylesheets/active_admin/mixins/active_admin\0", 0x7000088E06D8, 0x7000088E06F0)        = -1 Err#2

It eventually stops calling this repeated set of operations and then moves on to others such as 

69917/0x24ae41:  getattrlist("/Users\0", 0x7000088E1618, 0x7000088E1630)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink\0", 0x7000088E1448, 0x7000088E1460)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/Work\0", 0x7000088E1278, 0x7000088E1290)       = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/Work/mockingbot\0", 0x7000088E10A8, 0x7000088E10C0)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/Work/mockingbot/imock\0", 0x7000088E0ED8, 0x7000088E0EF0)      = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/Work/mockingbot/imock/app\0", 0x7000088E0D08, 0x7000088E0D20)      = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/Work/mockingbot/imock/app/assets\0", 0x7000088E0B38, 0x7000088E0B50)       = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/Work/mockingbot/imock/app/assets/config\0", 0x7000088E0968, 0x7000088E0980)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/Work/mockingbot/imock/app/assets/config/active_admin\0", 0x7000088E0798, 0x7000088E07B0)       = -1 Err#2

But the result is always -1 Err#2 which i'm assuming is a failed call. I don't know why it's repeatedly calling these, and I don't know why it stops calling them even though they appear to never succeed.

Even when the trace seems to die at the end it looks like it's just looping on another one of these patterns

69917/0x24ae41:  getattrlist("/Users\0", 0x7000088E1618, 0x7000088E1630)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink\0", 0x7000088E1448, 0x7000088E1460)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm\0", 0x7000088E1278, 0x7000088E1290)       = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems\0", 0x7000088E10A8, 0x7000088E10C0)      = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1\0", 0x7000088E0ED8, 0x7000088E0EF0)       = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems\0", 0x7000088E0D08, 0x7000088E0D20)      = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0\0", 0x7000088E0B38, 0x7000088E0B50)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app\0", 0x7000088E0968, 0x7000088E0980)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets\0", 0x7000088E0798, 0x7000088E07B0)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets/javascripts\0", 0x7000088E05C8, 0x7000088E05E0)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets/javascripts/active_admin\0", 0x7000088E03F8, 0x7000088E0410)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems/activeadmin-1.0.0/app/assets/javascripts/active_admin/mixins\0", 0x7000088E0228, 0x7000088E0240)         = -1 Err#2
69917/0x24ae41:  getattrlist("/Users\0", 0x7000088E1618, 0x7000088E1630)         = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink\0", 0x7000088E1448, 0x7000088E1460)        = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm\0", 0x7000088E1278, 0x7000088E1290)       = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems\0", 0x7000088E10A8, 0x7000088E10C0)      = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1\0", 0x7000088E0ED8, 0x7000088E0EF0)       = 0 0
69917/0x24ae41:  getattrlist("/Users/plrthink/.rvm/gems/ruby-2.3.1/gems\0", 0x0, 0x0)        = 0 0
dtrace: 627 dynamic variable drops with non-empty dirty list
69917/0x24ae3e:  psynch_cvwait(0x7FC896800058, 0xDB000000DD00, 0xDB00)       = 0 0
69917/0x24ae3f:  psynch_cvwait(0x7FC896800058, 0xDC000000DE00, 0xDC00)       = 0 0
69917/0x24ae40:  psynch_cvwait(0x7FC896800058, 0xDC000000DF00, 0xDC00)       = 0 0
69917/0x24acde:  poll(0x7000084DCEB0, 0x1, 0x64)         = 0 0
69917/0x24acde:  poll(0x7000084DCEB0, 0x1, 0x64)         = 0 0
69917/0x24acde:  poll(0x7000084DCEB0, 0x1, 0x64)         = 0 0
69917/0x24acde:  poll(0x7000084DCEB0, 0x1, 0x64)         = 0 0
69917/0x24acde:  poll(0x7000084DCEB0, 0x1, 0x64)         = 0 0
69917/0x24acde:  poll(0x7000084DCEB0, 0x1, 0x64)         = 0 0
69917/0x24acde:  poll(0x7000084DCEB0, 0x1, 0x64)         = 0 0
69917/0x24acde:  poll(0x7000084DCEB0, 0x1, 0x64)         = 0 0

I'm not sure where exactly this is corresponding to in Ruby code. You could try to use stackprof to see where time is being spent, though I don't know if it will write out a result if the process fails. I use this in my Rakefile

task "assets:profile" do
  puts "=============="

  StackProf.run(mode: :wall, out: "tmp/stackprof.dump") do
    Rake::Task["assets:precompile"].invoke
  end
end
plrthink commented 6 years ago

@schneems wow, thanks for this deeper analyze, I would follow your suggestions to continue on this.

BTW, is there any roadmaps on the v4 release?