我有一个长时间运行的任务,它是在 Mac OS(Mac Pro 12 Core)上本地运行的 Spark 作业(map/reduce 变体)。时间命令返回:
./run 278.74s user 83.56s system 0% cpu 13:50:45.69 total
这是否意味着该作业大部分时间都花在等待 IO 上?
我有一个长时间运行的任务,它是在 Mac OS(Mac Pro 12 Core)上本地运行的 Spark 作业(map/reduce 变体)。时间命令返回:
./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,您可能应该使用 Activity Monitor 的“磁盘活动”和“网络”屏幕来查看您的系统是否已将它们最大化。更通用的解决方案是分析您的代码。
我经常使用 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 的方法 - 学会使用它可以使调试代码和性能问题变得更加容易。