#xpath performance #760

Open
etm opened this Issue Sep 12, 2012 · 14 comments

Comments

Projects
None yet
5 participants
@etm

etm commented Sep 12, 2012

about 1/3 of the runtime of #xpath is spent allocating XPathContext. Not sure, but do you think caching the context could lead to bad situations? Caching would improve performance a lot.

Example (can be inserted into #xpath)

 @oldns ||= {}
 if @oldns == ns
   @ctx ||= XPathContext.new(self)
 else
   @ctx = XPathContext.new(self)
   @ctx.register_namespaces(ns)
  @oldns = ns
 end
...
@ctx.evaluate(....)

Note: adding and initializing @ctx and @oldns in the constructor is bad, as nodes that never need a ctx are created quite often, and thus this would degrade performance again.

cheers,

eTM

@kivikakk

This comment has been minimized.

Show comment Hide comment
@kivikakk

kivikakk Oct 19, 2012

I thought that this would be a good idea, so I tried implementing your suggestion to see how it would work.

I'm seeing failures where nodes aren't being found as a result, so it seems that it's not good enough to simply cache the XPathContext like this, unfortunately.

I thought that this would be a good idea, so I tried implementing your suggestion to see how it would work.

I'm seeing failures where nodes aren't being found as a result, so it seems that it's not good enough to simply cache the XPathContext like this, unfortunately.

@etm

This comment has been minimized.

Show comment Hide comment
@etm

etm Oct 19, 2012

consider the following piece of code:

 require 'rubygems'
 require 'nokogiri'

 doc = Nokogiri.XML("<foo><baz/><baz><bar name='test'/></baz></foo>")
 xpa = Nokogiri::XML::XPathContext.new(doc.root)

 p xpa.evaluate('//baz').length # => 2
 p xpa.evaluate('baz').length # => 2
 p xpa.evaluate('//@name').length # => 1
 p xpa.evaluate('baz').length # => 0
 p xpa.evaluate('//baz').length # => 2
 p xpa.evaluate('foo').length # => 1 

These results are rather strange. As soon as you look for attributes somehow the context shifts. After the third xpath, we find foo instead of baz.

I think this is a bug in libxml - or some well designed behaviour i don't get :-). We could circumvent it maybe if we make the context node settable not only in the constructor for XPathContext, but afterwards (libxml has this too). According to my tests this is still MUCH faster. E.g.:

xpa = Nokogiri::XML::XPathContext.new(doc.root)
.... some xpath
xpa.node = doc.root
.... some other xpath

Juergen

etm commented Oct 19, 2012

consider the following piece of code:

 require 'rubygems'
 require 'nokogiri'

 doc = Nokogiri.XML("<foo><baz/><baz><bar name='test'/></baz></foo>")
 xpa = Nokogiri::XML::XPathContext.new(doc.root)

 p xpa.evaluate('//baz').length # => 2
 p xpa.evaluate('baz').length # => 2
 p xpa.evaluate('//@name').length # => 1
 p xpa.evaluate('baz').length # => 0
 p xpa.evaluate('//baz').length # => 2
 p xpa.evaluate('foo').length # => 1 

These results are rather strange. As soon as you look for attributes somehow the context shifts. After the third xpath, we find foo instead of baz.

I think this is a bug in libxml - or some well designed behaviour i don't get :-). We could circumvent it maybe if we make the context node settable not only in the constructor for XPathContext, but afterwards (libxml has this too). According to my tests this is still MUCH faster. E.g.:

xpa = Nokogiri::XML::XPathContext.new(doc.root)
.... some xpath
xpa.node = doc.root
.... some other xpath

Juergen

@kivikakk

This comment has been minimized.

Show comment Hide comment
@kivikakk

kivikakk Oct 21, 2012

I don't have the code in front of me to check, but it does seem probable to me that this is by design. (Otherwise it seems like an obvious optimisation that Nokogiri would have possibly already taken up.)

By the way, your example was difficult to follow; I think some XML was stripped. If you encase the code examples in triple-backticks it'll render it literally.

Next time I get a chance I'll see if I can find what's going on with this.

I don't have the code in front of me to check, but it does seem probable to me that this is by design. (Otherwise it seems like an obvious optimisation that Nokogiri would have possibly already taken up.)

By the way, your example was difficult to follow; I think some XML was stripped. If you encase the code examples in triple-backticks it'll render it literally.

Next time I get a chance I'll see if I can find what's going on with this.

@flavorjones

This comment has been minimized.

Show comment Hide comment
@flavorjones

flavorjones Oct 22, 2012

Owner

@etm - 1/3 of the time spent ... how much time is that? Can you show how you're benchmarking and tell us what Ruby version (output from nokogiri -v please)?

Owner

flavorjones commented Oct 22, 2012

@etm - 1/3 of the time spent ... how much time is that? Can you show how you're benchmarking and tell us what Ruby version (output from nokogiri -v please)?

@kivikakk

This comment has been minimized.

Show comment Hide comment
@kivikakk

kivikakk Oct 22, 2012

@flavorjones: I see much less than 1/3rd—about 1% is spent allocating XPathContexts, but closer to 20% registering namespaces (XPathContext#register_namespaces). This is probably because I'm working with OpenOffice documents, which have quite a number.

I'm using ruby-prof to profile. It's difficult to demonstrate (proprietary codebase, woo), but here's some stuff anyway:

10,095 calls to Nokogiri::XML::Node#xpath, consuming 36.49s (total), only 0.13s is in the #xpath body itself, excluding blocks. 28.98s of runtime in Array#map from #xpath. Of that, only 0.16s is in Array#map itself—rest in thus in the block that #map calls.

Note that very little time is spent in XPathContext's new; the biggest saving from caching them comes from not repeating namespace registration.

I worked around this by only registering namespaces I need (i.e. by collecting the ones I want beforehand and passing them into every #xpath invocation).

$ nokogiri -v
# Nokogiri (1.5.5)
    ---
    warnings: []
    nokogiri: 1.5.5
    ruby:
      version: 1.9.3
      platform: x86_64-darwin11.3.0
      description: ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-darwin11.3.0]
      engine: ruby
    libxml:
      binding: extension      compiled: 2.7.3      loaded: 2.7.3

@flavorjones: I see much less than 1/3rd—about 1% is spent allocating XPathContexts, but closer to 20% registering namespaces (XPathContext#register_namespaces). This is probably because I'm working with OpenOffice documents, which have quite a number.

I'm using ruby-prof to profile. It's difficult to demonstrate (proprietary codebase, woo), but here's some stuff anyway:

10,095 calls to Nokogiri::XML::Node#xpath, consuming 36.49s (total), only 0.13s is in the #xpath body itself, excluding blocks. 28.98s of runtime in Array#map from #xpath. Of that, only 0.16s is in Array#map itself—rest in thus in the block that #map calls.

Note that very little time is spent in XPathContext's new; the biggest saving from caching them comes from not repeating namespace registration.

I worked around this by only registering namespaces I need (i.e. by collecting the ones I want beforehand and passing them into every #xpath invocation).

$ nokogiri -v
# Nokogiri (1.5.5)
    ---
    warnings: []
    nokogiri: 1.5.5
    ruby:
      version: 1.9.3
      platform: x86_64-darwin11.3.0
      description: ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-darwin11.3.0]
      engine: ruby
    libxml:
      binding: extension      compiled: 2.7.3      loaded: 2.7.3
@etm

This comment has been minimized.

Show comment Hide comment
@etm

etm Oct 22, 2012

@flavorjones, @unnali: yes register_namespaces is also slow, but something else is going on - please try the following example yourself:

    require 'rubygems' 
    require 'nokogiri'

    module Nokogiri
      module XML
          class Node

            def xpath_fast1(path,prefixes=[])
              return NodeSet.new(document) unless document
              ctx = XPathContext.new(self)
              ctx.register_namespaces(prefixes) unless prefixes.empty?
              path = path.gsub(/xmlns:/, ' :') unless Nokogiri.uses_libxml?
              ctx.evaluate(path)
            end

            def xpath_fast2(path,prefixes=[])
              return NodeSet.new(document) unless document
              if @custom_prefixes != prefixes
                @ctx = XPathContext.new(self)
                @ctx.register_namespaces(prefixes) unless prefixes.empty?
                @custom_prefixes = prefixes
              end
              path = path.gsub(/xmlns:/, ' :') unless Nokogiri.uses_libxml?
              @ctx.evaluate(path)
            end

          end
      end
    end

    doc = Nokogiri.XML("<foo><baz/><baz><bar name='test'/></baz></foo>")

    s = Time.now.to_f
    1.upto 50000 do |i|
      doc.root.xpath_fast1('//baz')
    end
    puts Time.now.to_f - s

    s = Time.now.to_f
    1.upto 50000 do |i|
      doc.root.xpath_fast2('//baz')
    end
    puts Time.now.to_f - s

The results (obviously no difference between ruby 1.9.3 und ruby 1.8.7 - almost the same numbers as most of the stuff is done by nokogiri:

fast1: 2.12183022499084
fast2: 0.841907024383545

Thats a massive speedup. Also note that NO namespace prefixes are used here, with lots of namespace prefixes the results are even better.

Sorry for using old-fashioned monkey-patching and time measurement ;-)

p.s.:

# Nokogiri (1.5.5)
    --- 
    nokogiri: 1.5.5
    warnings: []

    libxml: 
      binding: extension
      compiled: 2.7.8
      loaded: 2.7.8
    ruby: 
      engine: mri
      platform: i686-linux
      version: 1.8.7
      description: ruby 1.8.7 (2011-06-30 patchlevel 352) [i686-linux]```

# Nokogiri (1.5.5)
    ---
    warnings: []
    nokogiri: 1.5.5
    ruby:
      version: 1.9.3
      platform: i686-linux
      description: ruby 1.9.3p0 (2011-10-30 revision 33570) [i686-linux]
      engine: ruby
    libxml:
      binding: extension
      compiled: 2.7.8
      loaded: 2.7.8```

etm commented Oct 22, 2012

@flavorjones, @unnali: yes register_namespaces is also slow, but something else is going on - please try the following example yourself:

    require 'rubygems' 
    require 'nokogiri'

    module Nokogiri
      module XML
          class Node

            def xpath_fast1(path,prefixes=[])
              return NodeSet.new(document) unless document
              ctx = XPathContext.new(self)
              ctx.register_namespaces(prefixes) unless prefixes.empty?
              path = path.gsub(/xmlns:/, ' :') unless Nokogiri.uses_libxml?
              ctx.evaluate(path)
            end

            def xpath_fast2(path,prefixes=[])
              return NodeSet.new(document) unless document
              if @custom_prefixes != prefixes
                @ctx = XPathContext.new(self)
                @ctx.register_namespaces(prefixes) unless prefixes.empty?
                @custom_prefixes = prefixes
              end
              path = path.gsub(/xmlns:/, ' :') unless Nokogiri.uses_libxml?
              @ctx.evaluate(path)
            end

          end
      end
    end

    doc = Nokogiri.XML("<foo><baz/><baz><bar name='test'/></baz></foo>")

    s = Time.now.to_f
    1.upto 50000 do |i|
      doc.root.xpath_fast1('//baz')
    end
    puts Time.now.to_f - s

    s = Time.now.to_f
    1.upto 50000 do |i|
      doc.root.xpath_fast2('//baz')
    end
    puts Time.now.to_f - s

The results (obviously no difference between ruby 1.9.3 und ruby 1.8.7 - almost the same numbers as most of the stuff is done by nokogiri:

fast1: 2.12183022499084
fast2: 0.841907024383545

Thats a massive speedup. Also note that NO namespace prefixes are used here, with lots of namespace prefixes the results are even better.

Sorry for using old-fashioned monkey-patching and time measurement ;-)

p.s.:

# Nokogiri (1.5.5)
    --- 
    nokogiri: 1.5.5
    warnings: []

    libxml: 
      binding: extension
      compiled: 2.7.8
      loaded: 2.7.8
    ruby: 
      engine: mri
      platform: i686-linux
      version: 1.8.7
      description: ruby 1.8.7 (2011-06-30 patchlevel 352) [i686-linux]```

# Nokogiri (1.5.5)
    ---
    warnings: []
    nokogiri: 1.5.5
    ruby:
      version: 1.9.3
      platform: i686-linux
      description: ruby 1.9.3p0 (2011-10-30 revision 33570) [i686-linux]
      engine: ruby
    libxml:
      binding: extension
      compiled: 2.7.8
      loaded: 2.7.8```
@etm

This comment has been minimized.

Show comment Hide comment
@etm

etm Oct 22, 2012

p.s.s. The problem that it is not reliable still remains (see comment 3 days ago). BUT, unless i'm doing something wrong, i think the numbers make this a worthwhile pursuit ;-). I'am looking into the reliability issue by adding #node for resetting in C - but i need some more time here.

etm commented Oct 22, 2012

p.s.s. The problem that it is not reliable still remains (see comment 3 days ago). BUT, unless i'm doing something wrong, i think the numbers make this a worthwhile pursuit ;-). I'am looking into the reliability issue by adding #node for resetting in C - but i need some more time here.

@kivikakk

This comment has been minimized.

Show comment Hide comment
@kivikakk

kivikakk Oct 22, 2012

Okay, so in your case the slowdown is because 50,000 new XPathContexts take half a second to allocate (xpath_fast1 only):

 %self     total     self     wait    child    calls   name
 23.53      0.83     0.58     0.00     0.25    50000   Nokogiri::XML::XPathContext#evaluate 
 20.23      0.49     0.49     0.00     0.00    50000   <Class::Nokogiri::XML::XPathContext>#new 
 18.92      2.21     0.46     0.00     1.75    50000   Nokogiri::XML::Node#xpath_fast1 
 10.23      0.25     0.25     0.00     0.00    50001   Nokogiri::XML::Document#decorate 
  5.57      0.32     0.14     0.00     0.18    50000   <Module::Nokogiri>#uses_libxml? 

Whether this is totally ridiculous or not, I can't really comment.

Okay, so in your case the slowdown is because 50,000 new XPathContexts take half a second to allocate (xpath_fast1 only):

 %self     total     self     wait    child    calls   name
 23.53      0.83     0.58     0.00     0.25    50000   Nokogiri::XML::XPathContext#evaluate 
 20.23      0.49     0.49     0.00     0.00    50000   <Class::Nokogiri::XML::XPathContext>#new 
 18.92      2.21     0.46     0.00     1.75    50000   Nokogiri::XML::Node#xpath_fast1 
 10.23      0.25     0.25     0.00     0.00    50001   Nokogiri::XML::Document#decorate 
  5.57      0.32     0.14     0.00     0.18    50000   <Module::Nokogiri>#uses_libxml? 

Whether this is totally ridiculous or not, I can't really comment.

@jvshahid

This comment has been minimized.

Show comment Hide comment
@jvshahid

jvshahid Nov 20, 2013

Member

Duplicate of #741. This pr #1004 has a fix and will be merged into master soon.

Member

jvshahid commented Nov 20, 2013

Duplicate of #741. This pr #1004 has a fix and will be merged into master soon.

@jvshahid jvshahid closed this Nov 20, 2013

@Tristramg

This comment has been minimized.

Show comment Hide comment
@Tristramg

Tristramg Jan 27, 2015

@jvshahid correct me if I’m wrong, but #1004 only concerns JRuby, while @etm was talking about mri.

I observed also a speedup with the suggested monkey patching, nokogiri 1.6.6.2 and ruby mri 2.1.0

@jvshahid correct me if I’m wrong, but #1004 only concerns JRuby, while @etm was talking about mri.

I observed also a speedup with the suggested monkey patching, nokogiri 1.6.6.2 and ruby mri 2.1.0

@etm

This comment has been minimized.

Show comment Hide comment
@etm

etm Jan 27, 2015

Yes. I'm talking about MRI. And the (preceived) problem still persists. And its not primarily about speedup (which could be reaped after solving this). Its about the behaviour of the following code:

require 'rubygems'
require 'nokogiri'

doc = Nokogiri.XML("<foo><baz/><baz><bar name='test'/></baz></foo>")
xpa = Nokogiri::XML::XPathContext.new(doc.root)

p xpa.evaluate('//baz').length # => 2
p xpa.evaluate('baz').length # => 2
p xpa.evaluate('foo').length # => 0 
p xpa.evaluate('//@name').length # => 1
p xpa.evaluate('//baz').length # => 2
p xpa.evaluate('baz').length # => 0
p xpa.evaluate('foo').length # => 1  

This code should output 2201220, it does output 2201201. I still think this results point at a bug.

etm commented Jan 27, 2015

Yes. I'm talking about MRI. And the (preceived) problem still persists. And its not primarily about speedup (which could be reaped after solving this). Its about the behaviour of the following code:

require 'rubygems'
require 'nokogiri'

doc = Nokogiri.XML("<foo><baz/><baz><bar name='test'/></baz></foo>")
xpa = Nokogiri::XML::XPathContext.new(doc.root)

p xpa.evaluate('//baz').length # => 2
p xpa.evaluate('baz').length # => 2
p xpa.evaluate('foo').length # => 0 
p xpa.evaluate('//@name').length # => 1
p xpa.evaluate('//baz').length # => 2
p xpa.evaluate('baz').length # => 0
p xpa.evaluate('foo').length # => 1  

This code should output 2201220, it does output 2201201. I still think this results point at a bug.

@flavorjones

This comment has been minimized.

Show comment Hide comment
@flavorjones

flavorjones Jan 28, 2015

Owner

Urgh, OK, reopening.

@etm - I'm curious why no objections were raised when this ticket was closed. Honestly, I thought this had been solved, and apologize for the confusion.

Owner

flavorjones commented Jan 28, 2015

Urgh, OK, reopening.

@etm - I'm curious why no objections were raised when this ticket was closed. Honestly, I thought this had been solved, and apologize for the confusion.

@flavorjones flavorjones reopened this Jan 28, 2015

@etm

This comment has been minimized.

Show comment Hide comment
@etm

etm Jan 28, 2015

Sorry, entirely my fault, must have missed the mail notification that it was closed :-) It bugs me not that much that I check back regularely. After all, it only occurs in a code path, that is currently not used that way in nokogiri, so this is understandably not high priority.

etm commented Jan 28, 2015

Sorry, entirely my fault, must have missed the mail notification that it was closed :-) It bugs me not that much that I check back regularely. After all, it only occurs in a code path, that is currently not used that way in nokogiri, so this is understandably not high priority.

@flavorjones

This comment has been minimized.

Show comment Hide comment
@flavorjones

flavorjones Feb 9, 2015

Owner

@etm There is definitely some weirdness going on here. Part of the issue is that libxml2 stores state in XPathContext, meaning that you shouldn't re-use it unless you know what you're doing. Calling Node#xpath will create a new context each time to avoid these stateful behaviors.

This is also probably the behavior that's causing slowness.

That aside, there's still something else going on in the JRuby port that I don't fully understand yet; I need to isolate the behavior with test cases. Wish I could be more specific at this time.

Owner

flavorjones commented Feb 9, 2015

@etm There is definitely some weirdness going on here. Part of the issue is that libxml2 stores state in XPathContext, meaning that you shouldn't re-use it unless you know what you're doing. Calling Node#xpath will create a new context each time to avoid these stateful behaviors.

This is also probably the behavior that's causing slowness.

That aside, there's still something else going on in the JRuby port that I don't fully understand yet; I need to isolate the behavior with test cases. Wish I could be more specific at this time.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment