Анализ неточного распределения Wrk Latency

wrk — это отличный инструмент для стресс-тестирования HTTP, построенный на основе проектов с открытым исходным кодом, таких как Redis, NGINX, Node.js и LuaJIT. Он использует их сильные стороны в событийно-ориентированности, парсинге HTTP, высокой производительности и гибкости, а также позволяет писать собственные Lua-скрипты для генерации тестовых запросов.

Хотя у wrk нет тестовых случаев, и автор появляется примерно раз в год, чтобы объединить код, это не мешает нам использовать wrk в качестве основного инструмента для тестирования производительности и фаззинга. Если вы до сих пор используете многопоточный ab, стоит попробовать wrk.

Ниже приведена часть статистики распределения задержек из результатов wrk.

    Latency Distribution
     50%    1.20ms
     75%  595.78ms
     90%  899.11ms
     99%    1.00s

Этот пример означает, что 50% запросов завершаются за 1.2 мс, 90% запросов завершаются за 899 мс, а 99% запросов завершаются за 1 секунду.

Когда мы использовали wrk для стресс-тестирования нашего продукта, мы обнаружили, что большинство запросов в статистике задержек wrk завершались за несколько миллисекунд, но небольшой процент запросов имел задержку более 100 миллисекунд. Для системы, построенной на OpenResty, такая большая задержка не является научно обоснованной.

Хотя окончательное решение этой проблемы оказалось очень простым, конкретный анализ и локализация заняли несколько дней и были довольно запутанными. Само решение не так важно; интересен процесс и способ мышления при решении проблемы.

Когда мы сталкиваемся с проблемами задержек, наша первая реакция — это предположение, что где-то в коде или системе есть блокировка. Поскольку система сложная, мы предлагаем использовать флеймграфы.

Готового скрипта systemtap для анализа такого рода проблем не было, поэтому потребовалось время, чтобы написать его. Однако после нескольких корректировок скрипта systemtap значительных задержек обнаружено не было, что явно противоречит результатам wrk. Мы предположили, что скрипт может быть не идеальным и мог пропустить некоторые функции, которые не были захвачены. Но у нас также возникли сомнения в правильности результатов wrk.

Мы решили проверить, ошибочны ли статистические данные wrk или проблема действительно на стороне сервера. Мы захватили все пакеты с теста на сервере, где запущен wrk, отсортировали их по времени выполнения и с удивлением обнаружили, что результаты сильно отличаются от статистики задержек wrk — ни один запрос не превышал 100 миллисекунд. Я повторил тест несколько раз, и результаты были одинаковыми.

Теперь цель ясна: нужно разобраться с кодом wrk, касающимся статистики задержек. Самое большое опасение — это наличие бага во внутренней статистике wrk, который будет непросто исправить, учитывая, что это проект без тестовых случаев.

Мы изучили логику статистики wrk и добавили логи в начале и конце, с облегчением обнаружив, что данные о задержках были правильными. Но перед выводом окончательных результатов есть код statistic correction.

    if (complete / cfg.connections > 0) {
        int64_t interval = runtime_us / (complete / cfg.connections);
        stats_correct(statistics.latency, interval);
    }

Согласно этому условию, всякий раз, когда генерируются данные о задержках, они корректируются. Если вам интересно, вы можете посмотреть код функции stats_correct, он состоит всего из 10 строк, но я не смог понять его даже после нескольких прочтений.

Проверив историю коммитов, мы нашли только одну строку, которая также не была понятна:

remove calibration & improve CO correction

Если бы запись коммита была немного подробнее, без сокращений или с комментариями к коду, это могло бы сэкономить много времени.

Проблема была проверена, и можно подтвердить, что это не проблема продукта. Решение уже есть — закомментировать корректирующий код выше. Но у автора wrk, вероятно, была причина добавить его, и непонимание этой причины остается скрытой проблемой. Естественно, я создал issue, чтобы спросить автора, и wg, который появляется раз в год, ответил через 15 дней. Оказалось, что сокращение CO в коммите относится к Coordinated Omission, и он предоставил статью, посвященную этой проблеме. Заинтересованные могут поискать по этому ключевому слову.

Проще говоря, Coordinated Omission означает, что при стресс-тестировании недостаточно учитывать только время между отправкой и получением ответа (это service time), так как это пропускает множество потенциальных проблем. Необходимо также учитывать время ожидания тестового запроса, чтобы получить response time, который важен для пользователей.

Gil Tene, предложивший проблему CO, также внес изменения в wrk для решения этой проблемы: https://github.com/giltene/wrk2. В README этого проекта есть объяснения, которые можно прочитать, если интересно.

Для нашего продукта, конечно, нет блокировок в коде, и при проведении стресс-тестов процессор загружен полностью. Даже если есть блокировки, флеймграфы позволяют их обнаружить и проанализировать. Поэтому простая и грубая коррекция, которую wrk делает для Coordinated Omission, может вводить в заблуждение.