[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 <product> 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 <product> nodes each and processing one file at a time, and the same errors occurred. The <product> 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 <product> 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 <product> 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/