Иногда в моих программах происходят долгие процессы, за ходом которых интересно проследить: разбить их на стадии и проследить за временем выполнения каждой их них. По результатам замеров можно сказать, какая из стадий проходит медленнее всех, и попытаться ускорить её.
Грамотная оптимизация невозможна без профилировки — ведь, не зная точного времени работы всех модулей, вы можете взяться за оптимизацию какой-то одной функции (занимающей 10% времени), а окажется что вся проблема в другой (занимающей 80%). Оптимизировав первую функцию даже в два раза — вы выиграете всего 5% времени работы приложения, в то время как двукратная оптимизация второй функции даст целых 40%.
Модуль, выполняющий эти замеры, называется профайлер (profiler). Типичные профайлеры имеют гораздо больше функций, чем я назвал: постройка дерева вызовов, слежение за кэшем и памятью, автоматическое определение наиболее долгих функций, и наоборот, функций которые никогда не получают управление. Однако для микроконтроллеров реализовать всё перечисленное достаточно тяжело, да и у нас нет такой задачи.
Напишем свою компактную (но обязательно удобную!) реализацию профайлера для STM32 на Си. Конечно, это подойдёт и для любого другого однопоточного окружения.
API профайлера
Цикл работы профайлера будет очень прост:
- profiler_start(char *profile_name) — запускаем отсчёт времени, заодно для удобства сохраняем имя процесса
- profiler_event(char *event) — отмечаем событие, запоминаем его название и текущее время относительно старта
- profiler_stop() — заканчиваем отсчёт, выводим в отладочную консоль таблицу стадий и их длительности.
Использование:
profiler_start("Some interesting process"); profiler_event("Started"); /* === Долгий процесс №1 === */ profiler_event("Step 1, where we do something"); /* === Долгий процесс №2 === */ profiler_event("Step 2, where we do nothing :("); profiler_stop();
После окончания работы в ваш stdout будет выведена табличка:
Profiling "Some interesting process" sequence: --Event------------------------|timestamp|--delta_t- Started : 0 ms | + 0 ms Step 1, where we do something : 1435 ms | + 1435 ms Step 2, where we do nothing :( : 1732 ms | + 297 ms
Реальный пример работы:
Здесь видно, что наибольшее время занимает выполнение функции «Virtual ticket in complete». Начинать оптимизацию нужно с неё.
Код
#include "inttypes.h" #define MAX_PROFILING_EVENT_COUNT 10 uint32_t times[MAX_PROFILING_EVENT_COUNT], start; char *names[MAX_PROFILING_EVENT_COUNT], *name, event_count = 0; extern unsigned long MS_TIMER; void profiling_start(char *profile_name) { start = MS_TIMER; name = profile_name; } void profiling_event(char *event) { times[event_count] = MS_TIMER - start; names[event_count] = event; event_count++; } void profiling_stop() { uint32_t prev_time = 0; DEBUG_PRINTF(" Profiling \"%s\" sequence: --Event-----------------------|timestamp|--delta_t- ", name); for(int i = 0; i < event_count; i++) { DEBUG_PRINTF("%-30s:%5d ms | +%5d ms ", names[i], times[i], times[i] - prev_time); prev_time = times[i]; } event_count = 0; }
Функция DEBUG_PRINTF — это функция вывода в консоль из статьи про Telnet.
MS_TIMER — глобальная переменная времени из статьи про таймер и задержки.
Свежие комментарии