在 Solaris 10 中跟踪慢速 Java I/O

我们有一个 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