Русский
Русский
English
Статистика
Реклама

Profiling

Профилирование. Отслеживаем состояние боевого окружения с помощью Redis, ClickHouse и Grafana

14.07.2020 10:11:05 | Автор: admin

прим. latency/time.

Наверное перед каждым возникает задача профилирования кода в продакшене. С этой задачей хорошо справляется xhprof от Facebook. Вы профилируете, к примеру, 1/1000 запросов и видите картину на текущий момент. После каждого релиза прибегает продакт и говорит до релиза было лучше и быстрее. Исторических данных у вас нет и доказать вы ничего не можете. А что если бы могли?

Не так давно, переписывали проблемный участок кода и ожидали сильный прирост производительности. Написали юнит-тесты, провели нагрузочное тестирование, но как код поведет себя под живой нагрузкой? Ведь мы знаем, нагрузочное тестирование не всегда отображает реальные данные, а после деплоя необходимо быстро получить обратную связь от вашего кода. Если вы собираете данные, то, после релиза, вам достаточно 10-15 минут чтобы понять обстановку в боевом окружении.


прим. latency/time. (1) деплой, (2) откат

Стек


Для своей задачи мы взяли колоночную базу данных ClickHouse (сокр. кх). Скорость, линейная масштабируемость, сжатие данных и отсутствие deadlock стали главными причинами такого выбора. Сейчас это одна из основных баз в проекте.

В первой версии мы писали сообщения в очередь, а уже консьюмерами записывали в ClickHouse. Задержка достигала 3-4 часа (да, ClickHouse медленный на вставку по одной записи). Время шло и надо было что-то менять. Реагировать на оповещения с такой задержкой не было смысла. Тогда мы написали крон-команду, которая выбирала из очереди необходимое количество сообщений и отправляла пачку в базу, после, помечала их обработанными в очереди. Первые пару месяцев все было хорошо, пока и тут не начались в проблемы. Событий стало слишком много, начали появляться дубли данных в базе, очереди использовались не по-прямому назначению (стали базой данных), а крон-команда перестала справляться с записью в ClickHouse. За это время в проект добавилось ещё пара десятков таблиц, которые необходимо было писать пачками в кх. Скорость обработки упала. Необходимо было максимально простое и быстрое решение. Это подтолкнуло нас к написанию кода с помощью списков на redis. Идея такая: записываем сообщения в конец списка, крон-командой формируем пачку и отправляем её в очередь. Дальше консьюмеры разбирают очередь и записывают пачку сообщений в кх.

Имеем: ClickHouse, Redis и очередь (любую rabbitmq, kafka, beanstalkd)

Redis и списки


До определенного времени, Redis использовался как кэш, но всё меняется. База имеет огромный функционал, а для нашей задачи необходимы всего 3 команды: rpush, lrange и ltrim.

С помощью команды rpush будем записывать данные в конец списка. В крон-команде читать данные с помощью lrange и отправлять в очередь, если нам удалось отправить в очередь, то необходимо удалить выбранные данные с помощью ltrim.

От теории к практике. Создаем простой список.



У нас есть список из трех сообщений, добавим ещё немного



Новые сообщения добавляются в конец списка. С помощью команды lrange выбираем пачку (пусть будет =5 сообщений).



Далее пачку отправляем в очередь. Теперь необходимо удалить эту пачку из Redis, чтобы не отправить её повторно.



Алгоритм есть, приступим к реализации.

Реализация


Начнем с таблицы ClickHouse. Не стал сильно заморачиваться и определил всё в тип String.

create table profile_logs(    hostname   String, // хост бэкэнда, отправляющего событие    project    String, // название проекта    version    String, // версия фреймворка    userId     Nullable(String),    sessionId  Nullable(String),    requestId  String, // уникальная строка для всего запроса от клиента    requestIp  String, // ip клиента    eventName  String, // имя события    target     String, // URL    latency    Float32, // время выполнения (latency=endTime - beginTime)    memoryPeak Int32,    date       Date,    created    DateTime)    engine = MergeTree(date, (date, project, eventName), 8192);


Событие будет таким:
{  "hostname": "debian-fsn1-2",  "project": "habr",  "version": "7.19.1",  "userId": null,  "sessionId": "Vv6ahLm0ZMrpOIMCZeJKEU0CTukTGM3bz0XVrM70",  "requestId": "9c73b19b973ca460",  "requestIp": "46.229.168.146",  "eventName": "app:init",  "target": "/",  "latency": 0.01384348869323730,  "memoryPeak": 2097152,  "date": "2020-07-13",  "created": "2020-07-13 13:59:02"}


Структура определена. Чтобы посчитать latency нам нужен временной промежуток. Засекаем с помощью функции microtime:
$beginTime = microtime(true);// код который необходимо отслеживать$latency = microtime(true) - $beginTime;


Для упрощения реализации, будем использовать фреймворк laravel и библиотеку laravel-entry. Добавим модель (таблица profile_logs):
class ProfileLog extends \Bavix\Entry\Models\Entry{    protected $fillable = [        'hostname',        'project',        'version',        'userId',        'sessionId',        'requestId',        'requestIp',        'eventName',        'target',        'latency',        'memoryPeak',        'date',        'created',    ];    protected $casts = [        'date' => 'date:Y-m-d',        'created' => 'datetime:Y-m-d H:i:s',    ];}


Напишем метод tick (я сделал сервис ProfileLogService), который будет записывать сообщения в Redis. Получаем текущее время (наш beginTime) и записываем его в переменную $currentTime:
$currentTime = \microtime(true);


Если тик по событию вызван впервые, то записываем его в массив тиков и завершаем метод:
 if (empty($this->ticks[$eventName])) {    $this->ticks[$eventName] = $currentTime;    return;}


Если тик вызывается повторно, то мы записываем сообщение в Redis, с помощью метода rpush:
$tickTime = $this->ticks[$eventName];unset($this->ticks[$eventName]);Redis::rpush('events:profile_logs', \json_encode([    'hostname' => \gethostname(),    'project' => 'habr',    'version' => \app()->version(),    'userId' => Auth::id(),    'sessionId' => \session()->getId(),    'requestId' => \bin2hex(\random_bytes(8)),    'requestIp' => \request()->getClientIp(),    'eventName' => $eventName,    'target' => \request()->getRequestUri(),    'latency' => $currentTime - $tickTime,    'memoryPeak' => \memory_get_usage(true),    'date' => $tickTime,    'created' => $tickTime,]));


Переменая $this->ticks не статическая. Необходимо зарегистрировать сервис как singleton.

$this->app->singleton(ProfileLogService::class);


Размер пачки ($batchSize) можно сконфигурировать, рекомендуется указывать небольшое значние (например, 10,000 элементов). При возникновении проблем (к примеру, не доступен ClickHouse), очередь начнет уходить в failed, и вам необходимо отлаживать данные.

Напишем крон-команду:
$batchSize = 10000;$key = 'events:profile_logs'do {    $bulkData = Redis::lrange($key, 0, \max($batchSize - 1, 0));    $count = \count($bulkData);    if ($count) {        // все данные храним в json, необходимо применить decode        foreach ($bulkData as $itemKey => $itemValue) {            $bulkData[$itemKey] = \json_decode($itemValue, true);        }        // отправляем в очередь для записи в ch        \dispatch(new BulkWriter($bulkData));        // удаляем пачку из redis        Redis::ltrim($key, $count, -1);    }} while ($count >= $batchSize);


Можно сразу записывать данные в ClickHouse, но, проблема кроется в том, что крон работает в однопоточном режиме. Поэтому мы пойдем другим путем командой сформируем пачки и отправим их в очередь, для последующей многопоточной записи в ClickHouse. Количество консьюмеров можно регулировать это ускорит отправку сообщений.

Перейдем к написанию консьюмера:
class BulkWriter implements ShouldQueue{    use Dispatchable, InteractsWithQueue, Queueable, SerializesModels;    protected $bulkData;    public function __construct(array $bulkData)    {        $this->bulkData = $bulkData;    }    public function handle(): void    {            ProfileLog::insert($this->bulkData);        }    }}


Итак, формирование пачек, отправка в очередь и консьюмер разработаны можно приступать к профилированию:
app(ProfileLogService::class)->tick('post::paginate');$posts = Post::query()->paginate();$response = view('posts', \compact('posts'));app(ProfileLogService::class)->tick('post::paginate');return $response;


Если все сделано верно, то данные должны находиться в Redis. Запутим крон-команду и отправим пачки в очередь, а уже консьюмер вставит их в базу.



Данные в базе. Можно строить графики.

Grafana


Теперь перейдем к графическому представлению данных, что является ключевым элементом этой статьи. Необходимо установить grafana. Опустим процесс установки для debain-подобных сборок, можно воспользоваться ссылкой на документацию. Обычно, этап установки сводится к apt install grafana.

На ArchLinux установка выглядит следующим образом:
yaourt -S grafanasudo systemctl start grafana


Сервис запустился. URL: http://localhost:3000

Теперь необходимо установить ClickHouse datasource plugin:
sudo grafana-cli plugins install vertamedia-clickhouse-datasource


Если установили grafana 7+, то ClickHouse работать не будет. Нужно внести изменения в конфигурацию:
sudo vi /etc/grafana.ini


Найдем строку:
;allow_loading_unsigned_plugins =


Заменим её на эту:
allow_loading_unsigned_plugins=vertamedia-clickhouse-datasource


Сохраним и перезапустим сервис:
sudo systemctl restart grafana


Готово. Теперь можем перейти в grafana.
Логин: admin / пароль: admin по умолчанию.



После успешной авторизации, нажмем на шестеренку. В открывшемся popup-окне выберем на Data Sources, добавим соединение с ClickHouse.



Заполняем конфигурацию кх. Нажимаем на кнопку Save & Test, получаем сообщение об успешном соединении.

Теперь добавим новый dashboard:


Добавим панель:


Выберем базу и соответствующие колонки для работы с датами:


Перейдем к запросу:


Получили график, но хочется конкретики. Давайте выведем средний latency с округлением даты-с-временем вниз до начала пятиминутного интервала:


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


Профилировщик, ни в коем случае, не является заменой инструментам: xhprof (facebook), xhprof (tideways), liveprof от (Badoo). А только дополняет их.

Весь исходный код находится на github модель профилировщика, сервис, BulkWriteCommand, BulkWriterJob и middleware (1, 2).

Установка пакета:
composer req bavix/laravel-prof


Настройка соединений (config/database.php), добавляем clickhouse:
'bavix::clickhouse' => [    'driver' => 'bavix::clickhouse',    'host' => env('CH_HOST'),    'port' => env('CH_PORT'),    'database' => env('CH_DATABASE'),    'username' => env('CH_USERNAME'),    'password' => env('CH_PASSWORD'),],


Начало работы:
use Bavix\Prof\Services\ProfileLogService;// ...app(ProfileLogService::class)->tick('event-name');// кодapp(ProfileLogService::class)->tick('event-name');


Для отправки пачки в очередь нужно добавить команду в cron:
* * * * * php /var/www/site.com/artisan entry:bulk


Также необходимо запустить консьюмер:
php artisan queue:work --sleep=3 --tries=3

Рекомендуется настроить supervisor. Конфиг (5 консьюмеров):
[program:bulk_write]process_name=%(program_name)s_%(process_num)02dcommand=php /var/www/site.com/artisan queue:work --sleep=3 --tries=3autostart=trueautorestart=trueuser=www-datanumprocs=5redirect_stderr=truestopwaitsecs=3600


UPD:
1. ClickHouse нативно умеет тянуть данные из очереди kafka. Спасибо, sdm
Подробнее..

PHP-SPX простой профайлер трейсер для PHP

16.05.2021 14:08:59 | Автор: admin
Работая с различными PHP проектами часто приходится дебажить приложение чтобынайти и исправить ошибку. Во многих случаях вполне хватает xDebug, однако он не подходит для всех задач. Иногда нужно понять почему та или иная страница долго загружается, что съедает так много памяти или просто как работает большой и запутанный код.
php-spx logo webmageic

В практике приходилось попробовать профилирование с помощью xDebug с дальнейшим построением Flame Graphs но поскольку дамп генерируется долго, а сам граф нужно сделать отдельно, то такой подход не прижился.

Визуализация в QCacheGrind справлялась лучше, но не всегда давала понять что не так.

xHprof был достаточно быстрым но имел тот же недостаток с удобством визуализацией данных.

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

В последнее время я много работаю с Magento 2, но несмотря на довольно хорошую документацию, в реальности мы сталкиваемся реальными челенджами.

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

Поэтому как то в поисках хорошего визуализатора трейсов в виде таймлайнов для PHP я наткнулся на репозиторий PHP-SPX (Simple Profiling eXtension)

Первое на что я обратил внимание, это превью-анимация с таймлайном, флейм графом и списком вызова функций:
image

Мне показалось что это именно то что нужно, все необходимое, да еще и в одном месете. Больше всего меня заинтересовал таймлайн, т.к. он ну очень похож на тот который предлагает Blackfire и Tideways.

По кратким просмотре документации, я решил попробовать установить профайлер.
Доки нам говорят что достаточно скачать исходники и собрать все с помощью phpize и make, а далее подключить в php.ini

git clone https://github.com/NoiseByNorthwest/php-spx.gitcd php-spxphpize./configuremakesudo make install

В случае с докером все так же, только можно переместить исходники в более удобное место. В моем случае это было так:

RUN cd /usr/lib && git clone https://github.com/NoiseByNorthwest/php-spx.gitRUN cd /usr/lib/php-spx && phpize && ./configure && make && make install

Добавляем расширение в конфиг php.ini, тут можем подстроить некоторые параметры:

extension = /usr/lib/php-spx/modules/spx.sospx.http_enabled = 1spx.http_key = "dev" #ключ доступа к панели и триггерspx.http_ip_whitelist = "*" #список IP через запятую с которых разрешено профилированиеspx.data_dir = /var/www/html/spx_dumps #место сохранение дампов, по умолчанию - /tmp/spx


Поскольку профилирование разрешено со всех IP, то просто переходим по такому URL в php проекте.
http://localhost/?SPX_KEY=dev&SPX_UI_URI=/ 


Если все работает правильно то расширение перехватит запрос к приложению и подменит ответ своей панелью управления.
image

Далее отмечаем чекбокс Enabled и открываем любой URL приложения в новой вкладке (например главную страницу).
Профилировать можно и с помощью curl, достаточно добавить соответствующие куки.
curl --cookie "SPX_ENABLED=1; SPX_KEY=dev" http://localhost/


Подобным способом можно дебажить и консольные команды:
SPX_ENABLED=1 SPX_REPORT=full ./bin/console


После чего обновляем страницу панели управления и смотрим что есть в списке дампов. Следует отметить, что SPX имеет довольно низкий оверхед, что почти не влияет на время выполнения приложения.
php-spx dumps list

Открываем дамп, ждем конца загрузки:


Видим визуализацию всех вызовов PHP функций и методов в трех вариантах.
Timeline, Flat profile и Flame Graph.
php-spx webmageic

На таймлайне можем увеличивать и просматривать весь порядок вызовов вплоть до микро и наносекунд. Есть возможность также подсветки функций кликом.


Либо изменения цветов по паттерну регулярного выражения во вкладке category


Такая визуализация позволяет упростить анализ PHP приложения, найти различные места с проблемами производительности, а также просто понять что происходит внутри.
На примере профиля из Magento 2 могу сказать что на огромном таймлайне можем найти увидеть интересных вещей которые происходят внутри.


Часто можно увидеть такой паттерн-пилу, обычно это означает загрузку данных либо другие операции в цикле. В данном примере это проблема N+1 загрузки URL категорий.


Либо другой пример, когда после выполнения SQL запроса приложение создает PHP объекты.


Если включить добавление внутренних функций PHP в дампы, то увидим их на зуме до микро и наносекунд. Однако такой низкий уровень скорее полезный только для лучшего анализа колл стека чем поиска проблем с производительностью, с исключением возможных curl на внешние API, чтения больших файлов либо других специфических случаев. Обычно обертки фреймворка вполне достаточно для понимания происходящего.


Я использую PHP-SPX в паре с xDebug, это улучшает поиск подходящих мест для брейкпоинтов, а визуализация позволят лучше понять флов выполнения, что очень ускоряет знакомство с ранее неизвестными частями приложения.

Еще несколько примечаний от главного разработчика PHP-SPX:
  • автор не считает что расширение готово к использованию в продакшене, поэтому лучше устанавливать его только локально и на тестовые сервера
  • единственное ограничение доступа к профилированию через веб-интерфейс это белый список IP и параметр SPX_KEY

Итоги:


Из своего опыта использования, могу сказать, что на данный момент PHP-SPX это самый удобный Open-Source профайлер-трейсер для PHP с хорошей визуализацией. Много раз выполнял роль чит-кода позволяющего быстрее разобраться с новым кодом, найти и исправить различные проблемы производительности (особенно в Magento 2), а так же самому писать более надежный и эффективный код.

Если внедрятся глубже в тему профилирования и производительности в PHP то хорошим вариантом будет использование продвинутых платных расширений Blackfire либо Tideways, которые имеют имеют более широкие возможности визуализации, сравнения дампов, внедрения в пайплайны и другие фичи.

Однако в случае с таймлайном более подробным есть PHP-SPX т.к. он записывает все вызовы (по умолчанию семплинг не используется) в то время как Blackfire ограничивает нас до 1% времени выполнения:
The Timeline Threshold is not an absolute value. It is relative to the way your application performs. The threshold value is calculated by Blackfire as 1% of the duration of the profiled page/script
источник


Может быть кто-то из читателей поделиться в комментариях своим опытом использования PHP-SPX либо других инструментов при разработке PHP приложений?
Демо PHP-SPX можно посмотреть тут
Более подробную информацию о всех настройках и возможностях можно найти в репозитории.
Подробнее..

Профилирование в облаке и не только

05.01.2021 12:12:21 | Автор: admin

Приложение, оптимально использующее вычислительные ресурсы, это всегда хорошо и приятно. А если такое приложение работает в облаке, то ещё и выгодно. Порой очень выгодно. Просто потому, что в один квант оплаченного облачного вычислительного ресурса влезает, например, больше показанных в браузере котиков вместе с рекламой или платёжных транзакций за подписки на тех же котиков. И если с профилированием Go приложений всё более или менее понятно, то для приложений, написанных на C или C++, всё гораздо интереснее.


Так как большинство проблем с производительностью материализуются, как правило, в продакшене, то нас будут интересовать те инструменты, которые не требуют инструментализации кода и, следовательно, остановки и перезапуска рабочих процессов. Кроме того, я не буду упоминать профилировщики, которые анализируют работу кода на уровне микроархитектуры процессора типа vTune. Во-первых, на эту тему статей и так хватает. Во-вторых, я ошибочно полагаю, что вопросы микроархитектуры больше актуальны для разработчиков middleware типа серверов баз данных или библиотек, которые настолько круты, что Хабр не читают. Итак.


До недавнего времени одним из таких инструментов были Google perftools. Они включают два профилировщика: для CPU и для оперативной памяти. Начнём с первого.


Чтобы ваша программа стала профилируемой, её необходимо слинковать вместе с профилировщиком. Можно статически, можно динамически или же вообще подгрузить при помощи LD_PRELOAD. Его размер составляет около 60k, и он более никак не нагружает систему, когда не используется. Так что всегда линковаться с ним на боевых серверах будет не слишком накладно. Активируется он установкой переменной окружения CPUPROFILE:


$ CPUPROFILE=/tmp/envoy.prof envoy --concurrency 1 -c /path/to/config.yaml

В этом случае статистика начинает собираться с момента запуска исполняемого файла. Если дополнительно установить CPUPROFILESIGNAL=12, то активация будет включаться и выключаться по пользовательскому сигналу 12 (SIGUSR2).


Принцип работы CPU-профилировщика заключается в том, что он периодически (период тоже можно изменить) делает снимок текущих стеков процесса и сохраняет их файл, который можно проанализировать утилитой pprof. Например, чтобы быстро оценить, какие функции больше других или, точнее сказать, чаще других нагружают процессор, достаточно ввести


$ pprof -text /tmp/envoy.profFile: envoy-staticType: cpuShowing nodes accounting for 17.74s, 86.75% of 20.45s totalDropped 900 nodes (cum <= 0.10s)      flat  flat%   sum%        cum   cum%     5.19s 25.38% 25.38%     17.02s 83.23%  deflate_fast     4.04s 19.76% 45.13%      4.04s 19.76%  longest_match     3.92s 19.17% 64.30%      3.92s 19.17%  compress_block     3.04s 14.87% 79.17%      3.04s 14.87%  slide_hash     0.62s  3.03% 82.20%      0.63s  3.08%  crc32_z     0.18s  0.88% 83.08%      0.18s  0.88%  writev     0.12s  0.59% 83.67%      0.12s  0.59%  readv     0.11s  0.54% 84.21%      0.11s  0.54%  close     0.08s  0.39% 84.60%      0.17s  0.83%  std::__uniq_ptr_impl::_M_ptr     0.06s  0.29% 84.89%      0.16s  0.78%  std::get     0.06s  0.29% 85.18%      0.18s  0.88%  std::unique_ptr::get     0.04s   0.2% 85.38%     18.54s 90.66%  http_parser_execute     0.03s  0.15% 85.53%      0.33s  1.61%  Envoy::Router::Filter::decodeHeaders     0.03s  0.15% 85.67%      0.26s  1.27%  absl::container_internal::raw_hash_set::find     0.02s 0.098% 85.77%     17.16s 83.91%  Envoy::Http::Http1::ClientConnectionImpl::onBody     0.01s 0.049% 85.82%      0.12s  0.59%  Envoy::Event::DispatcherImpl::clearDeferredDeleteList     0.01s 0.049% 85.87%     20.03s 97.95%  Envoy::Event::FileEventImpl::mergeInjectedEventsAndRunCb     0.01s 0.049% 85.92%     17.06s 83.42%  Envoy::Extensions::Compression::Gzip::Compressor::ZlibCompressorImpl::process     0.01s 0.049% 85.97%      0.13s  0.64%  Envoy::Http::ConnectionManagerImpl::ActiveStream::encodeData     0.01s 0.049% 86.01%      0.11s  0.54%  Envoy::Http::HeaderString::HeaderString     0.01s 0.049% 86.06%      0.32s  1.56%  Envoy::Http::Http1::ClientConnectionImpl::onHeadersComplete     0.01s 0.049% 86.11%     17.18s 84.01%  Envoy::Http::Http1::ConnectionImpl::dispatchBufferedBody     0.01s 0.049% 86.16%     19.14s 93.59%  Envoy::Network::ConnectionImpl::onReadReady     0.01s 0.049% 86.21%      0.24s  1.17%  Envoy::Network::ConnectionImpl::onWriteReady     0.01s 0.049% 86.26%      0.20s  0.98%  Envoy::Network::IoSocketHandleImpl::read     0.01s 0.049% 86.31%      0.21s  1.03%  Envoy::Network::RawBufferSocket::doRead...

Для более детального анализа можно воспользоваться довольно удобным web-интерфейсом, который предоставляет тот же pprof:


$ pprof -http=localhost:8080 /tmp/envoy.prof

Теперь по адресу http://localhost:8080 можно взглянуть на красивый граф вызовов функции (callgraph)


callgraph


и на flamegraph


flamegraph


С анализом же расхода памяти всё несколько сложнее, покуда профилировщик кучи является органической частью tcmalloc (thread caching malloc) альтернативного менеджера памяти от gperftools минимизирующего количество системных вызовов за счет предварительного выделения памяти сверх необходимого. То есть, чтобы иметь возможность профилировать память на боевой системе, необходимо отказаться от стандартных реализаций malloc() и new и всегда линковаться с tcmalloc. И хоть tcmalloc считается быстрее и эффективнее особенно в многопоточных программах, не все готовы его использовать хотя бы из-за немного большего расхода памяти. Тем не менее профилировать память с ним так же просто как и CPU:


$ HEAPPROFILE=/tmp/envoyhprof envoy --concurrency 1 -c /path/to/config.yamlDumping heap profile to /tmp/envoyhprof.0001.heap (1024 MB allocated cumulatively, 6 MB currently in use)Dumping heap profile to /tmp/envoyhprof.0002.heap (2048 MB allocated cumulatively, 6 MB currently in use)Dumping heap profile to /tmp/envoyhprof.0003.heap (3072 MB allocated cumulatively, 6 MB currently in use)Dumping heap profile to /tmp/envoyhprof.0004.heap (4096 MB allocated cumulatively, 6 MB currently in use)Dumping heap profile to /tmp/envoyhprof.0005.heap (5120 MB allocated cumulatively, 6 MB currently in use)^CDumping heap profile to /tmp/envoyhprof.0006.heap (Exiting, 5 MB in use)

Теперь, чтобы узнать какие функции больше всего выделяли память на куче, надо снова воспользоваться pprof:


$ pprof -text -sample_index=alloc_space /tmp/envoyhprof.0005.heapFile: envoy-staticType: alloc_spaceShowing nodes accounting for 1558.99MB, 98.71% of 1579.32MB totalDropped 1117 nodes (cum <= 7.90MB)      flat  flat%   sum%        cum   cum% 1043.23MB 66.06% 66.06%  1043.23MB 66.06%  zcalloc  240.73MB 15.24% 81.30%   240.73MB 15.24%  Envoy::Zlib::Base::Base  150.71MB  9.54% 90.84%   406.68MB 25.75%  std::make_unique   79.15MB  5.01% 95.85%    79.15MB  5.01%  std::allocator_traits::allocate   18.68MB  1.18% 97.04%    26.62MB  1.69%  Envoy::Http::ConnectionManagerImpl::newStream   15.18MB  0.96% 98.00%    15.18MB  0.96%  Envoy::InlineStorage::operator new    8.39MB  0.53% 98.53%     8.39MB  0.53%  std::__cxx11::basic_string::basic_string    1.98MB  0.13% 98.65%    31.99MB  2.03%  Envoy::Http::Http1::allocateConnPool(Envoy::Event::Dispatcher&, Envoy::Random::RandomGenerator&, std::shared_ptr, Envoy::Upstream::ResourcePriority, std::shared_ptr const&, std::shared_ptr const&, Envoy::Upstream::ClusterConnectivityState&)::$_1::operator()    0.93MB 0.059% 98.71%    38.29MB  2.42%  Envoy::Server::ConnectionHandlerImpl::ActiveTcpListener::newConnection         0     0% 98.71%    59.54MB  3.77%  Envoy::Buffer::WatermarkBufferFactory::create         0     0% 98.71%    73.55MB  4.66%  Envoy::ConnectionPool::ConnPoolImplBase::newStream...

Как следует из таблицы, больше всего памяти выделяла zcalloc() из zlib, что совсем не удивительно, поскольку во время профилирования приложение сжимало прокачиваемый через себя трафик.


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


$ pprof -text -sample_index=inuse_space /tmp/envoyhprof.0005.heapFile: envoy-staticType: inuse_spaceShowing nodes accounting for 6199.96kB, 96.84% of 6402.51kB totalDropped 1016 nodes (cum <= 32.01kB)      flat  flat%   sum%        cum   cum% 2237.76kB 34.95% 34.95%  3232.51kB 50.49%  std::make_unique 2041.45kB 31.89% 66.84%  2041.45kB 31.89%  std::allocator_traits::allocate  375.03kB  5.86% 72.69%   753.26kB 11.77%  google::protobuf::DescriptorPool::Tables::AllocateString[abi:cxx11]  267.78kB  4.18% 76.88%   267.78kB  4.18%  std::__cxx11::basic_string::_M_mutate  201.61kB  3.15% 80.03%   201.61kB  3.15%  zalloc_with_calloc  160.43kB  2.51% 82.53%   160.43kB  2.51%  google::protobuf::Arena::CreateMessageInternal (inline)  146.74kB  2.29% 84.82%   146.74kB  2.29%  std::__cxx11::basic_string::_M_construct  141.38kB  2.21% 87.03%   157.38kB  2.46%  google::protobuf::DescriptorPool::Tables::AllocateMessage  139.88kB  2.18% 89.22%   139.88kB  2.18%  google::protobuf::DescriptorPool::Tables::AllocateEmptyString[abi:cxx11]   88.04kB  1.38% 90.59%   113.12kB  1.77%  google::protobuf::DescriptorPool::Tables::AllocateFileTables   72.52kB  1.13% 91.72%    72.90kB  1.14%  ares_init_options      71kB  1.11% 92.83%       71kB  1.11%  _GLOBAL__sub_I_eh_alloc.cc   69.81kB  1.09% 93.92%    69.81kB  1.09%  zcalloc   51.16kB   0.8% 94.72%    51.16kB   0.8%  google::protobuf::Arena::CreateArray (inline)   46.81kB  0.73% 95.45%    60.41kB  0.94%  google::protobuf::Arena::CreateInternal (inline)   37.23kB  0.58% 96.03%    37.23kB  0.58%  re2::PODArray::PODArray   33.53kB  0.52% 96.56%    33.53kB  0.52%  std::__cxx11::basic_string::_M_assign   11.50kB  0.18% 96.74%  2213.77kB 34.58%  Envoy::ConstSingleton::get    6.06kB 0.095% 96.83%    38.85kB  0.61%  google::protobuf::internal::ArenaStringPtr::Set    0.24kB 0.0038% 96.84%  2590.71kB 40.46%  Envoy::Server::InstanceImpl::InstanceImpl         0     0% 96.84%    79.56kB  1.24%  Envoy::(anonymous namespace)::jsonConvertInternal         0     0% 96.84%    84.48kB  1.32%  Envoy::(anonymous namespace)::tryWithApiBoosting         0     0% 96.84%   726.42kB 11.35%  Envoy::Config::ApiTypeOracle::getEarlierVersionDescriptor         0     0% 96.84%    77.22kB  1.21%  Envoy::Config::Utility::createTagProducer         0     0% 96.84%   706.72kB 11.04%  Envoy::Config::Utility::getAndCheckFactory         0     0% 96.84%   707.38kB 11.05%  Envoy::Config::Utility::getFactoryByType...

Ожидаемо, большую часть памяти держит std::make_unique(). И вообще внутри кода Envoy оптимизировать особо нечего главные потребители находятся в сторонних библиотеках. Однако если взглянуть на callgraph или flamegraph, то можно узнать, например, на какие функции обратить внимание, чтобы пореже звать std::make_unique(). Web-интерфейс в этом случае наиболее удобен


$ pprof -http=localhost:8080 /tmp/envoyhprof.0005.heap

В браузере вы увидите что-то вроде


Heap callgraph


и


Heap flamegraph


Можно также проверить, не течет ли память. Вычтем из результата самую первую часть дампа, где происходит инициализация программы:


$ pprof -text -sample_index=inuse_space --base=/tmp/envoyhprof.0001.heap /tmp/envoyhprof.0005.heapFile: envoy-staticType: inuse_spaceShowing nodes accounting for 1460B, 10.38% of 14060B total      flat  flat%   sum%        cum   cum%     1460B 10.38% 10.38%      1460B 10.38%  hist_accumulate         0     0% 10.38%      1460B 10.38%  Envoy::Event::DispatcherImpl::DispatcherImpl(std::__cxx11::basic_string const&, Envoy::Api::Api&, Envoy::Event::TimeSystem&, std::shared_ptr const&)::$_1::operator()         0     0% 10.38%      1460B 10.38%  Envoy::Event::DispatcherImpl::run         0     0% 10.38%      1460B 10.38%  Envoy::Event::DispatcherImpl::runPostCallbacks         0     0% 10.38%      1460B 10.38%  Envoy::Event::LibeventScheduler::run         0     0% 10.38%      1460B 10.38%  Envoy::Event::SchedulableCallbackImpl::SchedulableCallbackImpl(Envoy::CSmartPtr&, std::function)::$_0::__invoke         0     0% 10.38%      1460B 10.38%  Envoy::Event::SchedulableCallbackImpl::SchedulableCallbackImpl(Envoy::CSmartPtr&, std::function)::$_0::operator()         0     0% 10.38%      1460B 10.38%  Envoy::MainCommon::main         0     0% 10.38%      1460B 10.38%  Envoy::MainCommon::run         0     0% 10.38%      1460B 10.38%  Envoy::MainCommonBase::run         0     0% 10.38%      1460B 10.38%  Envoy::Server::InstanceImpl::run         0     0% 10.38%      1460B 10.38%  Envoy::Stats::ParentHistogramImpl::merge         0     0% 10.38%       730B  5.19%  Envoy::Stats::ThreadLocalHistogramImpl::merge         0     0% 10.38%      1460B 10.38%  Envoy::Stats::ThreadLocalStoreImpl::mergeHistograms(std::function)::$_2::operator()         0     0% 10.38%      1460B 10.38%  Envoy::Stats::ThreadLocalStoreImpl::mergeInternal         0     0% 10.38%      1460B 10.38%  __libc_start_main         0     0% 10.38%      1460B 10.38%  event_base_loop         0     0% 10.38%      1460B 10.38%  event_process_active         0     0% 10.38%      1460B 10.38%  event_process_active_single_queue         0     0% 10.38%      1460B 10.38%  main         0     0% 10.38%      1460B 10.38%  std::_Function_handler::_M_invoke         0     0% 10.38%      1460B 10.38%  std::function::operator()

Всё выглядит неплохо, память весьма умеренно тратится только на хранение накопленной статистики.


По закону жанра на этом месте должны начаться проблемы. Заключаются они в том, что не так давно Google выложил в своём аккаунте на GitHub новый, улучшенный tcmalloc. В котором, кэши памяти создаются не для потоков, как в оригинальной версии, а для ядер процессора. В задачах, создающих большое количество потоков, это может заметно улучшить производительность и снизить расход памяти.


Плохая же новость в том, что в новом tcmalloc отсутствует профилировщик. Однако же он теперь не особенно-то и нужен. В частности для профилирования CPU теперь вполне достаточно утилиты perf. Чтобы ею воспользоваться даже не нужно ни с чем линковаться. Всё нужное уже есть в ядре Linux:


$ perf record -g -F 99 -p `pgrep envoy`^C[ perf record: Woken up 1 times to write data ][ perf record: Captured and wrote 0.694 MB perf.data (1532 samples) ]

Результат сохраняется в файл perf.data, формат которого понятен pprof (начиная с некоторой версии):


$ pprof -http=localhost:8080 perf.data

То есть результат совершенно идентичен варианту с использованием gperftools.


Однако имеются подозрения, что perf.data содержит даже больше полезных данных, чем pprof позволяет отобразить. В частности я не смог найти, как сделать разбивку стеков по потокам. Если кто-то знает, напишите, пожалуйста, в комментариях. Такая разбивка может быть полезна для обнаружения узких мест, когда несколько потоков делегируют какую-то работу одному единственному потоку и перегружают его. Пока что для меня незаменимым инструментом для таких случаев служит набор скриптов Брендана Грегга: https://github.com/brendangregg/FlameGraph. Если их применить к имеющемуся файлу perf.data, то получим flamegraph, в котором можно различить три потока один главный и два рабочих.


$ perf script --input=perf.data | ./FlameGraph/stackcollapse-perf.pl > out.perf-folded$ ./FlameGraph/flamegraph.pl out.perf-folded > perf.svg


Впрочем, глядя на такой flamegraph, далеко не всегда мы можем догадаться, что имеем дело с блокировками на перегруженном потоке. Полезнее может оказаться картинка с неработающими потоками, то есть ожидающими снятия какой-нибудь блокировки. Опять же, всё нужное для этого есть в ядре Linux речь идёт о eBPF. Инструментализация кода не требуется. Только убедитесь, что в вашей системе установлен пакет с инструментами для BPF Compiler Collection. В Fedora он называется bcc-tools.


$ /usr/share/bcc/tools/offcputime -df -p `pgrep envoy` 30 > out.stacks$ ./FlameGraph/flamegraph.pl --color=io --title='Off-CPU Time Flame Graph' < out.stacks > off-cpu.svg

Для примера приведу два графика для Envoy под большой нагрузкой запущенного с четырьмя и девятью рабочими потоками.


Это 4 потока
4 workers


Это 9 потоков
9 workers


Можно заметить, что при большем количестве рабочих потоков оные всё большую часть времени ничегонеделания бесполезно ждут в цикле событий вместо того, чтобы с пользой ждать, например, возврата из других системных вызовов. При том, что запросы к серверу остаются необслуженными. Это как раз результат эксперимента по передаче части работы от рабочих потоков одному специализированному потоку плохая идея в общем случае.


А вот с профилированием памяти не всё так радужно, хотя и тут можно кое-чего добиться полагаясь только на eBPF и на утилиту stackcount из bcc-tools. Для того, чтобы получить flamegraph в стиле pprof, надо сделать следующее


$ sudo /usr/share/bcc/tools/stackcount -p `pgrep envoy`  -U "/full/path/to/envoy:_Znwm" > out.stack$ ./FlameGraph/stackcollapse.pl < out.stacks | ./FlameGraph/flamegraph.pl --color=mem --title="operator new(std::size_t) Flame Graph" --countname="calls" > out.svg

stackcount группирует вызовы к некоторой функции по идентичным стекам вызовов к ней (stack traces) и суммирует их. Обратите внимание на странно выглядящий параметр -U "/full/path/to/envoy:_Znwm". Он указывает на некоторую функцию в пространстве пользователя (в противоположность параметру -K, который может указать на функцию в пространстве ядра). В общем случае он задаётся как -U lib:func, где lib это имя библиотеки, а func имя функции в том виде, как оно выглядит выводе objdump -tT /path/to/lib. В нашем случае _Znwm это не что иное как void* operator new(std::size_t). А путь к исполняемому файлу вместо имени библиотеки указан потому, что есть нюанс Envoy статически слинкован с tcmalloc. К сожалению, из документации вы не узнаете о таких мелочах.


Чтобы понять как C++ компилятор видоизменит (mangle) нужную вам функцию, воспользуйтесь вот таким однострочником


$ echo -e "#include <new>\n void* operator new(std::size_t) {} " | g++ -x c++ -S - -o- 2> /dev/null        .file   ""        .text        .globl  _Znwm        .type   _Znwm, @function_Znwm:.LFB73:        .cfi_startproc        pushq   %rbp        .cfi_def_cfa_offset 16        .cfi_offset 6, -16        movq    %rsp, %rbp        .cfi_def_cfa_register 6        movq    %rdi, -8(%rbp)        nop        popq    %rbp        .cfi_def_cfa 7, 8        ret        .cfi_endproc.LFE73:        .size   _Znwm, .-_Znwm        .ident  "GCC: (GNU) 10.2.1 20201016 (Red Hat 10.2.1-6)"        .section        .note.GNU-stack,"",@progbits

Обратите внимание, что имя функции будет разным на 32 и 64 разрядных платформах из-за разного размера size_t. Кроме того void* operator new[](std::size_t) это отдельная функция. Как, впрочем, и malloc() с calloc(), которые будучи C-функциями свои имена не меняют.


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


Чтобы ответить на вопрос сколько, нужен инструмент, который будет суммировать аргументы вызовов malloc() или new, а лучше все сразу. То есть что-то вроде этого. В идеале хотелось бы, чтобы во внимание принимались ещё free() и delete, но это уже из области магии. Если кто-то уже реализовал такое на eBPF, отпишитесь, пожалуйста, в комментариях.


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

Подробнее..

Перевод Flame-графики огонь из всех движков

12.10.2020 18:16:09 | Автор: admin

Всем снова привет! Приглашаем на онлайн-встречу с Василием Кудрявцевым (директором департамента обеспечения качества в АО РТЛабс), которая пройдёт в рамках курса Нагрузочное тестирование. И публикуем перевод статьи Michael Hunger software developer and editor ofNeo4j Developer BlogandGRANDstack!

Стандартные профайлеры Java используют либо инструментарий байткода, либо сэмплинг (рассматривая трассировки стека через короткие промежутки времени), чтобы определить, где было потрачено время. В обоих подходах есть свои недостатки и странности. Понимание результатов работы таких профайлеров само по себе искусство и требует большого опыта.

К счастью, Брендан Грегг, инженер по производительности в Netflix, придумал flame-графики, гениального вида диаграммы для трассировки стека, которые можно собрать практически из любой системы.

Flame-график сортирует и агрегирует трассировки на каждом уровне стека, таким образом их количество отражает процент от общего времени, затраченного в этой части кода. Визуализация этих блоков в виде прямоугольников с шириной, пропорциональной проценту от общего времени работы и укладка их друг на друга оказалась крайне полезной визуализацией. (Обратите внимание на то, что порядок слева направо не имеет принципиального значения, часто это просто сортировка по алфавиту. То же самое и с цветами. Значение имеют только относительная ширина и глубина стека)

Flame-график бенчмарка заполнения непредаллоцированного ArrayListFlame-график бенчмарка заполнения непредаллоцированного ArrayList

Flame'ы снизу вверх отражают прогрессию от точки входа программы или потока (main или цикл событий) до листьев выполнения на концах flame'ов.

Вы сразу увидите, если некоторые части программы будут занимать неожиданно большое количество времени. Чем выше на диаграмме вы это видите, тем хуже. А если у вас есть очень широкий flame сверху, то вы точно нашли узкое место, где работа не делегируется куда-либо еще. После устранения проблемы, измерьте время работы еще раз, если проблема с производительностью сохранится, вернитесь к диаграмме, чтобы понять, где осталась проблема.

Для устранения недостатков стандартных профайлеров многие современные инструменты используют внутреннюю функцию JVM (AsyncGetCallTrace), которая позволяет собирать трассировки стека независимо от безопасных точек. Помимо этого, они объединяют измерение JVM-операций с нативным кодом и системных вызовов операционной системы, так что время, проведенное в сети, ввод/вывод или сборка мусора, также может стать частью flame-графа.

Такие инструменты, как Honest Profiler, perf-map-agent, async-profiler или даже IntelliJ IDEA, умеют захватывать информацию и с легкостью делать flame-графики.

В большинстве случаев вы просто скачиваете инструмент, предоставляете PID вашего Java-процесса и говорите инструменту работать в течение определенного периода времени и генерировать интерактивный SVG.

# download and unzip async profiler for your OS from:# https://github.com/jvm-profiling-tools/async-profiler./profiler.sh -d <duration> -f flamegraph.svg -s -o svg <pid> && \open flamegraph.svg  -a "Google Chrome"

SVG, создаваемый этими инструментами, не просто красочный, но и интерактивный. Вы можете увеличивать секции, искать посимвольно и т.д.

Flame-графики впечатляющий и мощный инструмент для быстрого обзора характеристик производительности ваших программ. С ними вы можете сразу увидеть проблемные места и сосредоточиться на них, а обзор аспектов, не связанных с JVM, помогает получить более полную картину.


Интересно развиваться в данном направлении? Запишитесь на бесплатный Demo-урок Скрипты и сценарии нагрузочного тестирования- Performance center (PC) и Vugen!

Подробнее..

Категории

Последние комментарии

  • Имя: Макс
    24.08.2022 | 11:28
    Я разраб в IT компании, работаю на арбитражную команду. Мы работаем с приламы и сайтами, при работе замечаются постоянные баны и лаги. Пацаны посоветовали сервис по анализу исходного кода,https://app Подробнее..
  • Имя: 9055410337
    20.08.2022 | 17:41
    поможем пишите в телеграм Подробнее..
  • Имя: sabbat
    17.08.2022 | 20:42
    Охренеть.. это просто шикарная статья, феноменально круто. Большое спасибо за разбор! Надеюсь как-нибудь с тобой связаться для обсуждений чего-либо) Подробнее..
  • Имя: Мария
    09.08.2022 | 14:44
    Добрый день. Если обладаете такой информацией, то подскажите, пожалуйста, где можно найти много-много материала по Yggdrasil и его уязвимостях для написания диплома? Благодарю. Подробнее..
© 2006-2024, personeltest.ru