Why does JRuby sometimes not print a newline at the end of the string when "puts" is being called from within a thread?

Matt Welke 0
Viewed 24

In Ruby, I'm used to seeing puts always append a newline to the string being printed before printing it.

While playing around with multi-threading in Ruby, including running it with JRuby, I noticed some odd behavior. Sometimes, two lines will be printed on the same line instead of being printed on separate lines like I expected. In my first time trying this, my script was using a Semaphore from concurrent-ruby because I was testing out concurrency and parallelism patterns. I was using the semaphore to only allow a configured number of threads from being started at a time. It was about a 20% chance of it happening.

To create a minimal reproduction for Stack Overflow, I took out concurrent-ruby and created a smaller version of my program that just created threads that ran immediately, without first storing the blocks of code in procs and without using a semaphore. With this new program, this issue happens 100% of the time (at least for how many times I've tried running it so far).

I understand that with multi-threading, the order of the two lines being printed could be different each time, depending on which thread runs first. But I didn't expect that sometimes, the newline that should be on the end of every string printed (because I print them with puts) would sometimes not be there.

Program:

def work(n)
  puts "Started unit of work ##{n}."
  i = 0
  100000000.times { i += 1 }
  puts "Finished unit of work ##{n}."
end

threads = []

2.times do |i|
  thread = Thread.new do
    work(i + 1)
  end
  threads << thread
end

threads.each do |t|
  t.join
end

puts "\nEnd."

Output:

Started unit of work #1.Started unit of work #2.

Finished unit of work #2.
Finished unit of work #1.

End.

Note how the output includes Started unit of work #1.Started unit of work #2. and not Started unit of work #1.\nStarted unit of work #2.. Also note how this issue doesn't occur for the second call to puts in each thread. Those are on separate lines, as expected.

This output was consistent every time I ran the Ruby script with JRuby. I couldn't get a run where it printed a newline after Started unit of work #1. or Started unit of work #2..

System details:

> jruby --version
jruby 9.3.8.0 (2.6.8) 2022-09-13 98d69c9461 OpenJDK 64-Bit Server VM 19+36-2238 on 19+36-2238 +jit [x86_64-linux]

> java --version
openjdk 19 2022-09-20
OpenJDK Runtime Environment (build 19+36-2238)
OpenJDK 64-Bit Server VM (build 19+36-2238, mixed mode, sharing)

> lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 22.04.1 LTS
Release:        22.04
Codename:       jammy
jruby multithreading ruby concurrency
1 Answers

You are not flushing the output stream nor are you using the output stream in synchronous mode.

Output streams typically work in a buffered mode where they collect a certain amount of characters in a buffer and only writing them out in larger "chunks".

As you can see in your output, the newlines are being written, but since your output is not synchronized, there is no guarantee as to which order the characters from the individual threads are written in.

So, what is written is:

  1. The text from thread #1
  2. The text from thread #2
  3. A newline (we don't know from which thread)
  4. Another newline (we don't know from which thread)

Depending on how exactly JRuby's output streams are implemented, it would be perfectly possible (and perfectly valid, according to the code you have written) to even get an output like this:

SSttaarrtteedd  uunniitt  ooff  wwoorrkk  ##21..\n\n

You can manually flush the output stream using the IO#flush method:

def work(n)
  puts "Started unit of work ##{n}."
  i = 0
  100000000.times { i += 1 }
  puts "Finished unit of work ##{n}."
  $stdout.flush
end

Or alternatively, you can set $stdout to synchronous mode using the IO#sync= method:

$stdout.sync = true

However, please note that this only affects Ruby's own buffers. It does not affect the JRE's, the JVM's, or the OS's buffers.

Jörg W Mittag0
Related