GC Crash (potential Nokogiri issue)

[yorickpeterse]

Another GC crash I bumped in yesterday and managed to re-trigger today: https://gist.githubusercontent.com/YorickPeterse/54683dc2bcd63fb9c2b9/raw/e85fd6e3710a1990608ce8fb922340674f0e8c30/gistfile1.txt

Currently not yet sure what's causing it, I'll continue to investigate during the day.

[yorickpeterse]

Some snippets from GDB in case I mess it up again:

(gdb) info locals
gc_data = {roots_ = @0x17644f0, handles_ = 0x17663a0, cached_handles_ = 0x1766520, global_cache_ = 0x7ffff7fd1010, threads_ = 0x1763758, global_handle_locations_ = 0x1766530, 
  llvm_state_ = 0x1a2ec40, young_bytes_allocated_ = 12582912, mature_bytes_allocated_ = 97109336, code_bytes_allocated_ = 15609056, symbol_bytes_allocated_ = 842848}
stats = {bytes_copied = 0, percentage_used = 0, promoted_objects = 0, lifetime = 0, excess_objects = 0}
__lsl_guard__ = {thread_ = 0x28ff630, lock_ = 0x1766498, locked_ = true, recursive_ = false}
(gdb) info args
this = 0x1766480
state = 0x7fffee033b80
gct = @0x7fffee034050: {<No data fields>}
call_frame = 0x7fffee034290
(gdb) p *this
$1 = {<rubinius::gc::WriteBarrier> = {lock_ = {lock_ = 0}, remember_set_ = 0x7fffd4b01b00, marked_set_ = 0x7fffe4000970}, <rubinius::Lockable> = {mutex_ = {<rubinius::Lock> = {
        _vptr$Lock = 0x16efcf0 <vtable for rubinius::Mutex+16>, locking_thread_ = 0x28ff630, lock_file_ = 0x11f2c4e <.L.str> "vm/object_memory.cpp", 
        lock_line_ = 511}, <rubinius::utilities::thread::Mutex> = {native_ = {__data = {__lock = 1, __count = 0, __owner = 14383, __nusers = 1, __kind = 2, __spins = 0, 
            __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = "\001\000\000\000\000\000\000\000/8\000\000\001\000\000\000\002", '\000' <repeats 22 times>, 
          __align = 1}, owner_ = 140737186920192}, <No data fields>}}, allocation_lock_ = {lock_ = 0}, inflation_lock_ = {lock_ = 0}, young_ = 0x1766950, mark_sweep_ = 0x1782a50, 
  immix_ = 0x1766b10, immix_marker_ = 0x1ca86f0, inflated_headers_ = 0x1782b10, capi_handles_ = 0x17663a0, 
  cached_capi_handles_ = {<std::_List_base<rubinius::capi::Handle*, std::allocator<rubinius::capi::Handle*> >> = {
      _M_impl = {<std::allocator<std::_List_node<rubinius::capi::Handle*> >> = {<__gnu_cxx::new_allocator<std::_List_node<rubinius::capi::Handle*> >> = {<No data fields>}, <No data fields>}, _M_node = {_M_next = 0x1766520, _M_prev = 0x1766520}}}, <No data fields>}, 
  global_capi_handle_locations_ = {<std::_List_base<rubinius::capi::GlobalHandle*, std::allocator<rubinius::capi::GlobalHandle*> >> = {
      _M_impl = {<std::allocator<std::_List_node<rubinius::capi::GlobalHandle*> >> = {<__gnu_cxx::new_allocator<std::_List_node<rubinius::capi::GlobalHandle*> >> = {<No data fields>}, <No data fields>}, _M_node = {_M_next = 0x2115240, _M_prev = 0x1827560}}}, <No data fields>}, code_manager_ = {static cDefaultChunkSize = 64, 
    static cGCTriggerThreshold = 67108864, mutex_ = {native_ = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 2, __spins = 0, __elision = 0, __list = {
            __prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 16 times>, "\002", '\000' <repeats 22 times>, __align = 0}, owner_ = 140737212573440}, shared_ = 0x1763690, 
    chunk_size_ = 64, first_chunk_ = 0x1772f90, last_chunk_ = 0x7fffd0d08b10, current_chunk_ = 0x7fffd0d08b10, current_index_ = 18, freed_resources_ = 0, 
    total_allocated_ = 30296480, total_freed_ = 14687424, gc_triggered_ = 0, bytes_used_ = 15609056}, mark_ = 2, young_gc_while_marking_ = 1, allow_gc_ = true, 
  mature_mark_concurrent_ = true, mature_gc_in_progress_ = false, young_gc_resize_ = false, slab_size_ = 4096, contention_lock_ = {native_ = {__data = {__lock = 0, __count = 0, 
        __owner = 0, __nusers = 0, __kind = 2, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
      __size = '\000' <repeats 16 times>, "\002", '\000' <repeats 22 times>, __align = 0}, owner_ = 140736844216064}, contention_var_ = {native_ = {__data = {__lock = 0, 
        __futex = 32, __total_seq = 16, __wakeup_seq = 16, __woken_seq = 16, __mutex = 0x17665d0, __nwaiters = 0, __broadcast_seq = 15}, 
      __size = "\000\000\000\000 \000\000\000\020\000\000\000\000\000\000\000\020\000\000\000\000\000\000\000\020\000\000\000\000\000\000\000\320ev\001\000\000\000\000\000\000\000\000\017\000\000", __align = 137438953472}}, shared_ = @0x1763690, collect_young_now = false, collect_mature_now = false, root_state_ = 0x1765d30, last_object_id = 2903661, 
  last_snapshot_id = 0, type_info = {0x0, 0x1788500, 0x17895a0, 0x1787180, 0x1766e10, 0x1766ec0, 0x1766fa0, 0x1767080, 0x1767160, 0x1767240, 0x1767320, 0x1767400, 0x17674e0, 
    0x17675d0, 0x17676b0, 0x1767790, 0x1767870, 0x1767950, 0x1767a30, 0x1767b10, 0x1767bf0, 0x1767cd0, 0x1767dc0, 0x1767ea0, 0x1767f80, 0x1768060, 0x1768140, 0x1768230, 
    0x1768310, 0x17683f0, 0x17684d0, 0x17685b0, 0x17870d0, 0x1787260, 0x1787340, 0x1787420, 0x1787500, 0x17875e0, 0x17876c0, 0x17877a0, 0x1787890, 0x1787980, 0x1787a60, 
    0x1787b40, 0x1787c20, 0x1787d00, 0x1787de0, 0x1787ed0, 0x1787fb0, 0x1788090, 0x1788180, 0x1788260, 0x1788340, 0x1788420, 0x17885e0, 0x1789140, 0x17887a0, 0x1788880, 
    0x1788960, 0x1788a40, 0x1788b20, 0x1788c00, 0x1788ce0, 0x1788dc0, 0x1788ea0, 0x1788f80, 0x1789060, 0x0, 0x17886c0, 0x1789220, 0x1789300, 0x17893e0, 0x17894c0, 0x1789680, 
    0x1789760, 0x1789840}, large_object_threshold = 51200, young_max_bytes = 100663296, young_autotune_factor = 8, young_autotune_size = true, gc_stats = {
    young_objects_allocated = {value = 339348064}, young_bytes_allocated = {value = 24388086024}, promoted_objects_allocated = {value = 6050594}, promoted_bytes_allocated = {
      value = 558281344}, mature_objects_allocated = {value = 2272291}, mature_bytes_allocated = {value = 1350270128}, young_collection_count = {value = 4797}, 
    full_collection_count = {value = 750}, total_young_collection_time = {value = 80263}, total_full_stop_collection_time = {value = 17465}, 
    total_full_concurrent_collection_time = {value = 439095}, last_young_collection_time = {value = 26}, last_full_stop_collection_time = {value = 31}, 
    last_full_concurrent_collection_time = {value = 522}}}
(gdb) p *state
$2 = {vm_ = 0x28ff630, vm_jit_ = 0x28ff7f8, shared_ = @0x1763690}
(gdb) p *call_frame
$3 = {previous = 0x7fffee034470, constant_scope_ = 0x7ffff557f470, dispatch_data = 0x0, compiled_code = 0x7ffff55847c8, flags = 40, ip_ = 1, optional_jit_data = 0x7fffdc005e80, 
  top_scope_ = 0x7fffc2ff88c8, scope = 0x7fffee034258, arguments = 0x7fffee0344e0, stk = 0x7fffee0342d8}

[yorickpeterse]

Data used in the rb_gc_mark call:

(gdb) frame
#5  0x000000000083e359 in rb_gc_mark (ptr=140736753360768) at vm/capi/gc.cpp:44
44            Object* res = capi::current_mark()->call(handle->object());
(gdb) info args
ptr = 140736753360768
(gdb) info locals
res = 0x7bdc85 <rubinius::Data::data()+21>
handle = 0x7fffd430df80
(gdb) p *ptr
$6 = 48
(gdb) p *res
$7 = {<rubinius::ObjectHeader> = {header = {f = {obj_type = rubinius::TranscodingType, zone = (rubinius::MatureObjectZone | rubinius::YoungObjectZone), age = 2, 
        meaning = rubinius::eAuxWordLock, Forwarded = 0, Remember = 0, Marked = 0, InImmix = 1, Pinned = 0, Frozen = 0, Tainted = 0, Untrusted = 0, LockContended = 0, unused = 1, 
        aux_word = 281314120}, flags64 = 1208234945575684936}, klass_ = 0x48e589485590c35d, ivars_ = 0x48f07d894820ec83, __body__ = 0x7bdc9d <rubinius::Data::free()+13>}, 
  static type = rubinius::ObjectType}
(gdb) p *handle
$8 = {object_ = 0x30, type_ = 193, references_ = 0, checksum_ = 3562094064, flush_ = 0x7fffd42dec00, update_ = 0x7fffc3748990, as_ = {rarray = 0x1, rstring = 0x1, rdata = 0x1, 
    rtypeddata = 0x1, rfloat = 0x1, rio = 0x1, rfile = 0x1, next_index_ = 1, cache_data = 1}}

[yorickpeterse]

And from the call to ObjectMark::call:

(gdb) info args
this = 0x7fffee0336c8
obj = 0x30
(gdb) frame
#4  0x00000000008675cd in rubinius::ObjectMark::call (this=0x7fffee0336c8, obj=0x30) at vm/gc/object_mark.cpp:28
28          return gc->saw_object(obj);
(gdb) p obj
$10 = (rubinius::Object *) 0x30

[yorickpeterse]

Recompiled Nokogiri with DEV=1 as I suspect it might (again) be the culprit. So far this indeed looks to be the case: https://gist.githubusercontent.com/YorickPeterse/54683dc2bcd63fb9c2b9/raw/2d4461fd667667619469875d1b05399b9c2247f6/dev_output.txt

I'll continue to verify to see if I'm not secretly running some outdated version of something and whether or not it truly is Nokogiri.

[yorickpeterse]

Data in Nokogiri's mark function:

(gdb) bt
#0  rubinius::ObjectHeader::flags (this=0x30) at /home/yorickpeterse/Private/Projects/ruby/rubinius/vm/oop.hpp:339
#1  0x00000000005c8ea5 in rubinius::ObjectHeader::zone (this=0x30) at /home/yorickpeterse/Private/Projects/ruby/rubinius/vm/oop.hpp:343
#2  0x00000000005c8e75 in rubinius::ObjectHeader::young_object_p (this=0x30) at /home/yorickpeterse/Private/Projects/ruby/rubinius/vm/oop.hpp:446
#3  0x0000000000852552 in rubinius::BakerGC::saw_object (this=0x1766950, obj=0x30) at vm/gc/baker.cpp:86
#4  0x00000000008675cd in rubinius::ObjectMark::call (this=0x7fffd8d73458, obj=0x30) at vm/gc/object_mark.cpp:28
#5  0x000000000083e359 in rb_gc_mark (ptr=140736561884512) at vm/capi/gc.cpp:44
#6  0x00007ffff5e24932 in mark (node=0x7fffc82438a0) at xml_node.c:23
#7  0x00000000007bde03 in rubinius::Data::Info::mark (this=0x1768310, t=0x7fffc3df7ca8, mark=...) at vm/builtin/data.cpp:155
#8  0x0000000000859b23 in rubinius::GarbageCollector::scan_object (this=0x1766950, obj=0x7fffc3df7ca8) at vm/gc/gc.cpp:108
#9  0x0000000000852c99 in rubinius::BakerGC::collect (this=0x1766950, data=0x7fffd8d73850, stats=0x7fffd8d73830) at vm/gc/baker.cpp:215
#10 0x0000000000737167 in rubinius::ObjectMemory::collect_young (this=0x1766480, state=0x7fffd8d73910, data=0x7fffd8d73850, stats=0x7fffd8d73830) at vm/object_memory.cpp:574
#11 0x0000000000736e9a in rubinius::ObjectMemory::collect_maybe (this=0x1766480, state=0x7fffd8d73910, gct=..., call_frame=0x7fffd8d74398) at vm/object_memory.cpp:531
#12 0x00000000007a4234 in rubinius::VM::collect_maybe (this=0x2947f70, gct=..., call_frame=0x7fffd8d74398) at vm/vm.cpp:310
#13 0x00000000007b781c in rubinius::(anonymous namespace)::collect_and_allocate (state=0x7fffd8dc7ee8, gct=..., self=0x2669050, calling_environment=0x7fffd8d74398)
    at vm/builtin/class.cpp:66
#14 0x00000000007b6886 in rubinius::(anonymous namespace)::allocate_packed (state=0x7fffd8dc7ee8, gct=..., self=0x2669050, calling_environment=0x7fffd8d74398)
    at vm/builtin/class.cpp:114
#15 0x00000000007b6358 in rubinius::Class::allocate (this=0x2669050, state=0x7fffd8dc7ee8, gct=..., calling_environment=0x7fffd8d74398) at vm/builtin/class.cpp:133
#16 0x00000000008fd593 in rbx_create_instance (state=0x7fffd8dc7ee8, call_frame=0x7fffd8d74398, cls=0x2669050) at vm/llvm/jit_util.cpp:1430
#17 0x00007fffef97941d in ?? ()
#18 0x00000000017f2aa0 in ?? ()
#19 0x00007fffc1ad4738 in ?? ()
#20 0x00007fffd8d73ec0 in ?? ()
#21 0x0000000000000000 in ?? ()
(gdb) info locals
doc = 0x7fffc8032140
(gdb) info args
node = 0x7fffc82438a0
(gdb) p *doc
$3 = {_private = 0x7fffc8c72d60, type = 3363466368, name = 0x0, children = 0x7fffc8018f20, last = 0x7fffc8b0fcc0, parent = 0x0, next = 0x0, prev = 0x0, doc = 0x7fffc8032140, 
  ns = 0x100000000, content = 0x0, properties = 0x0, nsDef = 0x0, psvi = 0x0, line = 36448, extra = 51374}
(gdb) p *node
$4 = {_private = 0x7fffc819ee20, type = XML_ELEMENT_NODE, name = 0x7fffc8243880 "\320E\"\310\377\177", children = 0x7fffc82437b0, last = 0x7fffc82437b0, parent = 0x7fffc83776b0, 
  next = 0x7fffc819eed0, prev = 0x7fffc8377550, doc = 0x7fffc8032140, ns = 0x0, content = 0x0, properties = 0x7fffc8377620, nsDef = 0x0, psvi = 0x0, line = 160, extra = 0}

[yorickpeterse]

Closing this in favour of sparklemotion/nokogiri#1047