sprockets
sprockets copied to clipboard
rails
compile seems to be dead on fairly large codebase with v4
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).
the beginning of the build
just a few seconds past
System configuration
- Sprockets version v4.0.0.*
- Ruby version v2.3.1p112
- Rails version v4.2.10
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.
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.
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 :)...
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
@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?