Performance regression in 3.16.14 series?

[ewoodh2o]

We upgraded libv8 to the 3.16.14 series last week and started seeing significantly slower asset compilation times (through Uglifier) compared to v3.11.8.17. I came at this through Rails' Asset Pipeline, so I'm way in the weeds here and don't know if it's libv8 or V8 itself, but thought I'd ask here to see if anyone had similar experiences.

This doesn't seem to affect times on my dev machine (OS X 10.10, Intel Core i7), but it's between 2x and 5x slower on our production servers (Scientific Linux 6.5, AMD). Seems to be worse for larger files (obviously in strict wall-clock time, but also closer to 5x+ slower on the big files).

Benchmarks for Uglifier.compile(), which is just the easiest way I know how to test:

_libv8-3.11.8.17-x86_64-linux_

Compiling bootstrap.js (62kb, not minified)
  0.700000   0.030000   0.730000 (  0.721680)
  0.670000   0.030000   0.700000 (  0.688308)

Compiling highcharts.js (496kb, not minified)
  4.510000   0.040000   4.550000 (  4.499848)
  4.250000   0.030000   4.280000 (  4.238179)

Compiling jquery-1.8.1.min.js (93kb, already minified)
  2.630000   0.040000   2.670000 (  2.639083)
  2.540000   0.030000   2.570000 (  2.548431)

Compiling jquery-ui-1.8.23.min.js (205kb, already minified)
  3.320000   0.070000   3.390000 (  3.345508)
  3.360000   0.070000   3.430000 (  3.382746)

Compiling application.js (900kb, mixed)
 15.020000   0.300000  15.320000 ( 15.129480)
 16.170000   0.180000  16.350000 ( 16.162925)

_libv8-3.16.14.3-x86_64-linux_

Compiling bootstrap.js (62kb, not minified)
  0.980000   0.010000   0.990000 (  0.976608)
  0.860000   0.020000   0.880000 (  0.865921)

Compiling highcharts.js (496kb, not minified)
  8.720000   0.080000   8.800000 (  8.736296)
  7.230000   0.060000   7.290000 (  7.230722)

Compiling jquery-1.8.1.min.js (93kb, already minified)
  4.110000   0.080000   4.190000 (  4.153838)
  3.830000   0.030000   3.860000 (  3.830293)

Compiling jquery-ui-1.8.23.min.js (205kb, already minified)
  7.260000   0.060000   7.320000 (  7.273115)
  6.580000   0.030000   6.610000 (  6.579161)

Compiling application.js (900kb, mixed)
 82.280000   0.190000  82.470000 ( 82.314145)
 87.490000   0.220000  87.710000 ( 87.526244)

Anyone experiencing anything similar, or have any ideas on what might cause this?

[ledbettj]

Here are some ruby-prof traces of the two versions mentioned above, simply using Uglifier to compress a 1.4mb javascript file. 3.16.14.7 took approximately 70 seconds, while 3.11.8.17 completed in about 18.

V8::C::String#Utf8Value seems to be the culprit at first glance.

$ uname -a
Linux throttle 3.14.1-1-ARCH #1 SMP PREEMPT Mon Apr 14 20:40:47 CEST 2014 x86_64 GNU/Linux

john@throttle:~/Projects/test$ be ./test.rb
Uglifier 2.5.3 libv8 3.16.14.7
Thread ID: 5649160
Fiber ID: 5500900
Total: 70.067854
Sort by: self_time

 %self      total      self      wait     child     calls  name
 73.85     51.749    51.749     0.000     0.000        1   V8::C::String#Utf8Value
 26.08     18.272    18.272     0.000     0.000        1   V8::C::Script#Run
  0.03      0.026     0.018     0.000     0.008        1   JSON::Ext::Generator::State#generate
  0.02      0.017     0.017     0.000     0.000        1   <Class::V8::C::Script>#New
  0.01      0.007     0.007     0.000     0.000       55   Symbol#to_s
  0.00     70.041     0.001     0.000    70.040        1   ExecJS::RubyRacerRuntime::Context#exec
  0.00     70.039     0.001     0.000    70.038        5  *Proc#call
  0.00      0.001     0.001     0.000     0.000        1   String#%
  0.00      0.000     0.000     0.000     0.000       61   String#encode
  0.00     70.068     0.000     0.000    70.068        1   Global#[No method]
  0.00     70.040     0.000     0.000    70.039        2  *<Module::V8::C>#Locker
  0.00     18.289     0.000     0.000    18.289        2   <Module::V8::C>#TryCatch
  0.00      0.000     0.000     0.000     0.000        3   Hash#initialize_copy
  0.00      0.000     0.000     0.000     0.000        2   <Class::V8::Context>#current=
  0.00      0.000     0.000     0.000     0.000        1   ExecJS::RubyRacerRuntime::Context#unbox
  0.00      0.000     0.000     0.000     0.000        1   Hash#reject
  0.00     70.068     0.000     0.000    70.068        1   Uglifier#run_uglifyjs
  0.00     18.290     0.000     0.000    18.289        2   V8::Error::Try#try
  0.00     70.040     0.000     0.000    70.040        1   ExecJS::RubyRacerRuntime::Context#eval
  0.00      0.000     0.000     0.000     0.000        3   Hash#merge
  0.00      0.026     0.000     0.000     0.026        1   JSON#generate
  0.00     51.749     0.000     0.000    51.749        1   V8::Conversion::Identity#to_ruby
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#output_options
  0.00      0.000     0.000     0.000     0.000        1   V8::C::Context#Exit
  0.00     70.038     0.000     0.000    70.038        1   V8::Context#eval
  0.00      0.000     0.000     0.000     0.000        7   Module#===
  0.00      0.000     0.000     0.000     0.000        7   Hash#keys
  0.00      0.000     0.000     0.000     0.000        3   Uglifier#conditional_option
  0.00      0.026     0.000     0.000     0.026        1   JSON#dump
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#comment_options
  0.00      0.000     0.000     0.000     0.000        2   V8::C::TryCatch#HasCaught
  0.00      0.000     0.000     0.000     0.000        4   <Class::Thread>#current
  0.00     51.749     0.000     0.000    51.749        1   V8::Context#to_ruby
  0.00     51.749     0.000     0.000    51.749        1   V8::Conversion::NativeString#to_ruby
  0.00      0.000     0.000     0.000     0.000        4   Kernel#initialize_dup
  0.00      0.000     0.000     0.000     0.000        2   Kernel#respond_to?
  0.00     70.038     0.000     0.000    70.038        1   V8::Context#lock_scope_and_enter
  0.00     51.749     0.000     0.000    51.749        1   V8::Conversion#to_ruby
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#encode_regexp
  0.00      0.000     0.000     0.000     0.000        2   ExecJS::Encoding#encode
  0.00     70.038     0.000     0.000    70.038        1   <Module::V8::C>#HandleScope
  0.00      0.000     0.000     0.000     0.000       15   Symbol#==
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#comment_setting
  0.00     70.038     0.000     0.000    70.038        1   V8::Context#enter
  0.00     70.040     0.000     0.000    70.040        1   ExecJS::RubyRacerRuntime::Context#lock
  0.00      0.000     0.000     0.000     0.000        1   String#==
  0.00      0.000     0.000     0.000     0.000        1   String#force_encoding
  0.00      0.000     0.000     0.000     0.000        2   Thread#[]=
  0.00     70.068     0.000     0.000    70.068        1   Uglifier#compile
  0.00      0.026     0.000     0.000     0.026        1   Uglifier#json_encode
  0.00      0.000     0.000     0.000     0.000        1   V8::C::Context#Enter
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#compressor_options
  0.00      0.000     0.000     0.000     0.000        2   <Class::V8::Context>#current
  0.00      0.000     0.000     0.000     0.000        3   String#to_s
  0.00     51.749     0.000     0.000    51.749        1   V8::Conversion::Fundamental#to_ruby
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#read_source
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#screw_ie8?
  0.00      0.000     0.000     0.000     0.000        1   JSON::Ext::Generator::State#configure
  0.00      0.000     0.000     0.000     0.000        1   V8::Context#entered?
  0.00      0.000     0.000     0.000     0.000        3   Kernel#respond_to_missing?
  0.00      0.000     0.000     0.000     0.000        2   Thread#[]
  0.00      0.000     0.000     0.000     0.000        1   Hash#==
  0.00      0.000     0.000     0.000     0.000        1   Kernel#dup
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#enclose_options
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#mangle_options
  0.00      0.000     0.000     0.000     0.000        1   JSON::Ext::Generator::State#initialize_copy
  0.00      0.000     0.000     0.000     0.000        3   Hash#has_key?
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#source_map_options
  0.00      0.000     0.000     0.000     0.000        3   Hash#key?
  0.00      0.000     0.000     0.000     0.000        3   Symbol#===
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#parse_options
  0.00      0.000     0.000     0.000     0.000        1   Kernel#===
  0.00      0.000     0.000     0.000     0.000        1   Module#<=
  0.00      0.000     0.000     0.000     0.000        2   NilClass#nil?
  0.00      0.000     0.000     0.000     0.000        1   Regexp#source
  0.00      0.000     0.000     0.000     0.000        1   Kernel#class
  0.00      0.000     0.000     0.000     0.000        1   Regexp#casefold?
  0.00      0.000     0.000     0.000     0.000        1   Hash#to_hash
  0.00      0.000     0.000     0.000     0.000        1   Kernel#block_given?
  0.00      0.000     0.000     0.000     0.000        1   Kernel#nil?
  0.00      0.000     0.000     0.000     0.000        1   BasicObject#==

* indicates recursively called methods

john@throttle:~/Projects/test$ be ./test.rb
Uglifier 2.5.3 libv8 3.11.8.17
Thread ID: 18510600
Fiber ID: 19495280
Total: 17.847674
Sort by: self_time

 %self      total      self      wait     child     calls  name
 99.73     17.799    17.799     0.000     0.000        1   V8::C::Script#Run
  0.10      0.019     0.018     0.000     0.000        1   JSON::Ext::Generator::State#generate
  0.10      0.018     0.018     0.000     0.000        1   <Class::V8::C::Script>#New
  0.05      0.009     0.009     0.000     0.000        1   V8::C::String#Utf8Value
  0.01     17.828     0.001     0.000    17.827        1   ExecJS::RubyRacerRuntime::Context#exec
  0.01     17.826     0.001     0.000    17.826        5  *Proc#call
  0.00      0.001     0.001     0.000     0.000        1   String#%
  0.00      0.000     0.000     0.000     0.000       55   Symbol#to_s
  0.00      0.000     0.000     0.000     0.000       61   String#encode
  0.00     17.848     0.000     0.000    17.848        1   Global#[No method]
  0.00     17.816     0.000     0.000    17.816        2   <Module::V8::C>#TryCatch
  0.00      0.000     0.000     0.000     0.000        1   ExecJS::RubyRacerRuntime::Context#unbox
  0.00      0.009     0.000     0.000     0.009        1   V8::Conversion::Identity#to_ruby
  0.00     17.826     0.000     0.000    17.826        2  *<Module::V8::C>#Locker
  0.00      0.000     0.000     0.000     0.000        1   Hash#reject
  0.00     17.848     0.000     0.000    17.848        1   Uglifier#run_uglifyjs
  0.00     17.827     0.000     0.000    17.827        1   ExecJS::RubyRacerRuntime::Context#eval
  0.00      0.000     0.000     0.000     0.000        7   Module#===
  0.00      0.000     0.000     0.000     0.000        3   Hash#initialize_copy
  0.00      0.000     0.000     0.000     0.000        3   Hash#merge
  0.00      0.019     0.000     0.000     0.019        1   JSON#generate
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#output_options
  0.00      0.000     0.000     0.000     0.000        7   Hash#keys
  0.00      0.019     0.000     0.000     0.019        1   JSON#dump
  0.00      0.000     0.000     0.000     0.000        3   Uglifier#conditional_option
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#comment_options
  0.00     17.825     0.000     0.000    17.825        1   V8::Context#eval
  0.00      0.009     0.000     0.000     0.009        1   V8::Conversion::NativeString#to_ruby
  0.00      0.000     0.000     0.000     0.000        2   Kernel#respond_to?
  0.00      0.000     0.000     0.000     0.000        2   V8::C::TryCatch#HasCaught
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#encode_regexp
  0.00      0.000     0.000     0.000     0.000        4   Kernel#initialize_dup
  0.00      0.000     0.000     0.000     0.000        1   V8::C::Context#Exit
  0.00      0.009     0.000     0.000     0.009        1   V8::Context#to_ruby
  0.00      0.000     0.000     0.000     0.000        2   <Class::V8::Context>#current
  0.00     17.817     0.000     0.000    17.816        2   V8::Error::Try#try
  0.00      0.000     0.000     0.000     0.000        2   Thread#[]=
  0.00      0.000     0.000     0.000     0.000       15   Symbol#==
  0.00     17.825     0.000     0.000    17.825        1   V8::Context#lock_scope_and_enter
  0.00      0.009     0.000     0.000     0.009        1   V8::Conversion#to_ruby
  0.00     17.848     0.000     0.000    17.848        1   Uglifier#compile
  0.00      0.000     0.000     0.000     0.000        2   ExecJS::Encoding#encode
  0.00      0.000     0.000     0.000     0.000        2   <Class::V8::Context>#current=
  0.00      0.019     0.000     0.000     0.019        1   Uglifier#json_encode
  0.00      0.000     0.000     0.000     0.000        4   <Class::Thread>#current
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#comment_setting
  0.00     17.826     0.000     0.000    17.826        1   ExecJS::RubyRacerRuntime::Context#lock
  0.00      0.000     0.000     0.000     0.000        3   Kernel#respond_to_missing?
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#compressor_options
  0.00     17.825     0.000     0.000    17.825        1   V8::Context#enter
  0.00      0.000     0.000     0.000     0.000        3   String#to_s
  0.00      0.000     0.000     0.000     0.000        1   String#force_encoding
  0.00     17.825     0.000     0.000    17.825        1   <Module::V8::C>#HandleScope
  0.00      0.000     0.000     0.000     0.000        1   JSON::Ext::Generator::State#configure
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#read_source
  0.00      0.000     0.000     0.000     0.000        1   V8::C::Context#Enter
  0.00      0.009     0.000     0.000     0.009        1   V8::Conversion::Fundamental#to_ruby
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#screw_ie8?
  0.00      0.000     0.000     0.000     0.000        1   String#==
  0.00      0.000     0.000     0.000     0.000        1   Kernel#dup
  0.00      0.000     0.000     0.000     0.000        1   Hash#==
  0.00      0.000     0.000     0.000     0.000        1   V8::Context#entered?
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#enclose_options
  0.00      0.000     0.000     0.000     0.000        1   JSON::Ext::Generator::State#initialize_copy
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#mangle_options
  0.00      0.000     0.000     0.000     0.000        3   Hash#has_key?
  0.00      0.000     0.000     0.000     0.000        1   Kernel#class
  0.00      0.000     0.000     0.000     0.000        2   Thread#[]
  0.00      0.000     0.000     0.000     0.000        3   Symbol#===
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#source_map_options
  0.00      0.000     0.000     0.000     0.000        1   Kernel#===
  0.00      0.000     0.000     0.000     0.000        1   Uglifier#parse_options
  0.00      0.000     0.000     0.000     0.000        1   Regexp#source
  0.00      0.000     0.000     0.000     0.000        3   Hash#key?
  0.00      0.000     0.000     0.000     0.000        1   Module#<=
  0.00      0.000     0.000     0.000     0.000        2   NilClass#nil?
  0.00      0.000     0.000     0.000     0.000        1   Hash#to_hash
  0.00      0.000     0.000     0.000     0.000        1   Regexp#casefold?
  0.00      0.000     0.000     0.000     0.000        1   Kernel#nil?
  0.00      0.000     0.000     0.000     0.000        1   Kernel#block_given?
  0.00      0.000     0.000     0.000     0.000        1   BasicObject#==

* indicates recursively called methods

[ignisf]

Very interesting. Thank you, @ledbettj.

[ignisf]

Hmm... Looking at https://github.com/cowboyd/therubyracer/blob/master/ext/v8/string.cc#L22 I'm not sure the regression is caused by v8. @cowboyd needs to weigh in here.

[ledbettj]

Just to make sure I include all the variables, the version of therubyracer also changed. Sorry for not including this in the initial post.

Faster: Uglifier 2.5.3 / libv8 3.11.8.17 / therubyracer 0.11.4
Slower: Uglifier 2.5.3 / libv8 3.16.14.7 / therubyracer 0.12.1

[beekermememe]

+1 on this, We are going from 5 minute deploys up to 18 minutes when deploying to C1 large instances
Rails 3.2.21. We are running a SPA so a good few JS files.

[pseidemann]

+1

[stefankaiser]

+1

[SamSaffron]

I am going to have to debug this, as it stands it takes us 12 seconds to simply run our JS snippets through babel to build application.js, this feels way too long.

I completely eliminated the ruby racer from our assets minification pipeline due to this huge performance hole. Going to work on some simpler repros this week, but this issue does need more attention.

[ignisf]

A reproduction would help. Let me know if I can help in some way. Unfortunately profiling c++ is a bit out of my league or I would have taken a crack at this.