Bug #1544: rb_io_write bug?

• Status: Closed
• Assignee: -
• ruby -v: ruby 1.9.1p0 (2009-01-30 revision 21907) [i386-darwin9.6.0]

[brianmario (Brian Lopez)]

=begin
I'm using rb_io_write to write (in C) to a StringIO instance (which was defined in Ruby, and passed to my C code) and noticed some strange behavior.
I'm writing to the IO at the beginning of a recursively called method and under 1.9.1 it's really slow unless I buffer up the contents then only write to the IO once using rb_io_write. For what I'm doing it's the difference between completing in 3.3 seconds, vs 0.13 seconds.
Under 1.8.6 I can write to the IO using rb_io_write in the smaller chunks (on ever recursive call) and it performs similar to the buffered write in 1.9.1.

Any known reason for this?
=end

[matz (Yukihiro Matsumoto)]

=begin
Hi,

In message "Re: [ruby-core:23642] [Bug #1544] rb_io_write bug?"
on Sun, 31 May 2009 05:33:18 +0900, Brian Lopez [e-mail] writes:

|I'm using rb_io_write to write (in C) to a StringIO instance (which was defined in Ruby, and passed to my C code) and noticed some strange behavior.
|I'm writing to the IO at the beginning of a recursively called method and under 1.9.1 it's really slow unless I buffer up the contents then only write to the IO once using rb_io_write. For what I'm doing it's the difference between completing in 3.3 seconds, vs 0.13 seconds.
|Under 1.8.6 I can write to the IO using rb_io_write in the smaller chunks (on ever recursive call) and it performs similar to the buffered write in 1.9.1.

1.9 does not use stdio, so there's possibility.
Can you show us the code to profile?

						matz.

=end

[brianmario (Brian Lopez)]

=begin
Sorry, I didn't have this ticket on "watch" and didn't notice you'd replied already...

Anyway, the code is in my yajl-ruby project. Specifically, if you look here: http://github.com/brianmario/yajl-ruby/blob/866e58ed553083e079ed5797eb5a6256dd6ce2d3/ext/yajl_ext.c#L74
That line is the call to rb_io_write that I was talking about. You'll notice I have it only call rb_io_write if the write buffer size is equal or surpassed the WRITE_BUFSIZE constants value (defaults to 8kb).

Previously, I wasn't doing that buffer size check and just calling rb_io_write on every call of the yajl_encode_part function (which is called recursively. That's how I surfaced the issue.

Again, it's performant in 1.8.6 either way (with the buffer size check or without).
=end

[rogerdpack (Roger Pack)]

=begin
Can you extract a small reproducible script?
-r
=end

[mame (Yusuke Endoh)]

• Status changed from Open to Feedback

=begin
Hi,

2009/5/31 Brian Lopez [e-mail]:

I'm using rb_io_write to write (in C) to a StringIO instance (which was defined in Ruby, and passed to my C code) and noticed some strange behavior.
I'm writing to the IO at the beginning of a recursively called method and under 1.9.1 it's really slow unless I buffer up the contents then only write to the IO once using rb_io_write. For what I'm doing it's the difference between completing in 3.3 seconds, vs 0.13 seconds.
Under 1.8.6 I can write to the IO using rb_io_write in the smaller chunks (on ever recursive call) and it performs similar to the buffered write in 1.9.1.

I failed to reproduce with RubyInline, 1.8.8dev and trunk.

require "rubygems"
require "inline"
require "stringio"
require "benchmark"

class Test
inline do |builder|
builder.c <<-EOF
VALUE test(VALUE io, VALUE str, VALUE num) {
int i = NUM2INT(num);;
while (i--) {
rb_io_write(io, str);
}
return Qnil;
}
EOF
end
end

str = "foobar"
N = 100_000
Benchmark.bm do |bm|
test = Test.new
io = StringIO.new("")
bm.report("1") { test.test(io, str, N) }
io = StringIO.new("")
bm.report("2") { test.test(io, str * N, 1) }
end

$ ../ruby-trunk-local/bin/ruby -v test.rb
ruby 1.9.2dev (2010-04-09 trunk 27269) [i686-linux]
user system total real
1 0.020000 0.000000 0.020000 ( 0.019992)
2 0.010000 0.000000 0.010000 ( 0.001042)

$ ruby18 -v test.rb
ruby 1.8.8dev (2010-04-08) [i686-linux]
user system total real
1 0.020000 0.000000 0.020000 ( 0.020884)
2 0.000000 0.000000 0.000000 ( 0.001030)

I tried various parameters of string length and loop count,
but I cannot reproduce the phenomenon you said.
I admit the condition will be very different from yours,
though.

2009/6/30 Brian Lopez [e-mail]:

Anyway, the code is in my yajl-ruby project. Specifically, if you look here: http://github.com/brianmario/yajl-ruby/blob/866e58ed553083e079ed5797eb5a6256dd6ce2d3/ext/yajl_ext.c#L74
That line is the call to rb_io_write that I was talking about. You'll notice I have it only call rb_io_write if the write buffer size is equal or surpassed the WRITE_BUFSIZE constants value (defaults to 8kb).

Previously, I wasn't doing that buffer size check and just calling rb_io_write on every call of the yajl_encode_part function (which is called recursively. That's how I surfaced the issue.

We are not familiar with yajl at all. Please show us the
smaller code to reproduce, or at least, tell us the process
to reproduce with yajl...

I can't help but close this ticket unless you answer.

--
Yusuke ENDOH [e-mail]
=end

[brianmario (Brian Lopez)]

=begin
Yusuke, as mentioned in my original post the issue I was having was in 1.9 not 1.8.
The line of code that was affected by the bug is http://github.com/brianmario/yajl-ruby/blob/master/ext/yajl_ext.c#L116 - I'll do my best to test this again on a newer version of 1.9.1 as my original finding of the bug was with 1.9.1p0.

That being said, the code you have looks like it would trigger it just fine (but on 1.9)
=end

[naruse (Yui NARUSE)]

• Status changed from Feedback to Open

=begin

=end

[jeremyevans0 (Jeremy Evans)]

• Description updated (diff)
• Status changed from Open to Closed