Иногда в моих программах происходят долгие процессы, за ходом которых интересно проследить: разбить их на стадии и проследить за временем выполнения каждой их них. По результатам замеров можно сказать, какая из стадий проходит медленнее всех, и попытаться ускорить её.
Грамотная оптимизация невозможна без профилировки — ведь, не зная точного времени работы всех модулей, вы можете взяться за оптимизацию какой-то одной функции (занимающей 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 — глобальная переменная времени из статьи про таймер и задержки.
