Статьи

Укрощение неожиданных производственных проблем

Время от времени у вас возникают необъяснимые производственные проблемы. Это влияет на бизнес, и руководство проинструктирует вас, пока кусочки головоломки собраны. Нет способа воссоздать это при настройке QA. Проблема скрывается там довольно долго и становится все более и более частой. Звучит страшно знакомо?

У меня особенная любовь к таким головоломкам. Мне нравится адреналиновый прилив охоты и исследовательский аспект создания теории. Последнее, что я унаследовал, заняло около 6 месяцев, чтобы выяснить, поскольку у унаследованного продукта было много проблем, которые возникли бы с нагрузкой и неудачей, а именно с выбором времени. Для решения проблемы такого масштаба требуются выносливость, итерации, сбор информации и интеллектуальный анализ данных.

Информация ниже покажет вам, что собирать и как обрабатывать собранные данные. Система, с которой я работал, работает на Enterprise Linux Server версии 5.8 (Carthage) и сервере JBoss. Вам нужно будет внести изменения в соответствии с особенностями вашей ОС и сервера приложений.

Вещи, которые помогут на охоте

1. Периодические дампы потоков сохраняются в файл, это может быть так же просто, как задание cron для JMX-консоли JBoss для активации метода jboss.system.ServerInfo listThreadDump

2. Периодическая загрузка процессора, сохраненная в файл, это может быть так же просто, как задание cron для JMX-консоли JBoss для активации метода jboss.system.ServerInfo listThreadCpuUtilization

3. Периодические результаты топ-команды

4. В журнале информации из приложения нет такой вещи, как избыточная отладочная информация. Страница JSP, которая позволяет изменять многословность данной категории, здесь бесценна.

5. Мониторинг программного обеспечения, такого как NewRelic . Он отлично подходит для определения самых медленных транзакций или SQL-запросов, количества времени, затрачиваемого на вызовы во внешние системы, сравнения производительности и составления отчетов по показателям SLA. Смотреть наблюдатель, хотя! Не забудьте обновить свои библиотеки при обновлении на 3 RD пакетов партии, JVM или операционную систему на устройстве или компьютере. Проанализируйте его файлы журналов. Откуда я знаю, сложилось несколько болезненное впечатление.

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

Мой гуру DevOps Джаред настроил JMX керлинг и топ для меня с помощью cron и скриптов, так что каждые 10 минут происходит обновление.

Это выражение cron

*/10 * * * * /tools/scripts/jboss/threaddump.sh > /dev/null 2>&1

И сам скрипт выглядит так

#!/bin/sh

logfile=`date +%H%M%S`
logdir=`date +%Y"/"%m"/"%d`
datestamp=`date +%Y%m%d`

if [ ! -d "/logs/console/$logdir" ]; then
        mkdir -p /logs/console/$logdir
fi

curl "http://localhost:8080/jmx-console/HtmlAdaptor?action=invokeOpByName&name=jboss.system%3Atype%3DServerInfo&methodName=listThreadDump" > /logs/console/$logdir/thread_dump_$datestamp_$logfile.html 2>&1
curl "http://localhost:8080/jmx-console/HtmlAdaptor?action=invokeOpByName&name=jboss.system%3Atype%3DServerInfo&methodName=listThreadCpuUtilization" > /logs/console/$logdir/thread_cpu_$logfile.html 2>&1
top -H -b -n 1 > /logs/console/$logdir/top_$logfile.log 2>&1

Теперь пойдем на охоту.

Первый вопрос, который нужно задать: есть ли у меня потоки, которые потребляют чрезмерное количество ресурсов процессора и что они делают ? Посмотрите на консоль JMX вручную или используйте предварительно собранный артефакт 2, чтобы найти список таких потоков. Список будет выглядеть так:

Название темы

CPU (миллисекунды)

AJP-0.0.0.0-8009-13

16783407

AJP-0.0.0.0-8009-8

5566706

AJP-0.0.0.0-8009-15

5087530

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

Когда подозреваемый найден, его местонахождение можно проверить вручную с консоли JMX или в артефакте 1. Последние 2 бесконечных цикла, которые я видел, были связаны с использованием HashMap несколькими потоками, что кратко описано здесь .

#!/usr/bin/perl
use strict;
use warnings;

my $dir = '.';
my %threads;

opendir(DIR, $dir) or die $!;

while (my $file = readdir(DIR)) {

	# We only want files
	next unless (-f "$dir/$file");

	# Use a regular expression to find files ending in .log.*
	next unless ($file =~ m/^server\.log\..*$/);

	open(my $fh, "<$file") or die("Could not open file $file.");
	foreach my $line (<$fh>) {
		#2014-02-27 01:00:00,827 25498282 INFO  [com.company.client.package.Class] (ajp-0.0.0.0-8009-22:) 
		if ($line =~ /^(201\d).(\d\d).(\d\d)[ \t]+(\d\d:\d\d:\d\d),\d\d\d \d+[ \t]+[A-Z]+[ \t]+[^ \t]+[ \t]+\(([^\)]+):\).*$/) {
			$threads{$5} = "$2/$3/$1 $4";
		}   
	}
	close($fh);
}

foreach my $thread (sort keys %threads) {
	print "$thread\t$threads{$thread}\n";
}

closedir(DIR);
exit 0;

Созданная информация должна быть отсортирована в хронологическом порядке:

sort -k2 -r threads.txt > threads_sorted.txt

Следующий вопрос должен быть: система испытывает тупики или ресурсные разногласия . Чтобы ответить на такой вопрос, необходимо проанализировать коллекцию артефактов 1 с течением времени. Это причина, почему файлы thread_dump имеют информацию о дате как часть имени. В Linux / Unix простая команда ниже поместит необходимую информацию в один файл:

grep -r "lockName:" thread_dump_* > suspects.txt

Теперь содержимое можно анализировать в текстовом файле с вкладками, которое можно использовать в старом добром Excel, и просматривать его в сводной таблице.

#!/usr/bin/perl -w
use strict;
use warnings;
if(!defined $ARGV[0]){
    print "No FilePath Specified!\n";
}

my $LOGFILE = $ARGV[0];

print "Time\tThread\tState\tLock Name\tLock Name Class\tCall Stack\n";

open(my $fh, "<$LOGFILE") or die("Could not open log file.");
foreach my $line (<$fh>) {

	if ($line =~ /^thread_dump_(\d\d\d\d)(\d\d)(\d\d)_(\d\d)(\d\d)\d\d.html:(.*)$/) {
		my $year = $1;
		my $month = $2;
		my $date = $1;
		my $hour = $4;
		my $min = $5;
		my $td = $6;

		my @matches = ($td =~ m/(\>b\<Thread: [^:]+ : priority:\d+, demon:[a-z]+, threadId:\d+, threadState:[A-Z_]+, lockName:[a-zA-Z0-9\$\.\@]+\>br\<\>blockquote\<[ a-zA-Z_\$\.\(\):0-9\>\<]+\>\/blockquote\<)/g);
		
		
		foreach my $x (@matches) {
			if ($x =~ /^\>b\<Thread: ([^:]+)\>\/b\< : priority:\d+, demon:[a-z]+, threadId:\d+, threadState:([A-Z_]+), lockName:([a-zA-Z0-9\$\.]+)(\@?[0-9a-f]*)\>br\<\>blockquote\<([ a-zA-Z_\$\.\(\):0-9\>\<]+)\>\/blockquote\<$/) {
				print "$month/$date/$year $hour:$min\t$1\t$2\t$3$4\t$3\t$5\n";
			} else {
				print STDERR "No match : $x\n";
			}
		}
	} else {
		print STDERR "No match in line : $line\n";
	}   
}
close($fh);

Это будет производить контент, как показано ниже

Время

Нить

высказывать

Имя замка

Имя класса блокировки

Стек вызовов

02.06.14 0:00

Обработчик ссылок

ОЖИДАНИЯ

java.lang.ref.Reference$Lock@57db6806

java.lang.ref.Reference $ Блокировка

java.lang.Object.wait (собственный метод) <br> java.lang.Object.wait (Object.java:503) <br> java.lang.ref.Reference $ ReferenceHandler.run (Reference.java:133) < ш>

02.06.14 0:00

RMI TCP Accept-1098

Runnable

значение NULL

значение NULL

java.net.PlainSocketImpl.socketAccept (собственный метод) <br> java.net.AbstractPlainSocketImpl.accept (AbstractPlainSocketImpl.java:398) <br>… <br>

02.06.14 0:00

GC Daemon

TIMED_WAITING

sun.misc.GC$LatencyLock@10a8ec79

sun.misc.GC $ LatencyLock

java.lang.Object.wait (собственный метод) <br> sun.misc.GC $ Daemon.run (GC.java:117) <br>

6/2/14 16:00

AJP-0.0.0.0-8009-3

BLOCKED

java.lang.Class@4c6cb02a

java.lang.Class

java.util.TimeZone.getDefaultInAppContext (TimeZone.java:734) <br> java.util.TimeZone.getDefaultRef (TimeZone.java:630) <br> java.util.Date.normalize (Date.java:1206) <бр > java.util.Date.toString (Date.java:1027) <br> … <br>

Агрегация будет выглядеть так

Количество потоков

Метки колонки

заголовки строк

BLOCKED

TIMED_WAITING

ОЖИДАНИЯ

Общий итог

com.arjuna.ats.arjuna.coordinator.TransactionReaper

97

97

com.enservio.util.ChannelThreadPool $ Channel

388

388

com.mchange.v2.async.ThreadPoolAsynchronousRunner

288

288

com.mchange.v2.resourcepool.BasicResourcePool

2

2

EDU.oswego.cs.dl.util.concurrent.Semaphore

97

97

java.lang.Class

1

1

java.lang.Object

1065

291

1356

java.lang.ref.Reference $ Блокировка

97

97

java.lang.ref.ReferenceQueue $ Блокировка

485

485

java.util.concurrent.locks.AbstractQueuedSynchronizer $ ConditionObject

580

485

1065

java.util.concurrent.Semaphore $ NonfairSync

97

97

java.util.concurrent.SynchronousQueue $ TransferStack

380

380

java.util.HashMap

1

1

java.util.LinkedList

388

388

java.util.TaskQueue

485

194

+679

java.util.TreeSet

97

97

org.apache.tomcat.util.net.JIoEndpoint $ Worker

6531

6531

org.apache.tomcat.util.net.JIoEndpoint $ WorkerStack

2

2

org.hornetq.core.postoffice.impl.PostOfficeImpl $ Жнец

97

97

org.hornetq.core.remoting.server.impl.RemotingServiceImpl $ FailureCheckAndFlushThread

97

97

org.hsqldb.lib.HsqlTimer $ TaskQueue

96

96

sun.misc.GC $ LatencyLock

97

97

Общий итог

2

3379

9057

12438

The pivot table like the one above, allows to see where the threads are waiting and/or blocked. The stack traces are readily available to drill down. This allowed to identify memcached client default configuration as a bottle neck in my practice along as pointed to architectural deficiency created by the use of the memcached values through application life cycle. It manifested itself though as BLOCKED threads on com.mchange.v2.resourcepool.BasicResourcePool — JDBC connections not released in time for others to re-use.

Additional clues that can be collected are exceptions from log files (artifact 4) or errors from artifact 5. First one can be collected by the following command with the manual aggregation:

grep -r Exception server.* > exceptions.txt

Second one will have all the aggregation already done. Of particular interest are timeout related messages in the logs:

grep -ir timeout server.* > timeout.txt

Everything else is application specific and will reflect logging messages of a particular system. It can be processed in the same way to extract metrics and correlate them over time.

With all the information at hand, start from the timestamp of the incident and go back in time through the artifacts to find the tipping point where it all started collapsing. You may find multiple issues nested one on top of another. Create an action plan for each issue and work to implement the fixes one by one. It can take multiple iterations in production to iron out all of those, so be patient and keep hunting.