Thursday, October 23, 2008

Интересный способ мониторинга рабочих сайтов

Иногда возникает ситуация, когда рабочий (production) сайт начинает тормозить, или вообще подвисать. Для нахождения проблемы можно просмотреть код в поисках узких мест или написать нагрузочный тест и посмотреть профилировщиком методы, которые выполняются много времени.

Но часто бывает так, что сайт начинает тормозить только при некотором стечении обстоятельств, например, когда заходит определенный пользователь на определенную страницу. Такого рода узкие места нагрузочным тестом не покроешь, так как не ясно, на каких именно данных проявляется проблема.

В этом случае можно воспользоваться утилитой jstack которая входит в состав JDK начиная с версии 1.5.0. Эта утилита позволяет просмотреть текущее состояние работающих в указанной виртуальной машине потоков (которые thread). Например,
user@laptop$ jstack 3344 "btpool0-439" prio=10 tid=0xa98da000 nid=0x1b3a in Object.wait() [0xa99ff000..0xa99ff130] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:482) - locked <0xb47e0078> (a org.mortbay.thread.BoundedThreadPool$PoolThread) "Java2D Disposer" daemon prio=10 tid=0xaa35c800 nid=0xb2e in Object.wait() [0xa9fd4000..0xa9fd50b0] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0xaf007a30> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at sun.java2d.Disposer.run(Disposer.java:125) at java.lang.Thread.run(Thread.java:619) Для каждого потока показаны его атрибуты, в том числе его название, и стектрейс.

Идея в том, чтобы на каждом запросе добавлять в название потока информацию, необходимую для идентификации узких мест. Тогда использовав jstack, из названия потока можно посмотреть, над чем в данный момент работает он работает.

Например, очевидными кандидатами на добавление в название потока являются адрес страницы, которая обрабатывается и логин пользователя. Код по добавлению этой информации логично разместить в HTTP-фильтре. Фрагмент его будет выглядеть приблизительно так:
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException { String threadName = getUser().login + ": " + RequestInfo.get().getRequestUrl(); Thread.currentThread().setName(threadName); chain.doFilter(request, response); } Теперь, если в выводе jstack будет часто видно, например, такое
"medved: /heavy/calculation" prio=10 tid=0x9aa9a800 nid=0x2519 runnable [0x9ad18000..0x9ad 190b0] java.lang.Thread.State: RUNNABLE at com.site.heavy.calculation.Calc.inner(Calc.java:113) at com.site.heavy.calculation.Calc.outer(Calc.java:43) значит, для пользователя medved медленно показывается страница /heavy/calculation. Это уже можно профилировать.

Названия потока удобно использовать также в других случаях отладки, например, записать в него User-Agent, и тогда прямо в стектрейсе ошибки будет видно, под каким браузером она возникла.

2 comments:

Dmitry Pekar said...

Интересный метод для сбора логов для анализа. При этом как альтернативу jstack (например, для 1.4.x и ниже) можно использовать kill -QUIT $pid

Vasyl Stashuk said...

onokondo,

спасибо, про kill -QUIT не знал.