我有一个长时间运行的任务,这是一个Spark作业(map/reduce变体),它在Mac OS (Mac Pro 12 Core)上本地运行。返回的时间命令:
./run 278.74s user 83.56s system 0% cpu 13:50:45.69 total
这是否意味着作业的大部分时间都在等待IO?
输出告诉您,在进程运行的大部分时间里,您被阻塞在某个上。它可以是对磁盘或网络的I/O,但也可以是对sleep()
的调用或其他使进程脱离cpu的操作。由于输出中的total
数字是"自进程开始以来的实时值",因此这种差异甚至可能是由于系统上的其他任务占用了所有资源,而不给进程运行的机会造成的。此外,请记住,等待用户输入所花费的任何时间都会计入total
时间,但您通常不会认为这是I/O限制(除非您认为用户是一个非常慢的设备,但这完全是另一个讨论)。
换句话说,您唯一知道的是进程本身不受cpu限制。
要弄清楚你的进程是否做了很多I/O,你可能应该使用活动监视器的"磁盘活动"one_answers"网络"屏幕来看看你的系统是否最大限度地利用了这些I/O。一个更通用的解决方案是分析你的代码。
我经常使用DTrace在Mac OS上做分析,所以这里有一个脚本,它会告诉你你的进程执行每个系统调用花费了多少纳秒。对于简单的程序,根据系统调用的内容,很明显它们为什么会花费很长时间。
$ sudo dtrace -n '
syscall:::entry /pid == $target/ {
self->ts = timestamp;
}
syscall:::return /pid == $target && self->ts/ {
@[probefunc] = sum(timestamp - self->ts);
self->ts = 0;
}
' -c java # <-- put './run' here instead of 'java'
syscall:::entry ' matched 880 probes
dtrace: pid 38883 has exited
...
close_nocancel 208017
workq_kernreturn 222226
open_nocancel 2569800
open 3098793
read 3467981
stat64 3641553
getdirentries64 4212212
kevent 26820366
可以看到,在JVM启动期间,文件系统调用要花费很多时间。如果一个系统调用需要很长时间才能完成,并且您不确定原因,那么您总是可以获得堆栈跟踪,以找出使用下一个脚本(用read
代替任何需要很长时间的脚本)如何调用它们:
$ sudo dtrace -n '
syscall::read:entry /pid == $target/ {
self->ts = timestamp;
}
syscall::read:return /pid == $target && self->ts/ {
@[ustack()] = sum(timestamp - self->ts);
self->ts = 0;
}
' -c java
# output truncated -- you'll get a bunch of stack traces
# sorted by the amount of time each one used
还有许多其他的方法可以使用DTrace -学会使用它可以使调试代码和性能问题更容易。