Optimize checking for interrupts by replacing any? with NOT empty? by jasonhl · Pull Request #380 · Shopify/liquid

jasonhl · 2014-07-15T18:54:21Z

Doing an object allocation profile on Shopify in production using stackprof reveals that the number three generator of objects is Liquid#context has_interrupt?

The method is called in the main flow of the block rendering, which means it is called a lot. The documentation for .any? (http://ruby-doc.org/core-2.1.2/Enumerable.html#method-i-any-3F) states that:

Passes each element of the collection to the given block. 
The method returns true if the block ever returns a value other than false or nil. 
If the block is not given, Ruby adds an implicit block of { |obj| obj } that will cause 
any? to return true if at least one of the collection members is not false or nil.

Note the 'implicit block' bit -- that's where the allocation comes from.

Changed this to !empty, which is equivalent if (and only if) the array in question cannot contain nil/false values. The @interrupts member is only altered by push_interrupt, which is only ever called with a the keywords break or continue, so this is perfectly safe.

The existing tests appear to cover both the break and continue tags, so I did not add any as this should not alter behaviour in any way.

I temporarily altered the the code in profile.rb to benchmark object allocation.

Here's before:

vagrant@vagrant:~/src/liquid/performance$ bundle exec ruby profile.rb               
==================================                                                  
  Mode: object(1)                                                                   
  Samples: 9639300 (0.00% miss rate)                                                
  GC: 0 (0.00%)                                                                     
==================================                                                  
     TOTAL    (pct)     SAMPLES    (pct)     FRAME                                  
   1947200  (20.2%)     1462300  (15.2%)     Liquid::Context#variable               
   2185900  (22.7%)     1433400  (14.9%)     Liquid::Variable#lax_parse             
    833800   (8.7%)      833800   (8.7%)     Liquid::Context#has_interrupt?         
  10194700 (105.8%)      806100   (8.4%)     Liquid::Block#parse                    
    752500   (7.8%)      752500   (7.8%)     block in Liquid::Variable#lax_parse    
   2944500  (30.5%)      521600   (5.4%)     Liquid::Block#create_variable          
    438600   (4.6%)      438600   (4.6%)     Liquid::Template#tokenize              
    480300   (5.0%)      433300   (4.5%)     Liquid::Context#find_variable          
   2368300  (24.6%)      421100   (4.4%)     Liquid::Context#resolve                
   3075100  (31.9%)      300600   (3.1%)     Liquid::Variable#render                
   1075400  (11.2%)      295500   (3.1%)     block in Liquid::Variable#render       
    289100   (3.0%)      289100   (3.0%)     Liquid::If#lax_parse                   
   2422900  (25.1%)      238800   (2.5%)     block in Liquid::Block#create_variable 
    204800   (2.1%)      204800   (2.1%)     Liquid::StandardFilters#truncatewords  
    146100   (1.5%)      143500   (1.5%)     Liquid::For#lax_parse                  
  10927100 (113.4%)      108700   (1.1%)     Liquid::Block#render_all               
    600600   (6.2%)       98500   (1.0%)     Liquid::Context#invoke                 
     70700   (0.7%)       70700   (0.7%)     Liquid::Block#block_delimiter          
     48300   (0.5%)       48000   (0.5%)     Liquid::Context#initialize             
  10764400 (111.7%)       47600   (0.5%)     Liquid::Tag.parse

Here's with the change in this PR:

vagrant@vagrant:~/src/liquid/performance$ bundle exec ruby profile.rb               
==================================                                                  
  Mode: object(1)                                                                   
  Samples: 8805500 (0.00% miss rate)                                                
  GC: 0 (0.00%)                                                                     
==================================                                                  
     TOTAL    (pct)     SAMPLES    (pct)     FRAME                                  
   1947200  (22.1%)     1462300  (16.6%)     Liquid::Context#variable               
   2185900  (24.8%)     1433400  (16.3%)     Liquid::Variable#lax_parse             
  10194700 (115.8%)      806100   (9.2%)     Liquid::Block#parse                    
    752500   (8.5%)      752500   (8.5%)     block in Liquid::Variable#lax_parse    
   2944500  (33.4%)      521600   (5.9%)     Liquid::Block#create_variable          
    438600   (5.0%)      438600   (5.0%)     Liquid::Template#tokenize              
    480300   (5.5%)      433300   (4.9%)     Liquid::Context#find_variable          
   2368300  (26.9%)      421100   (4.8%)     Liquid::Context#resolve                
   3075100  (34.9%)      300600   (3.4%)     Liquid::Variable#render                
   1075400  (12.2%)      295500   (3.4%)     block in Liquid::Variable#render       
    289100   (3.3%)      289100   (3.3%)     Liquid::If#lax_parse                   
   2422900  (27.5%)      238800   (2.7%)     block in Liquid::Block#create_variable 
    204800   (2.3%)      204800   (2.3%)     Liquid::StandardFilters#truncatewords  
    146100   (1.7%)      143500   (1.6%)     Liquid::For#lax_parse                  
   9043900 (102.7%)      108700   (1.2%)     Liquid::Block#render_all               
    600600   (6.8%)       98500   (1.1%)     Liquid::Context#invoke                 
     70700   (0.8%)       70700   (0.8%)     Liquid::Block#block_delimiter          
     48300   (0.5%)       48000   (0.5%)     Liquid::Context#initialize             
  10764400 (122.2%)       47600   (0.5%)     Liquid::Tag.parse                      
     47000   (0.5%)       47000   (0.5%)     block in Liquid::Context#find_variable

833,800 (8.7%) less objects allocated :-)

@camilo, @boourns, @dylanahsmith: Code review, please.
CC: @csfrancis

camilo · 2014-07-15T18:55:48Z

@Shopify/liquid ping

jasonhl · 2014-07-15T18:56:58Z

Thanks @camilo -- didn't know there was a group.

csfrancis · 2014-07-15T18:58:31Z

🚀 ✨

camilo · 2014-07-15T19:00:23Z

⛵ awesome ✨

fw42 · 2014-07-15T19:01:15Z

lolwutruby

fw42 · 2014-07-15T19:01:40Z

I think 8.7% improvement deserves a regression test

csfrancis · 2014-07-15T19:02:51Z

@fw42 https://github.com/ruby/ruby/blob/bb51e69af06268b26af96698a8903f06c284c1f6/enum.c#L1087-L1092

It's the NEW_MEMO that ends up allocating an object every time you call any?.

fw42 · 2014-07-15T19:05:08Z

I temporarily altered the the code in profile.rb to benchmark object allocation.

Does it make sense to push that change as well? Seems useful.

camilo · 2014-07-15T19:05:48Z

maybe have both profiles yes, but it'd be a seperate PR IMO, @jasonhl maybe update CHANGELOG

camilo · 2014-07-15T19:06:57Z

I think 8.7% improvement deserves a regression test

This is not easy to test I think, how'd you go about it ( besides expecting that .any? did not get call)

fw42 · 2014-07-15T19:10:56Z

@camilo: Yeah dunno, maybe just as simple as

test "use empty? instead of any? because it's way faster, dont fucking change this!" do
  ...
  something.expects(:any?).never
  something.expects(:empty?)
end

Not pretty, but I think this improvement would be worth the ugly test.

In two weeks, someone is gonna be all "oh, I don't like negations, let's just use any?, that's nicer" :-)

fw42 · 2014-07-15T19:30:32Z

Fix indentation please :-)

fw42 · 2014-07-15T19:32:42Z

For reference: #221 / cc @d-Pixie

fw42 · 2014-07-15T20:00:27Z

For more reference: Shopify/ruby#4

d-Pixie · 2014-07-15T20:46:47Z

Nice to know that my semantic improvement only cost 8.7% in performance. You learn something every day :)

jasonhl · 2014-07-15T20:50:11Z

lol @d-Pixie

If it makes you feel any better, it gave me the opportunity to change liquid for the first time :-)

jasonhl · 2014-07-16T03:02:06Z

@fw42: Test added. Had to do the cleanup of spy explicitly in the teardown to get it to work, but it's not so bad.

jasonhl · 2014-07-16T03:03:27Z

@camilo: CHANGELOG? Did you mean this file: https://github.com/Shopify/liquid/blob/master/History.md or...?

camilo · 2014-07-16T04:58:35Z

@jasonhl yes that one so it goes as a thing in the next release

boourns · 2014-07-16T11:52:01Z

❤️

dylanahsmith · 2014-07-16T15:03:51Z

https://github.com/ruby/ruby/blob/bb51e69af06268b26af96698a8903f06c284c1f6/enum.c#L1087-L1092

It's the NEW_MEMO that ends up allocating an object every time you call any?.

@csfrancis you mind submitting a patch upstream that memoizes NEW_MEMO? That way we can avoid hacky regression tests in liquid.

dylanahsmith · 2014-07-16T15:05:12Z

❤️ the use of spy to avoid affecting the behaviour of the code

channeling your wisdom here @dylanahsmith

csfrancis · 2014-07-16T15:05:36Z

Yeah @dylanahsmith - I'm planning on submitting Shopify/ruby#5 upstream once Charlie 👍's.

dylanahsmith · 2014-07-16T15:06:04Z

👍

camilo · 2014-07-16T15:24:27Z

also

Optimize checking for interrupts by replacing any? with NOT empty?

Optimize checking for interrupts by replacing any? with NOT empty?

4cfc05e

fw42 reviewed Jul 15, 2014
View reviewed changes

Comment thread lib/liquid/context.rb Outdated

Copy link
Copy Markdown

Contributor

fw42 Jul 15, 2014

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fix indentation please :-)

dylanahsmith reviewed Jul 16, 2014
View reviewed changes

Adding tests, spy dependency

fd8c300

jasonhl mentioned this pull request Jul 16, 2014

Add object profiling in addition to cpu profiling #381

Merged

jasonhl added a commit that referenced this pull request Jul 16, 2014

Merge pull request #380 from Shopify/optimize_interrupt_handling

535d549

Optimize checking for interrupts by replacing any? with NOT empty?

jasonhl merged commit 535d549 into master Jul 16, 2014

jasonhl deleted the optimize_interrupt_handling branch July 16, 2014 15:36

Conversation

jasonhl commented Jul 15, 2014

Uh oh!

camilo commented Jul 15, 2014

Uh oh!

jasonhl commented Jul 15, 2014

Uh oh!

csfrancis commented Jul 15, 2014

Uh oh!

camilo commented Jul 15, 2014

Uh oh!

fw42 commented Jul 15, 2014

Uh oh!

fw42 commented Jul 15, 2014

Uh oh!

csfrancis commented Jul 15, 2014

Uh oh!

fw42 commented Jul 15, 2014

Uh oh!

camilo commented Jul 15, 2014

Uh oh!

camilo commented Jul 15, 2014

Uh oh!

fw42 commented Jul 15, 2014

Uh oh!

fw42 Jul 15, 2014

Choose a reason for hiding this comment

Uh oh!

fw42 commented Jul 15, 2014

Uh oh!

fw42 commented Jul 15, 2014

Uh oh!

d-Pixie commented Jul 15, 2014

Uh oh!

jasonhl commented Jul 15, 2014

Uh oh!

jasonhl commented Jul 16, 2014

Uh oh!

jasonhl commented Jul 16, 2014

Uh oh!

camilo commented Jul 16, 2014

Uh oh!

boourns commented Jul 16, 2014

Uh oh!

dylanahsmith commented Jul 16, 2014

Uh oh!

dylanahsmith Jul 16, 2014

Choose a reason for hiding this comment

Uh oh!

camilo Jul 16, 2014

Choose a reason for hiding this comment

Uh oh!

csfrancis commented Jul 16, 2014

Uh oh!

dylanahsmith commented Jul 16, 2014

Uh oh!

camilo commented Jul 16, 2014

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants