NoMethodError#message takes very long

Discussion in 'Ruby' started by Adiel Mittmann, Mar 16, 2011.

  1. Hello.

    I've been noticing a problem for a while in a larger application and today I
    produced a minimal example, given below. When a method is not found, Sinatra
    calls NoMethodError#message to display a nice error message, but that is taking
    VERY long.

    <snip>
    require 'sinatra'
    require 'nokogiri'
    get '/' do
    @xml = Nokogiri::XML(File.new('baz.xml', 'rb').read())
    foo()
    'hello'
    end
    </snip>

    The file 'baz.xml' can be just a simple file, like a root element containing
    some thousands of elements. The number of elements is important because, oddly
    enough, the time taken for the message to be displayed is proportional to the
    size of the XML file. In my system, with a 3.7 MB file this program takes almost
    13 seconds to print the message, but in a larger application the message takes a
    few minutes to appear.

    You can try to print the line yourself instead, but that also takes very long:

    <snip>
    begin
    foo()
    rescue ::Exception => boom
    puts boom.message
    end
    <snip>

    I don't know where the error might be. The code above looks too innocent to
    cause such a weird behavior, and I don't see how either Nokogiri or Sinatra
    could be involved, although both of them are required to reproduce the problem.

    I'm using Ruby 1.9.2p180, Nokogiri 1.4.4 and Sinatra 1.2.0.

    Any help would be greatly appreciated!

    --
    Adiel Mittmann
    Adiel Mittmann, Mar 16, 2011
    #1
    1. Advertising

  2. Adiel Mittmann

    Eric Hodel Guest

    On Mar 15, 2011, at 8:25 PM, Adiel Mittmann wrote:

    > Hello.
    >=20
    > I've been noticing a problem for a while in a larger application and =

    today I
    > produced a minimal example, given below. When a method is not found, =

    Sinatra
    > calls NoMethodError#message to display a nice error message, but that =

    is taking
    > VERY long.
    >=20
    > <snip>
    > require 'sinatra'
    > require 'nokogiri'
    > get '/' do
    > @xml =3D Nokogiri::XML(File.new('baz.xml', 'rb').read())
    > foo()
    > 'hello'
    > end
    > </snip>
    >=20
    > The file 'baz.xml' can be just a simple file, like a root element =

    containing
    > some thousands of elements. The number of elements is important =

    because, oddly
    > enough, the time taken for the message to be displayed is proportional =

    to the
    > size of the XML file. In my system, with a 3.7 MB file this program =

    takes almost
    > 13 seconds to print the message, but in a larger application the =

    message takes a
    > few minutes to appear.


    Let me see if I have this straight:

    If baz.xml is empty it is fast
    If baz.xml is large it is slow

    If this is true it is because it takes time to parse the XML file before =
    it gets to foo and discovers that there is no method foo.

    Ruby does not know that foo does not exist until you try to call it.=
    Eric Hodel, Mar 16, 2011
    #2
    1. Advertising

  3. On Wed, Mar 16, 2011 at 7:24 AM, Eric Hodel <> wrote:
    > On Mar 15, 2011, at 8:25 PM, Adiel Mittmann wrote:
    >
    >> Hello.
    >>
    >> I've been noticing a problem for a while in a larger application and tod=

    ay I
    >> produced a minimal example, given below. When a method is not found, Sin=

    atra
    >> calls NoMethodError#message to display a nice error message, but that is=

    taking
    >> VERY long.
    >>
    >> <snip>
    >> require 'sinatra'
    >> require 'nokogiri'
    >> get '/' do
    >> =A0@xml =3D Nokogiri::XML(File.new('baz.xml', 'rb').read())
    >> =A0foo()
    >> =A0'hello'
    >> end
    >> </snip>
    >>
    >> The file 'baz.xml' can be just a simple file, like a root element contai=

    ning
    >> some thousands of elements. The number of elements is important because,=

    oddly
    >> enough, the time taken for the message to be displayed is proportional t=

    o the
    >> size of the XML file. In my system, with a 3.7 MB file this program take=

    s almost
    >> 13 seconds to print the message, but in a larger application the message=

    takes a
    >> few minutes to appear.

    >
    > Let me see if I have this straight:
    >
    > If baz.xml is empty it is fast
    > If baz.xml is large it is slow
    >
    > If this is true it is because it takes time to parse the XML file before =

    it gets to foo and discovers that there is no method foo.
    >
    > Ruby does not know that foo does not exist until you try to call it.


    Additional remarks: the file is not properly closed and reading the
    whole file in one go is probably also not a good solution. I'd rather

    require 'sinatra'
    require 'nokogiri'
    get '/' do
    @xml =3D File.open('baz.xml', 'rb') {|io| Nokogiri::XML(io)}
    foo()
    'hello'
    end

    Note, the fact that you read in a large file as one String can
    actually be related to your slowness because it might case GC
    overhead.

    Cheers

    robert

    --=20
    remember.guy do |as, often| as.you_can - without end
    http://blog.rubybestpractices.com/
    Robert Klemme, Mar 16, 2011
    #3
  4. Hello.

    On Wed, Mar 16, 2011 at 03:24:29PM +0900, Eric Hodel wrote:
    > Let me see if I have this straight:
    >
    > If baz.xml is empty it is fast
    > If baz.xml is large it is slow
    >
    > If this is true it is because it takes time to parse the XML file before it gets to foo and discovers that there is no method foo.
    >
    > Ruby does not know that foo does not exist until you try to call it.


    The thing is: if method foo is not called at all, and thus no exception is
    raised, the resulting web page is shown quickly enough. Nokogiri is pretty fast
    at parsing XML files.

    It only takes long when the inexistent method foo() is called and the pogram
    tries to print the exception message.

    Yes, I know this is *very*, *very* weird. Can anybody try to reproduce this bug?
    The code snippet is very simple and it shouldn't take more than a couple
    minutes.

    Thanks for the reply.

    --
    Adiel Mittmann
    Adiel Mittmann, Mar 16, 2011
    #4
  5. On Wed, Mar 16, 2011 at 1:15 PM, Adiel Mittmann <> wrote:
    > Hello.
    >
    > On Wed, Mar 16, 2011 at 03:24:29PM +0900, Eric Hodel wrote:
    >> Let me see if I have this straight:
    >>
    >> If baz.xml is empty it is fast
    >> If baz.xml is large it is slow
    >>
    >> If this is true it is because it takes time to parse the XML file before it gets to foo and discovers that there is no method foo.
    >>
    >> Ruby does not know that foo does not exist until you try to call it.

    >
    > The thing is: if method foo is not called at all, and thus no exception is
    > raised, the resulting web page is shown quickly enough. Nokogiri is pretty fast
    > at parsing XML files.
    >
    > It only takes long when the inexistent method foo() is called and the pogram
    > tries to print the exception message.
    >
    > Yes, I know this is *very*, *very* weird. Can anybody try to reproduce this bug?
    > The code snippet is very simple and it shouldn't take more than a couple
    > minutes.


    Not if one does not have the environment installed. Did you try the
    suggested change?

    Cheers

    robert


    --
    remember.guy do |as, often| as.you_can - without end
    http://blog.rubybestpractices.com/
    Robert Klemme, Mar 16, 2011
    #5
  6. Hello.

    On Wed, Mar 16, 2011 at 09:08:42PM +0900, Robert Klemme wrote:
    > Additional remarks: the file is not properly closed and reading the
    > whole file in one go is probably also not a good solution. I'd rather
    >
    > require 'sinatra'
    > require 'nokogiri'
    > get '/' do
    > @xml = File.open('baz.xml', 'rb') {|io| Nokogiri::XML(io)}
    > foo()
    > 'hello'
    > end
    >
    > Note, the fact that you read in a large file as one String can
    > actually be related to your slowness because it might case GC
    > overhead.


    That is indeed a better way to read the file, thanks for pointing it out.

    The same problem happens with the code you suggested, however.

    In any case, did you test any of the variants? Was it very slow as in my case?

    Thank you for your reply.

    --
    Adiel Mittmann
    Adiel Mittmann, Mar 16, 2011
    #6
  7. Hi, I discovered what's causing the problem.

    Ruby's function name_err_mesg_to_str (file error.c, line 929, SVN snapshot),
    which produces the dreaded message, proceeds as follows:

    1. It converts the object that does not possess the method in question to a
    string, by calling #inspect;

    2. If it doesn't like that string (i.e., if it's nil or is bigger than 65
    characters), then it creates a simpler representation and use it instead.

    In other words, if you happen to call a method on an object that doesn't define
    to_s but that does contain a lot of data, then calling an undefined method and
    trying to print the resulting exception's message will take a long time because
    all the data in the object will have to be converted to a string -- just to be
    discarded.

    Maybe in a case like this the message should always return the simpler
    representation of the object instead of calling to_s?

    --
    Adiel Mittmann
    Adiel Mittmann, Mar 16, 2011
    #7
  8. On Wed, Mar 16, 2011 at 10:28 PM, Adiel Mittmann <> wrote:
    > Hi, I discovered what's causing the problem.
    >
    > Ruby's function name_err_mesg_to_str (file error.c, line 929, SVN snapshot),
    > which produces the dreaded message, proceeds as follows:
    >
    > 1. It converts the object that does not possess the method in question to a
    > string, by calling #inspect;
    >
    > 2. If it doesn't like that string (i.e., if it's nil or is bigger than 65
    > characters), then it creates a simpler representation and use it instead.
    >
    > In other words, if you happen to call a method on an object that doesn't define
    > to_s but that does contain a lot of data, then calling an undefined method and
    > trying to print the resulting exception's message will take a long time because
    > all the data in the object will have to be converted to a string -- just to be
    > discarded.
    >
    > Maybe in a case like this the message should always return the simpler
    > representation of the object instead of calling to_s?


    I'd rather provide a custom #inspect method for objects which may
    contain potentially large volumes of data. Nobody can read that
    anyway when printed on console or somewhere else.

    Kind regards

    robert

    --
    remember.guy do |as, often| as.you_can - without end
    http://blog.rubybestpractices.com/
    Robert Klemme, Mar 17, 2011
    #8
  9. Hello.

    On Thu, Mar 17, 2011 at 05:07:47PM +0900, Robert Klemme wrote:
    > I'd rather provide a custom #inspect method for objects which may
    > contain potentially large volumes of data. Nobody can read that
    > anyway when printed on console or somewhere else.


    I agree with you: if I am going to print out a big object to the console, it's
    better to provide a custom #inspect in order to generate a nice summary.

    However, I find it odd that I *must* write such a method for all big objects,
    regardless of whether I'm ever going to print them out or not -- because
    otherwise my program may eventually freeze for up to a few minutes doing the
    very complicated task of telling me that some method didn't exist :)

    --
    Adiel Mittmann
    Adiel Mittmann, Mar 17, 2011
    #9
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. Replies:
    4
    Views:
    1,002
    David Bishop
    Jun 16, 2005
  2. =?Utf-8?B?cHJhc2hhbnRo?=
    Replies:
    4
    Views:
    509
    Lau Lei Cheong
    Jan 20, 2006
  3. Raymond Arthur St. Marie II of III

    very Very VERY dumb Question About The new Set( ) 's

    Raymond Arthur St. Marie II of III, Jul 23, 2003, in forum: Python
    Replies:
    4
    Views:
    470
    Raymond Hettinger
    Jul 27, 2003
  4. shanx__=|;-

    very very very long integer

    shanx__=|;-, Oct 16, 2004, in forum: C Programming
    Replies:
    19
    Views:
    1,615
    Merrill & Michele
    Oct 19, 2004
  5. Abhishek Jha

    very very very long integer

    Abhishek Jha, Oct 16, 2004, in forum: C Programming
    Replies:
    4
    Views:
    418
    jacob navia
    Oct 17, 2004
Loading...

Share This Page