我们有一个Java应用程序,在Solaris 10服务器上比在Windows PC上慢得多。
我们分析了(-Xprof)应用程序,发现UnixFileSystem.getBooleanAttributes0方法在使用本地调用的情况下消耗了大约40%的CPU时间。
我们怎样才能跟踪我们的search,以确定哪些是行为缓慢的原因?
更新:
我们执行了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; 公共类TestCL { public static void main(String [] args){ 属性properties = new Properties(); InputStream in = TestCL.class.getClassLoader()。getResourceAsStream(“TestCL.properties”); if(in == null){ System.err.println(“TestCL.properties not found”); System.exit(-1); } 尝试{ properties.load(IN); catch(IOException e){ System.err.println(“TestCL.properties加载错误”); e.printStackTrace(); System.exit(-2); 最后{ 尝试{ 附寄(); catch(IOException e){ e.printStackTrace(); } } 枚举e = properties.keys(); while(e.hasMoreElements()){ String className =(String)e.nextElement(); 尝试{ 的Class.forName(类名); System.out.println(“OK”+ className); catch(Throwable t){ System.err.println(“KO”+ className +“”+ t.getClass()。getName()+“”+ t.getMessage()); } } } }
更新3:
所有类都打包在一个.jar文件中。 我们还对所有的课程进行了解压testing,性能没有显着的提高。
java -cp library.jar:. TestCL
如果你使用Solaris,你很幸运能够使用dtrace。 这将允许您剖析内核级别,并获得有关jvm如何与内核交互的更多线索。
更多信息在这里
http://www.devx.com/Java/Article/33943
如果你想知道你正在做什么,那么使用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性能问题方面取得了巨大的成功。
您还应该使用完全的debugging日志logging来运行您的Java虚拟机和您的应用程序。 如果您有权访问内核日志,请检查它们是否有exception事件。
祝你好运。
服务器故障中的其他人是否具有一些用于故障查找等问题的忍者技巧。 我有我自己的debugging方式,但知道别的想法会很有趣。
—————–更新————–
我又看了一遍,似乎你似乎在做很多的解决path。
这需要修复。 你正在使用一个很长的path,或者从一个符号链接的目录运行。 尝试删除符号链接,或使用硬链接,看看你是否得到更好的结果。
该应用程序做很多的目录遍历,然后尝试使用绝对path,而不是相对path。
再次,只是一个想法,我吃了芝士蛋糕。 用java探针运行dtrace,这应该足够深入地查看java类/方法花费的最多时间。
祝你好运(再次)。 现在不要放弃,我想我们非常接近解决scheme。
在你的solaris系统上只运行sys_diag -G -I1 -l -v ,它会聚合所有的性能信息(CPU /内存/networking/磁盘IO / Dtrace /内核…),并用单一的颜色编码分析输出。 HTML报告的结果/瓶颈表征子系统的工作量。这将显示任何/所有的瓶颈以及可能发生的locking(lockstat,..)。 最新版本是v8.1 HTH。
只是发布最终结果。
服务器(Sun T系列)对于单线程Java应用程序来说太慢了。 去搞清楚。
谢谢大家的答复和支持。
您的dtrace输出显示您的应用程序大部分时间都在写入 。 你应该检查(当然使用dtrace :-))这些写入的地方。 如果他们去solaris文件系统,那么你应该检查文件系统是否不是瓶颈。
使用iostat来查看是否存在导致磁盘访问速度慢于预期的问题可能是值得的。 加载几千个类不应该消耗大量的磁盘IO,特别是如果你已经运行了几次,使得这些块在caching中。
尝试
iostat -nxtcmpz 3
同时testing正在运行,并查看是否有任何设备具有特别高的繁忙/等待百分比,或者平均服务时间特别高。 这只是可能你有一个死亡的磁盘,或没有反应的NFS安装杀死性能。