Rastreando o Java I / O lento no Solaris 10

Question

Temos uma aplicação Java que é significativamente mais lenta no servidor Solaris 10 do que no Windows PC.

Nós fizemos o perfil (-Xprof) do aplicativo e observamos que o método UnixFileSystem.getBooleanAttributes0 consome cerca de 40% do tempo de CPU com chamadas nativas.

Como podemos seguir nossa busca para identificar qual é a causa do comportamento lento?

Atualização:

Executamos dtrace e observamos que o tempo de CPU é de 0,489 s, enquanto os resultados de time são

real 0m40.759s
user 0m47.669s
sys 0m2.287s

Parece que o tempo não é gasto em CPU, mas em outro lugar. Como podemos prosseguir com uma investigação mais aprofundada com os resultados dtrace ? Podemos usar outras opções dtrace para mostrar mais informações?

Muito obrigado.

# /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

Atualização 2:

Aqui está a fonte do aplicativo Java dtraced. Ele apenas carrega milhares de classes de um único arquivo .jar, reproduzindo o mesmo comportamento observado em um aplicativo maior. %pr_e%

Atualização 3:

Todas as classes são agrupadas em um único arquivo .jar. Também executamos o teste com todas as classes descompactadas e não há melhoria significativa no desempenho.

java -cp library.jar:. TestCL

    

Answer 1

Se você usa o Solaris, tem sorte de poder usar o dtrace. Isso permitirá que você crie um perfil para o nível do kernel e obtenha mais dicas sobre como o jvm está interagindo com o kernel.

Mais informações aqui

link

Se você quiser descobrir o que está fazendo, execute o dtrace com os testes do jvm.

link

link

isso lhe dará resultados muito mais significativos em relação ao seu programa. Dar uma olhada na seção "Tempos de método".

link

é um ótimo guia para encontrar gargalos de garrafa de i / o.

isso também pode ajudar link

Não há regras rígidas e rápidas ao rastrear problemas como esse, mas informações É a chave!!. Se você seguir estes guias, Você está no caminho certo para se tornar um engenheiro de sistemas ninja.

Você pode usar jprofiler link

não é de código aberto, no entanto, tive grande sucesso em rastrear problemas de desempenho do Java com ele.

Você também deve executar seu java vm e seu aplicativo com o log de depuração completo. Se você tiver acesso aos logs do kernel, verifique se há eventos incomuns.

Boa sorte.

Alguém mais na falha do servidor tem algumas dicas ninja para problemas de detecção de falhas como este. Eu tenho meu próprio jeito de depurar, mas seria interessante saber o que os outros pensam?

----------------- UPDATE --------------

Eu olhei para o rastreamento novamente, parece que você parece estar fazendo muitos caminhos de resolução.

Isso precisa ser corrigido. Você está usando um caminho muito longo ou em um diretório que é symlinked. Tente remover links simbólicos ou usando links de hardware e veja se você obtém melhores resultados.

O aplicativo faz o lote de diretório atravessado e, em seguida, tenta usar o caminho absoluto, em vez que caminhos relativos.

Mais uma vez, apenas uma ideia 'Eu tive mais de comer um bolo de queijo. Execute o dtrace com os probes java, que deve detalhar o suficiente para ver que classe / métodos java estão demorando mais tempo.

Boa sorte (de novo). Não desista agora, acho que estamos muito perto da solução.

    

Answer 2

No seu sistema solaris, execute sys_diag -G -I1 -l -v e ele agregará todas as informações de desempenho (CPU / Memória / Rede / Disco IO / Dtrace / kernel ...) e analisará a saída com um único relatório .html codificado por cores. descobertas / gargalos que caracterizam a carga de trabalho por subsistema. Isso mostrará qualquer / todos os gargalos assim como o bloqueio que pode estar ocorrendo (lockstat, ..). A última versão é v8.1 HTH.

    

Answer 3

Só para postar o resultado final.

O servidor (Sun T Series) é tão lento para um aplicativo Java de encadeamento único. Vai a figura.

Obrigado a todos pelas respostas e apoio.

    

Answer 4

Sua saída do dtrace mostra que seus aplicativos passam a maior parte do tempo em gravações . Você deve checar (usando dtrace claro :-)) onde estas gravações vão. Se eles forem para o sistema de arquivos solaris, você deve verificar se o sistema de arquivos não é um gargalo.

    

Answer 5

Pode valer a pena dar uma olhada com o iostat para ver se há um problema que está fazendo com que os acessos a disco sejam mais lentos do que o esperado. Carregar alguns milhares de classes não deve consumir muito IO em disco, especialmente se você executá-lo algumas vezes para que os blocos estejam no cache.

Tente

iostat -nxtcmpz 3

enquanto o seu teste está em execução, e veja se algum dispositivo tem uma porcentagem de ocupado / espera particularmente alta, ou se os tempos médios de serviço são especialmente altos. É possível que você tenha um disco prestes a morrer, ou um desempenho de montagem de NFS sem resposta.