Иногда в моих программах происходят долгие процессы, за ходом которых интересно проследить: разбить их на стадии и проследить за временем выполнения каждой их них. По результатам замеров можно сказать, какая из стадий проходит медленнее всех, и попытаться ускорить её.

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