为何JRuby线程内调用puts有时不会在字符串末尾添加换行？

问题现象 #

在Ruby中，puts默认会在输出字符串末尾添加换行符，但在JRuby的多线程场景下，出现了异常行为：部分puts输出的换行符丢失，导致两行内容被打印在同一行。

复现代码如下：

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."

运行后输出：

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

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

End.

可以看到，两个线程中第一次调用puts的内容被拼接在同一行，而第二次调用puts的内容则正常分行。每次运行该脚本都会出现一致的异常结果。

系统环境信息：

• JRuby版本：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版本：openjdk 19 2022-09-20
• 系统：Ubuntu 22.04.1 LTS

原因分析 #

JRuby的puts底层依赖Java的IO实现，而Java的System.out相关输出操作并非完全原子：puts的逻辑是先输出字符串，再输出换行符，这两步在多线程并发时可能被打断。当两个线程几乎同时执行puts时，线程A刚输出完字符串，线程B就开始输出自己的字符串，导致两个字符串拼接在一起，换行符被延后输出。

示例中第二次puts未出现问题，是因为中间的100000000.times循环让线程执行产生了时间间隔，避免了瞬时并发的情况。

解决方案 #

1. 给输出操作加互斥锁 #

通过Ruby的Mutex实现同步，确保每次puts操作是原子性的，避免并发打断：

PRINT_LOCK = Mutex.new

def safe_puts(str)
  PRINT_LOCK.synchronize do
    puts str
  end
end

def work(n)
  safe_puts "Started unit of work ##{n}."
  i = 0
  100000000.times { i += 1 }
  safe_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(&:join)

safe_puts "\nEnd."

2. 直接调用Java的同步输出方法 #

Java的System.out.println方法内部通过同步机制保证了输出的原子性，直接调用该方法可以避免换行丢失问题：

def work(n)
  Java::java.lang.System.out.println("Started unit of work ##{n}.")
  i = 0
  100000000.times { i += 1 }
  Java::java.lang.System.out.println("Finished unit of work ##{n}.")
end

threads = []

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

threads.each(&:join)

Java::java.lang.System.out.println("\nEnd.")

3. 升级JRuby版本 #

该问题可能是特定JRuby版本的已知bug，尝试升级到最新稳定版（如9.4.x系列），新版本可能修复了IO操作的并发同步问题。

内容的提问来源于stack exchange，提问作者Matt Welke