如何测量 Ruby 中的互斥量争用？答案

【问题标题】：How can I measure mutex contention in Ruby?如何测量 Ruby 中的互斥量争用？
【发布时间】：2016-07-28 15:30:40
【问题描述】：

我最近发现自己试图诊断某个特定 Ruby 程序运行缓慢的原因。最终，结果证明是由缩放问题引起的，该问题导致对特定互斥体的大量争用。

我想知道是否有任何工具可以用来使这个问题更容易诊断？我知道我可以使用 ruby-prof 来获取该程序的所有 100 多个线程花费时间的详细输出，但我很好奇是否有任何工具专门专注于测量 Ruby 中的互斥争用？

【问题讨论】：

我对 Ruby 没有任何经验，但是如果您在可以安装 Systemtap 的 Linux 上工作，您可以使用 Systemtap 脚本，它会向您显示我写的每个进程/线程的争用情况它的详细信息在这里：stackoverflow.com/questions/38623976/…

标签： ruby concurrency mutex monitoring

【解决方案1】：

所以如果想出了如何使用 DTrace 来做到这一点。

给定一个这样的 Ruby 程序：

# mutex.rb
mutex = Mutex.new
threads = []

threads << Thread.new do
  loop do
    mutex.synchronize do
      sleep 2
    end
  end
end

threads << Thread.new do
  loop do
    mutex.synchronize do
      sleep 4
    end
  end
end

threads.each(&:join)

我们可以像这样使用 DTrace 脚本：

/* mutex.d */
ruby$target:::cmethod-entry
/copyinstr(arg0) == "Mutex" && copyinstr(arg1) == "synchronize"/
{
  self->file = copyinstr(arg2);
  self->line = arg3;
}

pid$target:ruby:rb_mutex_lock:entry
/self->file != NULL && self->line != NULL/
{
  self->mutex_wait_start = timestamp;
}

pid$target:ruby:rb_mutex_lock:return
/self->file != NULL && self->line != NULL/
{
  mutex_wait_ms = (timestamp - self->mutex_wait_start) / 1000;
  printf("Thread %d acquires mutex %d after %d ms - %s:%d\n", tid, arg1, mutex_wait_ms, self->file, self->line);
  self->file = NULL;
  self->line = NULL;
}

当我们针对 Ruby 程序运行此脚本时，我们会得到如下信息：

$ sudo dtrace -q -s mutex.d -c 'ruby mutex.rb'

Thread 286592 acquires mutex 4313316240 after 2 ms - mutex.rb:14
Thread 286591 acquires mutex 4313316240 after 4004183 ms - mutex.rb:6
Thread 286592 acquires mutex 4313316240 after 2004170 ms - mutex.rb:14
Thread 286592 acquires mutex 4313316240 after 6 ms - mutex.rb:14
Thread 286592 acquires mutex 4313316240 after 4 ms - mutex.rb:14
Thread 286592 acquires mutex 4313316240 after 4 ms - mutex.rb:14
Thread 286591 acquires mutex 4313316240 after 16012158 ms - mutex.rb:6
Thread 286592 acquires mutex 4313316240 after 2002593 ms - mutex.rb:14
Thread 286591 acquires mutex 4313316240 after 4001983 ms - mutex.rb:6
Thread 286592 acquires mutex 4313316240 after 2004418 ms - mutex.rb:14
Thread 286591 acquires mutex 4313316240 after 4000407 ms - mutex.rb:6
Thread 286592 acquires mutex 4313316240 after 2004163 ms - mutex.rb:14
Thread 286591 acquires mutex 4313316240 after 4003191 ms - mutex.rb:6
Thread 286591 acquires mutex 4313316240 after 2 ms - mutex.rb:6
Thread 286592 acquires mutex 4313316240 after 4005587 ms - mutex.rb:14
...

我们可以收集此输出并使用它来获取有关哪些互斥锁引起最多争用的信息。

【讨论】：