У нас есть приложение Java, которое на сервере Solaris 10 работает значительно медленнее, чем на ПК с Windows.
Мы профилировали (-Xprof) приложение и заметили, что метод UnixFileSystem.getBooleanAttributes0 потребляет около 40% процессорного времени с собственными вызовами.
Как мы можем проследить наш поиск, чтобы определить, что является причиной медленного поведения?
Обновить:
Мы выполнили dtrace и мы наблюдаем, что время процессора составляет 0,489 секунды, в то время как time результаты
real 0m40.759s
user 0m47.669s
sys 0m2.287s
Кажется, время тратится не на процессор, а в другое место. Как мы можем продолжить расследование, имея это 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:
Вот исходный код Java-приложения dtraced. Он просто загружает несколько тысяч классов из одного файла .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
Если вы используете Solaris, вам повезло, что вы можете использовать dtrace. Это позволит вам профилировать уровень ядра и получить больше подсказок о том, как jvm взаимодействует с ядром.
Больше информации здесь
http://www.devx.com/Java/Article/33943
Если вы хотите узнать, что делает jvm, запустите dtrace с зондами jvm.
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
- отличное руководство для поиска узких мест ввода-вывода.
это также может помочь 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 и приложение с полным ведением журнала отладки. Если у вас есть доступ к журналам ядра, проверьте их на наличие необычных событий.
Удачи.
Есть ли у кого-нибудь еще по ошибке сервера несколько советов ниндзя по поиску неисправностей, таких как эта. У меня есть свой способ отладки, но было бы интересно узнать, что думают другие?
-----------------ОБНОВИТЬ--------------
Я снова посмотрел на трассировку, кажется, вы делаете много путей разрешения.
Это нужно исправить. Вы используете очень длинный путь или работаете из каталога с символической ссылкой? Попробуйте удалить символические ссылки или использовать жесткие ссылки и посмотрите, добьетесь ли вы лучших результатов.
Выполняет ли приложение много операций обхода каталогов, затем попробуйте использовать абсолютные пути, а не относительные пути.
Опять же, просто идея: «Я съела сырный пирог. Запустите dtrace с java-зондами, которые должны быть достаточно детализированы, чтобы увидеть, какой java-класс / методы занимают больше всего времени.
Удачи (снова). Не сдавайтесь сейчас, я думаю, мы очень близки к решению.
В вашей системе Solaris просто запустите sys_diag -G -I1 -l -v и он будет собирать всю информацию о производительности (CPU / Memory / Network / Disk IO / Dtrace / kernel ...) и анализировать вывод с помощью одного цветного отчета в формате .html о находках / узких местах, характеризующих рабочую нагрузку по подсистемам. Это покажет все узкие места, а также возможные блокировки (lockstat, ..). Последняя версия - v8.1 HTH.
Ваш dtrace вывод показывает, что ваши приложения большую часть времени тратят на пишет. Вы должны проверить (используя dtrace конечно :-)) где эти записи идут. Если они переходят в файловую систему solaris, вам следует проверить, не является ли файловая система узким местом.
Просто чтобы опубликовать окончательный результат.
Сервер (Sun T Series) настолько медленный для однопоточного Java-приложения. Иди разберись.
Спасибо всем за ответы и поддержку.
Возможно, стоит взглянуть на iostat, чтобы узнать, есть ли проблема, из-за которой доступ к вашему диску медленнее, чем ожидалось. Загрузка нескольких тысяч классов не должна потреблять много дискового ввода-вывода, особенно если вы запускали ее несколько раз, чтобы блоки находились в кеше.
Пытаться
iostat -nxtcmpz 3
во время выполнения теста и посмотрите, есть ли у каких-либо устройств особенно высокий процент занятости / ожидания или особенно велико ли среднее время обслуживания. Вполне возможно, что у вас умирающий диск или не отвечающее на запросы монтирование NFS, убивающее производительность.