[Из песочницы] Плагин CsvLogWriter для JMeter

Введение
Наверняка каждый, кто пользовался стандартными листенерами в JMeter, сталкивался со следующими ограничениями:

стандартные листенеры не позволяют получить подробную информацию по всем запросам, прописанным в тест плане;
стандартные листенеры выводят информацию в XML — формате, что осложняет дальнейший анализ логов средствами Excel и IPython.

Чтобы обойти данные ограничения, было принято решение переработать формирование лог-файлов с помощью нового плагина CsvLogWriter.

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

вывод полного текста ошибки в строковом формате;
фиксация данных по дочерним подзапросам.

В стандартных листенерах для JMeter фиксация полного содержания ошибки возможна в XML-формате, что доставляет неудобства для анализа. Возникла потребность сохранять текст ошибки в строковом формате с последующей записью, например, в CSV-формат для обеспечения возможности построения графиков в Excel и IPython. Обычно получаемые лог-файлы не отображают данные по дочерним подзапросам. Что крайне неудобно при использовании сложной структуры тест-плана. Пример структуры продемонстрирован на рисунке 1.

Рисунок 1. Структура тест-плана

При использовании стандартных листенеров мы сможем получить данные только по Transaction Controller1. Исходя из этого было решено добавить фиксацию данных по дочерним подзапросам, таким образом получить результаты мы сможем по Transaction Controller1, Transaction Controller 2 и вложенным в него семплерам.

Описание функционала плагина pflb@CsvLogWriter
В ходе работы был написан плагин pflb@CsvLogWriter для JMeter. К ключевым особенностям данного плагина можно отнести то, что он может фиксировать результаты работы дочерних подзапросов и записывать полный текст ошибки, при ее возникновении, в виде обычного текста, а не в XML-формате.

Формат лога
Данные, фиксируемые в лог-файле, представлены в таблице 1.
Таблица 1. Формат лога
№
Имя
Тип
Описание
Примеры значений для колонки лога
Единица измерения
1
timeStamp
long
Время начала или конца запроса
мс
2
elapsed
long
Длительность обработки запроса: endTime — startTime — idleTime
49, 434
мс
3
label
String
Наименование компонента JMeter
4
responseCode
String
Код ответа на запрос
«200», «Non HTTP response code: java.net.UnknownHostException»
5
responseMessage
String
Расшифровка кода ответа
«OK», «Internal Server Error»
6
threadName
String
Имя потока
«Thread Group 1-1»
7
dataType
String
Тип данных в ответе, на практике принимает два значения — «bin» или «text»
«bin», «text»
8
success
boolean
Статус успешности выполнения запроса
true или false
9
failureMessage
String
Сообщение об ошибке,
в случае срабатывания Assertion-компонента,
добавленного к Sampler-у.
В CsvLogWriter в поле записываются сообщения
ото всех Assertion-компонентов,
выполнение которых сгенерировало ошибку.
В базовом логере записывается только первое сообщение.
10
bytes
int
Размер ответа.
Значение и алгоритм расчёта зависят от настроек
sampler-а. На значение могут влиять responseData.length,
headersSize, bodySize.
Байт
11
grpThreads
int
Количество активных потоков в текущей группе
12
allThreads
int
Количество активных виртуальных пользователей всех групп
13
URL
String
Ссылка
14
Filename
String
Наименования файла, в который записываются ответы.
Поле заполняется при использовании Save Response to File Listener.
Этот Listener редко используется, обычно значение колонки
— пустая строка
15
Latency
int
Время до получения первого ответа сервера.
Эта временная задержка включает в себя время,
потраченное на соединение с сервером,
задержки, обусловленные установкой защищённого соединения,
и внутренними задержками JMeter на получение
первых байт ответа сервера. Если по какой-то причине
работа Sampler-а была приостановлена, а потом возобновлена,
то значение Latency будет скорректировано
на длительность приостановки Sampler-а.
мс
16
Encoding
String
Кодировка. Возвращается кодировка ответа,
если кодировка ответа не задана,
то возвращается значение кодировки по умолчанию.
Значение кодировки по умолчанию задано в
«sampleresult.default.encoding».
Для HTTP Request значение по умолчанию «ISO-8859-1».
«ISO-8859-1», «UTF-8»
17
SampleCount
int
Количество семплов.
Для HTTP Request значение равно 1.
Для JMS Sampler, выполняющего подписку на события
и чтение нескольких сообщений за раз,
значение равно количеству циклов опроса
или количеству прочитанных сообщений.
Значение всегда больше или равно одному.
1, 2
шт
18
ErrorCount
int
Количество ошибок.
Для HTTP Request значение равно 0 если success
и равно 1 если запрос не успешный.
Для других sampler-ов выполняющих обработку
нескольких сообщений за раз,
значение может быть больше 1.
0, 1
шт
19
Hostname
String
Наименование машины
20
IdleTime
int
Время простоя
мс
21
Connect
int
Время, затраченное на установку соединения
мс
22
headersSize
int
Размер заголовков
Байт
23
bodySize
int
Размера тела
Байт
24
contentType
String
Тип содержимого из заголовка ответа
25
endTime
long
Время конца запроса
мс
26
isMonitor
boolean
Признак поставлена ли галочка Use as Monitor
true, false
27
threadName_label
String
Наименование треда и компонента JMeter
28
parent_threadName_label
String
Наименование треда и компонента JMeter родителя
29
startTime
long
Время начала запроса
мс
30
stopTest
boolean
Признак остановлен ли тест — кнопка Stop.
Также в настройках Thread Group есть опция
«Stop Test» при ошибке. Если в колонке «stopTest»
стоит true, значит произошла именно такая ситуация.
Сценарий прервался на текущем запросе.
true, false
31
stopTestNow
boolean
Признак остановлен ли тест резко — кнопка Shutdown.
Также в настройках Thread Group есть опция
«Stop Test Now» при ошибке. Если в колонке «stopTestNow»
стоит true, значит произошла именно такая ситуация.
Сценарий прервался на текущем запросе.
true, false
32
stopThread
boolean
Признак остановлен ли текущий поток.
В настройках Thread Group есть опция «Stop Thread»
при ошибке. Если в колонке «stopThread» стоит true,
значит произошла именно такая ситуация.
Сценарий прервался на текущем запросе.
true, false
33
startNextThreadLoop
boolean
Стартует ли повтор.
В настройках Thread Group есть опция «Start Next Thread Loop»
при ошибке. Если в колонке «startNextThreadLoop» стоит true,
значит произошла именно такая ситуация.
Сценарий прервался на текущем запросе.
true, false
34
isTransactionSampleEvent
boolean
Признак того, что текущее событие является транзакцией (TransactionController). То есть, это лишь группирующий элемент.
true, false
35
transactionLevel
int
Уровень вложенности запроса.
Если используется иерархия Transaction Controller
или у подзапросов есть подзапросы,
то в данной колонке будет уровень вложенности.
0 для корневого запроса или корневого Transaction Controller.
1 для подзапроса, родитель которого является корневым.
36
responseDataAsString
String
Полное содержание ошибки в формате строки
в случае ее возникновения, если success == false,
то в responseData будет содержаться полное тело ответа
37
requestHeaders
String
Заголовки запроса
38
responseData
String
Полное содержание ошибки в случае ее возникновения,
если success == false, то в responseData будет содержаться
полное тело ответа, перекодированное в base64
39
responseHeaders
String
Заголовки ответа
40
<Имя переменной>
String
Переменные JMeter

Структура лога расширяет базовый формат CSV лога. С базовым набором параметров можно ознакомиться по ссылке jmeter.apache.org/usermanual/listeners.html#csvlogformat

Полученный CSV-лог можно загрузить любым базовым Listener-ом JMeter, поддерживающим загрузку CSV-лога.
Также в логе появились дополнительные колонки, которые могут пригодится при анализе (стр. 22-35 таблицы Формат лога).
Тела и заголовки ответов и запросов записываются только при ошибках (стр. 36-39 таблицы Формат лога).
Также в лог запишутся колонки для переменных: jmeter.apache.org/usermanual/listeners.html#sample_variables — описание возможности логировать значения переменных.

Интерфейс
Для запуска плагина необходимо заполнить поле Filename. Поле Filename содержит путь к файлу, в котором будет вестись фиксация результатов работы. Можно прописать директорию вручную, или выбрать файл используя кнопку Browse. Если указанный файл существует, то создается новый файл. Наименование нового лог-файла формируется добавлением постфикса с номером лог-файла к оригинальному наименованию.

Так же на форме расположены флажки. С помощью флажков можно манипулировать данными, фиксируемыми в логе. Флажок Additional parameters отвечает за фиксацию дополнительных параметров (22-35 строки в таблице Формат лога), Response data отвечает за фиксацию текста ошибок (36-39 строки в таблице Формат лога), User variables отвечает за фиксацию пользовательских переменных.

Интерфейс плагина представлен на рисунке 2.

Рисунок 2. Интерфейс плагина CSVLogWriter

Сравнение плагина CSVLogWriter и Simple Data Writer
В данном разделе попробуем провести сравнение плагина CsvLogWriter и стандартного листенера Simple Data Writer.

Состав логируемых данных
Листенер Simple Data Writer дает пользователю возможность настроить список фиксируемых данных. На рисунке 3 показано окно настроек выводимых данных.

Рисунок 3. Окно настроек фиксируемых данных листенера Simple Data Writer

Плагин CsvLogWriter всегда выводит базовый перечень параметров (аналогичный Simple Data Writer) и позволяет настроить вывод списка дополнительных данных с помощью 3 флажков на форме:

Additional parameters — дополнительные параметры (22-35 строки в таблице Формат лога);
Response data — тексты ошибок (36-39 строки в таблице Формат лога);
User variables — пользовательские переменные (для вывода необходимо запускать JMeter с ключом -Jsample_variables).

Детальный перечень фиксируемых данных жестко прописан в коде. Но, как видно на рисунке 3, Simple Data Writer не может выводить текст ошибки в строковом формате. Полный текст ошибки фиксируется только в XML формате. По этой причине в случае, когда нам необходим текст ошибок приходится вести 2 лога — 1 в CSV-формате (если необходима дальнейшая обработка лога с построением графиков в Excel или iPython) и 1 в XML-формате.

Логирование подзапросов
Так же, листенер Simple Data Writer не фиксирует результаты работы дочерних подзапросов, соответственно, такой лог-файл нельзя назвать исчерпывающим. Для наглядного сравнения объема выводимых данных запустим тест, соответствующий тест-плану на рисунке 1, и посмотрим на лог-файлы. Лог-файл SimpleDataWriter представлен на рисунке 4.

Рисунок 4. Лог-файл Simple Data Writer

Как видно на рисунке 4, SimpleDataWriter выводит информацию только по Transaction Controller1. В свою очередь, плагин CsvLogWriter за счет обработки дочерних подзапросов выводит гораздо больше информации. Содержание лог-файла плагина CsvLogWriter представлено на рисунке 5.

Рисунок 5. Лог-файл CsvLogWriter

Сравнение быстродействия
Так же проводился анализ быстродействия метода SimpleOccured, отвечающего за обработку событий. Профилирование велось в Java VisualVM. В тест плане не использовались подзапросы. Для SimpleDataWriter тестирование запускалось с записью в 1 CSV-файл и с записью в 2 файла — CSV и XML. Количество виртуальных пользователей составляло 10, количество повторение 100. Итоги сравнения приведены в таблице 2.

Таблица 2. Сравнение быстродействия SimpleDataWriter и плагина CsvLogWriter
CsvLogWriter
SimpleDataWriter (CSV+XML)
SimpleDataWriter (CSV)
Длительность (мс), количество вызовов
Длительность (мс), количество вызовов
Длительность (мс), количество вызовов
215, 2000
23076, 4000
101, 2000

Выводы:

CsvLogWriter в 10 раз быстрее SimpleDataWriter (XML с максимальной детализацией);
CsvLogWriter в 2 раза медленнее SimpleDataWriter (CSV с максимальной детализацией);
SimpleDataWriter (XML с максимальной детализацией) в 20 раз медленнее SimpleDataWriter (CSV с максимальной детализацией).

Ссылка на плагин
github.com/pflb/Jmeter.Plugin.CsvLogWriter

стандартные листенеры не позволяют получить подробную информацию по всем запросам, прописанным в тест плане;
стандартные листенеры выводят информацию в XML — формате, что осложняет дальнейший анализ логов средствами Excel и IPython.

вывод полного текста ошибки в строковом формате;
фиксация данных по дочерним подзапросам.