我们有一个 Java 应用程序，它在 Solaris 10 服务器中的运行速度明显比在 Windows PC 中慢。
我们对应用程序进行了分析（-Xprof），并观察到 UnixFileSystem.getBooleanAttributes0 方法通过本机调用消耗了大约 40% 的 CPU 时间。
我们如何通过搜索来确定导致行为缓慢的原因？
更新：
我们已经执行dtrace并观察到 CPU 时间为 0.489 秒，而time结果是
real 0m40.759s
user 0m47.669s
sys 0m2.287s
看来时间不是花在 CPU 上，而是花在了其他地方。得到这个dtrace结果后，我们如何进一步调查？我们可以使用其他dtrace选项来显示更多信息吗？
非常感谢。
# /dtrace-toolkit/DTraceToolkit-0.99/procsystime -aTp 5695
Tracing... Hit Ctrl-C to end...
dtrace: 1032 dynamic variable drops with non-empty dirty list
^C
Elapsed Times for PID 5695,
SYSCALL TIME (ns)
gtime 7799
sysconfig 8018
lwp_kill 10105
getsockname 10215
systeminfo 10984
getrlimit 11093
lwp_self 20210
schedctl 26361
lwp_continue 27349
priocntlsys 33390
unlink 53050
lwp_sigmask 136303
setcontext 143447
so_socketpair 202427
lwp_create 223626
brk 227141
so_socket 263276
memcntl 461091
ioctl 1094955
lwp_cond_broadcast 1946728
lwp_mutex_wakeup 2579492
lwp_cond_signal 2903277
mmap 3082973
access 4446250
mprotect 4534229
getdents64 5713309
mmap64 6272480
fsat 6925239
stat 6926115
open 8324983
fcntl 8840868
close 11264404
llseek 11678791
munmap 11867401
fstat64 17852129
lwp_park 22098570
open64 23549922
stat64 39673214
read 41876097
resolvepath 81905859
yield 175946072
write 225507878
lwp_mutex_timedlock 887174392
pollsys 20393318412
lwp_cond_wait 345099369278
TOTAL: 367108549202
CPU Times for PID 5695,
SYSCALL TIME (ns)
gtime 1208
sysconfig 1647
lwp_self 2198
systeminfo 2856
lwp_kill 3186
getsockname 3625
getrlimit 4613
lwp_continue 13839
schedctl 14059
priocntlsys 14498
lwp_sigmask 20541
unlink 45801
setcontext 96874
brk 121804
lwp_park 158601
so_socketpair 195178
lwp_create 209017
so_socket 241199
memcntl 365972
ioctl 606397
lwp_cond_broadcast 1367556
lwp_mutex_wakeup 1561103
lwp_cond_signal 1803831
access 1885436
mmap 2655710
llseek 3266410
open 3614795
fsat 4043369
getdents64 4253373
mprotect 4345864
close 4547395
fcntl 4871095
stat 5183012
mmap64 5308789
fstat64 8141116
munmap 10774529
pollsys 11928811
lwp_mutex_timedlock 19212980
open64 19443958
lwp_cond_wait 23144761
read 28043647
stat64 31710269
resolvepath 70641662
yield 77731698
write 137678654
TOTAL: 489282936
Syscall Counts for PID 5695,
SYSCALL COUNT
getrlimit 1
getsockname 1
gtime 1
lwp_kill 1
rexit 1
so_socketpair 1
sysconfig 1
systeminfo 1
unlink 1
lwp_continue 2
lwp_create 2
schedctl 2
lwp_self 3
priocntlsys 3
so_socket 3
lwp_exit 4
setcontext 7
lwp_park 11
memcntl 14
brk 16
lwp_sigmask 19
mprotect 25
mmap 56
access 67
lwp_cond_broadcast 86
ioctl 87
open 100
fsat 129
mmap64 133
lwp_mutex_wakeup 148
munmap 153
lwp_cond_signal 162
getdents64 224
stat 283
pollsys 348
lwp_cond_wait 537
lwp_mutex_timedlock 558
open64 590
fcntl 625
close 777
stat64 1146
llseek 1368
read 1404
fstat64 1559
resolvepath 1644
yield 10049
write 13416
TOTAL: 35769
更新 2：
这是 dtraced Java 应用程序的源代码。它只从一个 .jar 文件中加载几千个类，重现了在更大的应用程序中观察到的相同行为。
import java.io.IOException;
import java.io.InputStream;
import java.util.Enumeration;
import java.util.Properties;
public class TestCL {
public static void main(String[] args) {
Properties properties = new Properties();
InputStream in = TestCL.class.getClassLoader().getResourceAsStream("TestCL.properties");
if (in == null) {
System.err.println("TestCL.properties not found");
System.exit(-1);
}
try {
properties.load(in);
} catch (IOException e) {
System.err.println("TestCL.properties loading error");
e.printStackTrace();
System.exit(-2);
} finally {
try {
in.close();
} catch (IOException e) {
e.printStackTrace();
}
}
Enumeration e = properties.keys();
while (e.hasMoreElements()) {
String className = (String) e.nextElement();
try {
Class.forName(className);
System.out.println("OK " + className);
} catch (Throwable t) {
System.err.println("KO " + className + " " + t.getClass().getName() + " " + t.getMessage());
}
}
}
}
更新 3：
所有类都打包在一个 .jar 文件中。我们还对所有类都解压后进行了测试，性能没有显著提高。
java -cp library.jar:. TestCL
答案1
如果您使用的是 Solaris，那么您很幸运能够使用 dtrace。这将允许您分析内核级别并获得有关 jvm 如何与内核交互的更多线索。
更多信息请点击此处
http://www.devx.com/Java/Article/33943
如果您想知道 jvm 正在做什么，那么请使用 jvm 探测器运行 dtrace。
http://java.sun.com/javase/6/docs/technotes/guides/vm/dtrace.html
http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_Java#DTrace_Topics:_Java
这将为您提供与您的程序相关的更有意义的输出。请查看“方法时间”部分。
http://www.princeton.edu/~unix/Solaris/troubleshoot/diskio.html
是查找 I/O 瓶颈的绝佳指南。
这也可能有帮助http://prefetch.net/blog/index.php/2007/03/03/viewing-busy-code-paths-with-dtrace/
跟踪此类问题时没有硬性规定，但信息是关键！！如果您遵循这些指南，您就很有可能成为一名忍者系统工程师。
您可能可以使用 jprofiler http://www.ej-technologies.com/products/jprofiler/overview.html
它不是开源的，但是我在用它追踪 Java 性能问题方面取得了巨大的成功。
您还应该使用完整的调试日志来运行 Java VM 和应用程序。如果您有权访问内核日志，请检查其中是否存在异常事件。
祝你好运。
服务器故障方面的其他人是否有一些忍者技巧来查找此类故障问题。我有自己的调试方法，但想知道其他人的想法会很有趣吗？
- - - - - - - - -更新 - - - - - - -
我再次查看了该跟踪，似乎你正在做很多解析路径。
这需要修复。您是否使用了很长的路径，或者从符号链接的目录运行。尝试删除符号链接，或使用硬链接，看看是否能获得更好的结果。
应用程序是否进行了大量目录遍历，然后尝试使用绝对路径，而不是相对路径。
再次重申，这只是我吃奶酪蛋糕时的一个想法。使用 java 探测器运行 dtrace，这应该能够深入挖掘以查看哪个 java 类/方法耗时最多。
祝你好运（再次）。现在不要放弃，我认为我们离解决方案已经很近了。
答案2
在您的 solaris 系统上运行sys_diag -G -I1 -l -v，它将汇总所有性能信息（CPU/内存/网络/磁盘 IO/Dtrace/内核...），并使用单个颜色编码的 .html 报告分析输出，该报告包含按子系统描述工作负载的发现/瓶颈。这将显示任何/所有瓶颈以及可能发生的锁定（lockstat，...）。最新版本是 v8.1 HTH。
答案3
只是为了发布最终结果。
对于单线程 Java 应用程序来说，服务器（Sun T 系列）就是这么慢。想想看。
感谢大家的回答和支持。
答案4
可能值得使用 iostat 查看是否存在导致磁盘访问速度比预期慢的问题。加载几千个类不会消耗大量磁盘 IO，特别是如果您已经运行了几次以便块位于缓存中。
尝试
iostat -nxtcmpz 3
在测试运行时，查看是否有任何设备的繁忙/等待百分比特别高，或者平均服务时间是否特别长。很可能您的磁盘快要坏了，或者 NFS 挂载无响应，从而影响性能。