From: merante.joe@... Date: 2015-06-09T14:29:26+00:00 Subject: [ruby-core:69504] [Ruby trunk - Bug #10803] Similar issue/stack trace as above in 2.1.5, 2.1.6 Issue #10803 has been updated by Joe Merante. Subject changed from 2.1.5: rb_gc_mark() to Similar issue/stack trace as above in 2.1.5, 2.1.6 ruby -v changed from ruby 2.1.5p273 (2014-11-13 revision 48405) [x86_64-darwin14.0] to ruby 2.1.6p336 (2015-04-13 revision 50298) [x86_64-darwin13.0] Backport deleted (2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN) Hi, We've been experiencing a similar issue for the last few weeks when trying to process a large (125mb, with about 12,000 nodes) xml file using Nokogiri. While we initially thought the issue was due to the proliferation of objects generated using Nokogiri Slop (as we watched the memory used gradually increase toward 100% on the Mac until the error), we refactored to use Nokogiri::XML::Element's and the same problem occurred, with pretty much the same stack trace, leading us to think it's a Ruby issue. We also tried chunking the file into separate files of ~50 nodes each and processing one file at a time, and the same errors occurred. The nodes range in size from about 2K to about 700K. While I can't share the exact code unfortunately, below is a brief description along with the the stack trace in the hopes it helps determine resolution of the issue! We've encountered this using Ruby 2.1.5 and 2.1.6, each on Mac OS X 10.9.5 (Mavericks) and Yosemite, and with both Ruby versions on Gentoo 2.1. Thanks for any help and all your hard work. Joe ===description of how the code works 1) create a Proc to add an ActiveRecord object (Temp) which stores raw xml in our database, pass this proc and the file path to an object (Processor) for processing 2) Processor uses Saxerator, a wrapper around Nokogiri::Sax, to grab one node at a time from the file and pass it into the proc to create an ActiveRecord Temp object. This is successful, whether a few nodes or 12,000 (the max we've tried) 3) We then iterate through (using ActiveRecord's #find_each, with batch size of 1000) to pass the Temp objects into another object to pull out values using Nokogiri on the raw xml contained in each Temp object to create a new FinalObject, then delete the Temp object Note that the use of a Temp object to store xml in the database was only after encountering this bug when trying to read in the file and process each node directly into a FinalObject in the database. The trace below occurs, sometimes on the 6,000th Temp object in step 3, sometimes on one of the first ones in step 3 ===stack trace /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/nokogiri-1.6.6.2/lib/nokogiri/xml/searchable.rb:157: [BUG] rb_gc_mark(): 0x007f8f67b0b5a0 is T_NONE ruby 2.1.6p336 (2015-04-13 revision 50298) [x86_64-darwin13.0] -- Crash Report log information -------------------------------------------- See Crash Report log file under the one of following: * ~/Library/Logs/CrashReporter * /Library/Logs/CrashReporter * ~/Library/Logs/DiagnosticReports * /Library/Logs/DiagnosticReports for more details. -- Control frame information ----------------------------------------------- c:0054 p:---- s:0234 e:000233 CFUNC :new c:0053 p:0014 s:0230 e:000229 BLOCK /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/nokogiri-1.6.6.2/lib/nokogiri/xml/searchable.rb:157 [FINISH] c:0052 p:---- s:0226 e:000225 CFUNC :map c:0051 p:0050 s:0223 e:000222 METHOD /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/nokogiri-1.6.6.2/lib/nokogiri/xml/searchable.rb:156 c:0050 p:0010 s:0214 e:000213 BLOCK /Users/digital/dev/OURFILE.rb [FINISH] c:0049 p:---- s:0212 e:000211 CFUNC :call c:0048 p:0016 s:0209 e:000206 METHOD /Users/digital/dev/OURFILE.rb c:0047 p:0134 s:0201 E:001e78 METHOD /Users/digital/dev/OURFILE.rb [FINISH] c:0046 p:---- s:0196 e:000195 CFUNC :new c:0045 p:0020 s:0191 e:000190 BLOCK /Users/digital/dev/OURFILE.rb [FINISH] c:0044 p:---- s:0188 e:000187 CFUNC :collect c:0043 p:0024 s:0185 e:000184 METHOD /Users/digital/dev/OURFILE.rb c:0042 p:0007 s:0182 e:000181 METHOD /Users/digital/dev/OURFILE.rb c:0041 p:0008 s:0179 e:000178 METHOD /Users/digital/OURFILE.rb c:0040 p:0013 s:0172 e:000171 METHOD /Users/digital/OURFILE.rb c:0039 p:0024 s:0166 e:000165 BLOCK /Users/digital/OURFILE.rb c:0038 p:0193 s:0164 e:000163 METHOD /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/activerecord-3.2.21/lib/active_record/connection_adapters/abstract c:0037 p:0017 s:0155 e:000154 METHOD /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/activerecord-3.2.21/lib/active_record/transactions.rb:208 c:0036 p:0043 s:0150 E:0026e8 BLOCK /Users/digital/OURFILE.rb [FINISH] c:0035 p:---- s:0144 e:000143 CFUNC :each c:0034 p:0052 s:0141 E:002670 METHOD /Users/digital/OURFILE.rb c:0033 p:0067 s:0135 e:000134 BLOCK /Users/digital/OURFILE.rb c:0032 p:0008 s:0130 e:000129 BLOCK /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/activerecord-3.2.21/lib/active_record/relation/batches.rb:21 [FINISH] c:0031 p:---- s:0127 e:000126 CFUNC :each c:0030 p:0008 s:0124 E:000230 BLOCK /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/activerecord-3.2.21/lib/active_record/relation/batches.rb:21 c:0029 p:0224 s:0121 E:0026c8 METHOD /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/activerecord-3.2.21/lib/active_record/relation/batches.rb:72 c:0028 p:0013 s:0110 E:001bd0 METHOD /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/activerecord-3.2.21/lib/active_record/relation/batches.rb:20 c:0027 p:0015 s:0106 E:000a28 METHOD /usr/local/var/rbenv/versions/2.1.6/lib/ruby/gems/2.1.0/gems/activerecord-3.2.21/lib/active_record/querying.rb:8 c:0026 p:0023 s:0101 E:000408 METHOD /Users/digital/OURFILE.rb c:0025 p:0015 s:0098 E:002368 EVAL (pry):1 [FINISH] .... -- C level backtrace information ------------------------------------------- 0 ruby 0x000000010ed961c0 rb_vm_bugreport + 144 1 ruby 0x000000010ec476d1 report_bug + 305 2 ruby 0x000000010ec47594 rb_bug + 180 3 ruby 0x000000010ec686fe gc_mark_children + 2830 4 ruby 0x000000010ec6fc9e gc_marks_body + 670 5 ruby 0x000000010ec6d9bb garbage_collect_body + 859 6 ruby 0x000000010ec66587 garbage_collect + 407 7 ruby 0x000000010ec6cf1d garbage_collect_with_gvl + 61 8 ruby 0x000000010ec68e34 objspace_xmalloc + 196 9 nokogiri.bundle 0x000000010f70387c xmlHashCreate + 124 10 nokogiri.bundle 0x000000010f74cb5f xmlXPathNewContext + 207 11 nokogiri.bundle 0x000000010f69761c new + 44 12 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 13 ruby 0x000000010ed7ba9d vm_exec_core + 11933 14 ruby 0x000000010ed8a461 vm_exec + 129 15 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 16 ruby 0x000000010ed86c78 rb_yield + 184 17 ruby 0x000000010ec124f9 rb_ary_collect + 137 18 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 19 ruby 0x000000010ed7b8d3 vm_exec_core + 11475 20 ruby 0x000000010ed8a461 vm_exec + 129 21 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 22 ruby 0x000000010ed8967a vm_invoke_proc + 186 23 ruby 0x000000010ed895b0 rb_vm_invoke_proc + 32 24 ruby 0x000000010ec577d5 proc_call + 117 25 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 26 ruby 0x000000010ed7ba9d vm_exec_core + 11933 27 ruby 0x000000010ed8a461 vm_exec + 129 28 ruby 0x000000010ed91a8e vm_call0_body + 814 29 ruby 0x000000010ed8349f rb_funcallv + 207 30 ruby 0x000000010eca7a69 rb_class_new_instance + 41 31 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 32 ruby 0x000000010ed7ba9d vm_exec_core + 11933 33 ruby 0x000000010ed8a461 vm_exec + 129 34 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 35 ruby 0x000000010ed86c78 rb_yield + 184 36 ruby 0x000000010ec124f9 rb_ary_collect + 137 37 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 38 ruby 0x000000010ed7b8d3 vm_exec_core + 11475 39 ruby 0x000000010ed8a461 vm_exec + 129 40 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 41 ruby 0x000000010ed86c78 rb_yield + 184 42 ruby 0x000000010ec0d099 rb_ary_each + 73 43 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 44 ruby 0x000000010ed7b8d3 vm_exec_core + 11475 45 ruby 0x000000010ed8a461 vm_exec + 129 46 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 47 ruby 0x000000010ed86c78 rb_yield + 184 48 ruby 0x000000010ec0d099 rb_ary_each + 73 49 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 50 ruby 0x000000010ed7b8d3 vm_exec_core + 11475 51 ruby 0x000000010ed8a461 vm_exec + 129 52 ruby 0x000000010ed90e0f eval_string_with_cref + 1631 53 ruby 0x000000010ed87661 rb_f_eval + 161 54 ruby 0x000000010ec59325 bind_eval + 85 55 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 56 ruby 0x000000010ed94312 vm_call_method + 866 57 ruby 0x000000010ed7ba9d vm_exec_core + 11933 58 ruby 0x000000010ed8a461 vm_exec + 129 59 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 60 ruby 0x000000010ed90788 catch_i + 88 61 ruby 0x000000010ed88399 rb_catch_protect + 185 62 ruby 0x000000010ed8892c rb_f_catch + 76 63 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 64 ruby 0x000000010ed94312 vm_call_method + 866 65 ruby 0x000000010ed7b8d3 vm_exec_core + 11475 66 ruby 0x000000010ed8a461 vm_exec + 129 67 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 68 ruby 0x000000010ed90788 catch_i + 88 69 ruby 0x000000010ed88399 rb_catch_protect + 185 70 ruby 0x000000010ed8892c rb_f_catch + 76 71 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 72 ruby 0x000000010ed94312 vm_call_method + 866 73 ruby 0x000000010ed7b8d3 vm_exec_core + 11475 74 ruby 0x000000010ed8a461 vm_exec + 129 75 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 76 ruby 0x000000010ed906e1 loop_i + 49 77 ruby 0x000000010ec50b16 rb_rescue2 + 278 78 ruby 0x000000010ed889b3 rb_f_loop + 51 79 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 80 ruby 0x000000010ed94312 vm_call_method + 866 81 ruby 0x000000010ed7b8d3 vm_exec_core + 11475 82 ruby 0x000000010ed8a461 vm_exec + 129 83 ruby 0x000000010ed8f095 invoke_block_from_c + 2213 84 ruby 0x000000010ed8967a vm_invoke_proc + 186 85 ruby 0x000000010ed895b0 rb_vm_invoke_proc + 32 86 ruby 0x000000010ec577d5 proc_call + 117 87 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 88 ruby 0x000000010ed94312 vm_call_method + 866 89 ruby 0x000000010ed7ba9d vm_exec_core + 11933 90 ruby 0x000000010ed8a461 vm_exec + 129 91 ruby 0x000000010ed8a3a0 rb_iseq_eval + 288 92 ruby 0x000000010ec54f47 rb_load_internal0 + 311 93 ruby 0x000000010ec5453e rb_require_safe + 1598 94 ruby 0x000000010ed949c7 vm_call_cfunc + 1063 95 ruby 0x000000010ed94312 vm_call_method + 866 96 ruby 0x000000010ed7ba9d vm_exec_core + 11933 97 ruby 0x000000010ed8a461 vm_exec + 129 98 ruby 0x000000010ed8b3ec rb_iseq_eval_main + 396 99 ruby 0x000000010ec4ffa4 ruby_exec_internal + 148 100 ruby 0x000000010ec4fece ruby_run_node + 78 101 ruby 0x000000010ec0a79f main + 79 ---------------------------------------- Bug #10803: Similar issue/stack trace as above in 2.1.5, 2.1.6 https://bugs.ruby-lang.org/issues/10803#change-52807 * Author: Gabriel Mazetto * Status: Feedback * Priority: Normal * Assignee: Koichi Sasada * ruby -v: ruby 2.1.6p336 (2015-04-13 revision 50298) [x86_64-darwin13.0] * Backport: ---------------------------------------- ~~~ /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/bundler/gems/syck-358913870211/lib/syck.rb:136: [BUG] rb_gc_mark(): 0x007f96aa63a888 is T_NONE ruby 2.1.5p273 (2014-11-13 revision 48405) [x86_64-darwin14.0] -- Control frame information ----------------------------------------------- c:0053 p:---- s:0202 e:000201 CFUNC :load c:0052 p:0011 s:0198 e:000197 METHOD /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/bundler/gems/syck-358913870211/lib/syck.rb:136 c:0051 p:0009 s:0194 e:000193 BLOCK /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/bundler/gems/syck-358913870211/lib/syck.rb:147 [FINISH] c:0050 p:---- s:0191 e:000190 CFUNC :open c:0049 p:0015 s:0187 e:000186 METHOD /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/bundler/gems/syck-358913870211/lib/syck.rb:146 c:0048 p:0044 s:0183 e:000182 METHOD /myapp/app/models/component/default_field.rb:46 c:0047 p:0021 s:0180 e:000179 METHOD /myapp/app/models/component/default_field.rb:42 c:0046 p:0007 s:0177 e:000176 METHOD /myapp/app/models/component/default_field.rb:4 c:0045 p:0031 s:0174 e:000173 BLOCK /myapp/app/models/conversion/content_processor.rb:26 [FINISH] c:0044 p:---- s:0169 e:000168 CFUNC :each c:0043 p:0011 s:0166 e:000165 METHOD /myapp/app/models/conversion/content_processor.rb:24 c:0042 p:0013 s:0163 e:000162 METHOD /myapp/app/models/conversion/content_processor.rb:14 c:0041 p:0034 s:0160 e:000159 METHOD /myapp/app/models/conversion/conversion_importer.rb:32 c:0040 p:0032 s:0155 e:000153 BLOCK /myapp/app/models/conversion/conversion_importer.rb:26 [FINISH] c:0039 p:---- s:0151 e:000150 CFUNC :each c:0038 p:0015 s:0148 e:000147 METHOD /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-3.2.18/lib/active_record/relation/delegation.rb:6 c:0037 p:0015 s:0143 E:001c30 METHOD /myapp/app/models/conversion/conversion_importer.rb:24 c:0036 p:0007 s:0139 e:000138 METHOD /myapp/app/models/conversion/conversion_importer.rb:10 c:0035 p:0073 s:0135 e:000134 METHOD /myapp/app/models/conversion/lead_importer.rb:45 c:0034 p:0019 s:0132 e:000131 METHOD /myapp/app/models/conversion/lead_importer.rb:15 c:0033 p:0030 s:0129 e:000128 METHOD /myapp/app/models/conversion.rb:83 c:0032 p:0026 s:0126 e:000125 METHOD /myapp/app/models/conversion.rb:17 c:0031 p:0031 s:0122 e:000121 BLOCK /myapp/app/models/lead/import.rb:206 c:0030 p:0193 s:0119 e:000118 METHOD /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-3.2.18/lib/active_record/connection_adapters/abstract/database_statemen c:0029 p:0017 s:0110 e:000109 METHOD /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-3.2.18/lib/active_record/transactions.rb:208 c:0028 p:0015 s:0105 E:000700 BLOCK /myapp/app/models/lead/import.rb:204 [FINISH] c:0027 p:---- s:0102 e:000101 IFUNC c:0026 p:---- s:0100 e:000099 CFUNC :each c:0025 p:---- s:0098 e:000097 CFUNC :each_slice c:0024 p:0024 s:0094 E:000958 METHOD /myapp/app/models/lead/import.rb:203 c:0023 p:0014 s:0091 E:000e48 METHOD /myapp/app/models/lead/import.rb:98 c:0022 p:0006 s:0088 E:001af8 EVAL (irb):2 [FINISH] c:0021 p:---- s:0086 e:000085 CFUNC :eval c:0020 p:0024 s:0079 E:0019b8 METHOD /opt/rubies/2.1.5/lib/ruby/2.1.0/irb/workspace.rb:86 c:0019 p:0025 s:0072 E:001a28 METHOD /opt/rubies/2.1.5/lib/ruby/2.1.0/irb/context.rb:380 c:0018 p:0022 s:0066 E:001b28 BLOCK /opt/rubies/2.1.5/lib/ruby/2.1.0/irb.rb:492 c:0017 p:0040 s:0058 E:001be8 METHOD /opt/rubies/2.1.5/lib/ruby/2.1.0/irb.rb:624 c:0016 p:0009 s:0053 E:001a98 BLOCK /opt/rubies/2.1.5/lib/ruby/2.1.0/irb.rb:489 c:0015 p:0118 s:0049 E:000a60 BLOCK /opt/rubies/2.1.5/lib/ruby/2.1.0/irb/ruby-lex.rb:247 [FINISH] c:0014 p:---- s:0046 e:000045 CFUNC :loop c:0013 p:0007 s:0043 E:000338 BLOCK /opt/rubies/2.1.5/lib/ruby/2.1.0/irb/ruby-lex.rb:233 [FINISH] c:0012 p:---- s:0041 e:000040 CFUNC :catch c:0011 p:0015 s:0037 E:000358 METHOD /opt/rubies/2.1.5/lib/ruby/2.1.0/irb/ruby-lex.rb:232 c:0010 p:0030 s:0034 E:002438 METHOD /opt/rubies/2.1.5/lib/ruby/2.1.0/irb.rb:488 c:0009 p:0008 s:0031 E:001468 BLOCK /opt/rubies/2.1.5/lib/ruby/2.1.0/irb.rb:397 [FINISH] c:0008 p:---- s:0029 e:000028 CFUNC :catch c:0007 p:0143 s:0025 E:0011e8 METHOD /opt/rubies/2.1.5/lib/ruby/2.1.0/irb.rb:396 c:0006 p:0195 s:0020 E:0026f0 METHOD /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/railties-3.2.18/lib/rails/commands/console.rb:47 c:0005 p:0011 s:0016 E:0006a0 METHOD /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/railties-3.2.18/lib/rails/commands/console.rb:8 c:0004 p:0426 s:0012 E:0022c8 TOP /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/railties-3.2.18/lib/rails/commands.rb:41 [FINISH] c:0003 p:---- s:0008 e:000007 CFUNC :require c:0002 p:0045 s:0004 E:000be8 EVAL script/rails:5 [FINISH] c:0001 p:0000 s:0002 E:000b18 TOP [FINISH] ~~~ I've experienced this problem with other gems that have C extensions, it's not deterministic. -- https://bugs.ruby-lang.org/