libxml 2.8.0 test suite hangs on ruby 2.2

[graaff]

With ruby 2.2.0p0 (2014-12-25 revision 49005) [x86_64-linux] the libxml 2.8.0 test suite hangs indefinitely in a busy loop. The test suite does pass with other ruby versions, e.g. ruby 2.1.5p273 (2014-11-13 revision 48405) [x86_64-linux]

Loaded suite test/test_suite
Started
............................Node#properties is deprecated.  Use Node#[] instead.
..................Warning: failed to load external entity "i_dont_exist.xml".
.................................
DOCUMENT
version=1.0
encoding=utf-8
URL=/var/tmp/portage/dev-ruby/libxml-2.8.0/w...
standalone=true
  ELEMENT bands
    ATTRIBUTE genre
      TEXT
        content=metal
    ELEMENT m#C3#B6tley_cr#C3#BCe
      ATTRIBUTE country
        TEXT interned
          content=us
      TEXT
        content=M#C3#B6tley Cr#C3#BCe is an American heavy metal...
    ELEMENT iron_maiden
      ATTRIBUTE country
        TEXT interned
          content=uk
      TEXT
        content=Iron Maiden is a British heavy metal ban...
........................Parser.register_error_handler is deprecated.  Use Error.set_handler instead
......./var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_error.rb:150: warning: Passing no parameters to XML::Parser.new is deprecated.  Pass an instance of XML::Parser::Context instead.
XML::Parser#string is deprecated.  Use XML::Parser.string instead
XML::Parser#string is deprecated.  Use XML::Parser.string instead
./var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_error.rb:95: warning: already initialized constant STDERR
/var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_error.rb:101: warning: already initialized constant STDERR
/var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_error.rb:95: warning: previous definition of STDERR was here
.../var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_error.rb:79: warning: already initialized constant STDERR
/var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_error.rb:101: warning: previous definition of STDERR was here
/var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_error.rb:85: warning: already initialized constant STDERR
/var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_error.rb:79: warning: previous definition of STDERR was here
.Error: Invalid predicate.
xmlXPathEval: evaluation failed
.................N
===============================================================================
TestNamespaces#test_namespaces was redefined [test_namespaces(TestNamespaces)]
/var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_namespaces.rb:126:in `<class:TestNamespaces>'
===============================================================================
.........................................333333
.    ELEMENT bands
      ATTRIBUTE genre
        TEXT
          content=metal
      ELEMENT m#C3#B6tley_cr#C3#BCe
        ATTRIBUTE country
          TEXT
            content=us
        TEXT
          content=M#C3#B6tley Cr#C3#BCe is an American heavy metal...
      ELEMENT iron_maiden
        ATTRIBUTE country
          TEXT
            content=uk
        TEXT
          content=Iron Maiden is a British heavy metal ban...
......../var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_parser.rb:315: warning: Passing no parameters to XML::Parser.new is deprecated.  Pass an instance of XML::Parser::Context instead.
XML::Parser#document= is deprecated.  Use XML::Parser.document= instead
....../var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_parser.rb:326: warning: Passing no parameters to XML::Parser.new is deprecated.  Pass an instance of XML::Parser::Context instead.
XML::Parser#file is deprecated.  Use XML::Parser.file instead
.../var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_parser.rb:335: warning: Passing no parameters to XML::Parser.new is deprecated.  Pass an instance of XML::Parser::Context instead.
XML::Parser#io is deprecated.  Use XML::Parser.io instead
........./var/tmp/portage/dev-ruby/libxml-2.8.0/work/ruby22/libxml-2.8.0/test/tc_parser.rb:348: warning: Passing no parameters to XML::Parser.new is deprecated.  Pass an instance of XML::Parser::Context instead.
XML::Parser#string is deprecated.  Use XML::Parser.string instead
...........
...............set_error_handler is deprecated.  Use Error.set_handler instead
.set_error_handler is deprecated.  Use Error.set_handler instead
reset_error_handler is deprecated.  Use Error.reset_handler instead
.

[cfis]

Hmm, have you done any debugging into which test is hanging?

[graaff]

I've just retested with ruby 2.2.1p85 (2015-02-26 revision 49769) [x86_64-linux] and have some more information.

I'm observing the hang in tc_node_edit.rb in the test_merge method, while reading the 500 documents. Adding a counter shows that I'm getting from 0 to 160 and then the busy loop happens. ruby just sits using 100% memory with apparently constant memory.

Aha, and the 160 is not constant, I'm seeing different values here. I've even had a single run where it passed through test_merge, and then exhibited the same behavior later. In fact, commenting out tc_node_edit.rb in test_suite.rb does not solve the issue because later tests then seem to trigger it.

My best guess: a bug in ruby's GC is being triggered somehow. The ruby process doesn't listen to SIGTERM. I've added GC.start inside the 500.times loop and with that in place the test_merge test passes consistently every time.

[boutil]

Hi!

I'm observing a similar behavior on Debian with ruby2.2 (2.2.2p95).
It is triggered in my case by test_memory in test/tc_xpath.rb.

[simpl1g]

I have the same issue with 2.2 on Ubuntu in test_memory in test/tc_xpath.rb.

[cfis]

Yes, I sometimes see this too. It does seem to have to do with garbage collection, but after playing with it for a bit nothing obvious stands out yet.

[cfis]

Finally tracked this down!

[graaff]

Thanks! I no longer see test suite hangs with ruby22 and libxml 2.9.0.

[cfis]

Great - thanks for checking.