Logging, Debug e Otimização 🔍
Sistema de Logging do ESP-IDF
O sistema de logging do ESP-IDF fornece infraestrutura robusta para diagnóstico e monitoramento de aplicações durante desenvolvimento e operação. Compreender como usar logging efetivamente acelera dramaticamente identificação e resolução de problemas, além de fornecer visibilidade valiosa sobre comportamento do sistema em produção.
O ESP-IDF implementa sistema de logging hierárquico com cinco níveis de severidade que permitem filtrar mensagens baseado em importância. Cada mensagem é associada a tag que identifica componente ou módulo que a originou, permitindo controle fino sobre quais subsistemas produzem saída. Esta granularidade é essencial em sistemas complexos onde você pode querer logging detalhado de módulo específico sem ser inundado por mensagens de outros componentes.
As macros de logging como ESP_LOGI, ESP_LOGW e ESP_LOGE oferecem interface conveniente que automaticamente adiciona informações contextuais como timestamp, nível de log e tag. Em tempo de compilação, mensagens abaixo de determinado nível podem ser completamente removidas do binário, eliminando overhead tanto de CPU quanto de tamanho de código para builds de produção otimizados.
📊 Níveis de Logging e Quando Usar Cada Um
Escolher nível apropriado de logging para cada mensagem requer compreensão clara do propósito e audiência de cada nível. Esta decisão impacta tanto utilidade dos logs quanto performance do sistema, especialmente quando logging sobre UART tem overhead significativo.
O nível ERROR deve ser reservado para condições verdadeiramente excepcionais que indicam falhas graves impedindo operação normal. Mensagens de erro tipicamente precedem recuperação de emergência ou shutdown do sistema. Por exemplo, falha ao alocar memória essencial ou impossibilidade de comunicar com hardware crítico justificam logs de erro. Cada erro deve ser acionável, significando que alguém lendo o log saberá exatamente qual problema ocorreu e poderá tomar ação corretiva.
Mensagens de WARNING indicam condições anormais que o sistema consegue lidar mas que merecem atenção. Exemplos incluem tentativas de reconexão após perda de rede, uso de valores default quando configuração esperada está ausente, ou aproximação de limites de recursos. Warnings não interrompem operação mas sinalizam que algo pode requerer investigação ou ajuste de configuração.
O nível INFO representa fluxo normal de operação do sistema e marcos importantes no processamento. Inicialização de componentes, estabelecimento de conexões e conclusão de tarefas significativas tipicamente geram mensagens INFO. Este nível deve fornecer visão clara do que sistema está fazendo sem detalhes excessivos. Em produção, INFO é frequentemente nível mínimo habilitado.
DEBUG oferece informações detalhadas úteis durante desenvolvimento e troubleshooting mas excessivamente verbosas para operação normal. Valores de variáveis, estados intermediários de algoritmos e detalhes de protocolos de comunicação são apropriados para DEBUG. Este nível é tipicamente desabilitado em builds de produção para economizar espaço e performance.
Finalmente, VERBOSE fornece máximo detalhe possível, incluindo dumps hexadecimais de pacotes, trace de cada função chamada e estado de cada estrutura de dados significativa. Este nível é usado apenas quando diagnosticando problemas específicos extremamente difíceis, pois overhead pode ser substancial.
#include "esp_log.h"
#include "esp_system.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
// Tags para diferentes módulos
static const char *TAG_MAIN = "MAIN";
static const char *TAG_SENSOR = "SENSOR";
static const char *TAG_NETWORK = "NETWORK";
/**
* Demonstrar diferentes níveis de logging
*
* Cada nível tem propósito específico e overhead associado
*/
void demonstrate_log_levels(void)
{
ESP_LOGE(TAG_MAIN, "Mensagem de ERRO - algo crítico falhou");
ESP_LOGW(TAG_MAIN, "Mensagem de WARNING - situação anormal mas recuperável");
ESP_LOGI(TAG_MAIN, "Mensagem de INFO - operação normal significativa");
ESP_LOGD(TAG_MAIN, "Mensagem de DEBUG - detalhes para troubleshooting");
ESP_LOGV(TAG_MAIN, "Mensagem de VERBOSE - máximo detalhe possível");
}
/**
* Configurar níveis de log dinamicamente em runtime
*
* Útil para habilitar debug temporariamente sem recompilar
*/
void configure_log_levels(void)
{
// Configurar nível global para INFO
esp_log_level_set("*", ESP_LOG_INFO);
// Habilitar DEBUG apenas para módulo de sensor
esp_log_level_set(TAG_SENSOR, ESP_LOG_DEBUG);
// Silenciar completamente módulo de network
esp_log_level_set(TAG_NETWORK, ESP_LOG_NONE);
ESP_LOGI(TAG_MAIN, "Níveis de log configurados");
}
/**
* Logging com formatação avançada
*
* Suporta todos os especificadores de formato do printf
*/
void advanced_logging_examples(void)
{
int contador = 42;
float temperatura = 25.5f;
const char *status = "operacional";
// Valores numéricos
ESP_LOGI(TAG_SENSOR, "Contador: %d, Temperatura: %.2f°C",
contador, temperatura);
// Strings e ponteiros
ESP_LOGI(TAG_MAIN, "Status: %s, Endereço: %p", status, &contador);
// Hexadecimal
uint32_t flags = 0xABCD1234;
ESP_LOGI(TAG_MAIN, "Flags: 0x%08X", flags);
// Múltiplas variáveis
ESP_LOGI(TAG_MAIN, "Sistema: contador=%d temp=%.1f status=%s",
contador, temperatura, status);
}
/**
* Logging de buffers binários
*
* Útil para debug de protocolos de comunicação
*/
void log_buffer_example(void)
{
uint8_t buffer[] = {0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08,
0x09, 0x0A, 0x0B, 0x0C, 0x0D, 0x0E, 0x0F, 0x10};
// Dump hexadecimal formatado
ESP_LOG_BUFFER_HEX(TAG_MAIN, buffer, sizeof(buffer));
// Dump com interpretação de caracteres
ESP_LOG_BUFFER_HEXDUMP(TAG_MAIN, buffer, sizeof(buffer));
// Dump apenas de caracteres imprimíveis
const char *string = "Hello, ESP32! 123";
ESP_LOG_BUFFER_CHAR(TAG_MAIN, string, strlen(string));
}
/**
* Macros condicionais para logging eficiente
*
* Logging é completamente removido em compilação se nível
* estiver abaixo do configurado
*/
void conditional_logging_example(void)
{
int expensive_calculation_result = 0;
// Este código só executa se DEBUG estiver habilitado em compilação
#if CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_DEBUG
// Cálculo caro apenas quando debug necessário
for (int i = 0; i < 1000000; i++) {
expensive_calculation_result += i;
}
ESP_LOGD(TAG_MAIN, "Resultado do cálculo: %d", expensive_calculation_result);
#endif
}
/**
* Implementar logging thread-safe customizado
*
* Para casos onde controle adicional é necessário
*/
typedef struct {
uint64_t timestamp;
esp_log_level_t level;
char tag[32];
char message[256];
} custom_log_entry_t;
#define LOG_BUFFER_SIZE 100
static custom_log_entry_t log_buffer[LOG_BUFFER_SIZE];
static int log_buffer_index = 0;
static SemaphoreHandle_t log_mutex = NULL;
void custom_log_init(void)
{
log_mutex = xSemaphoreCreateMutex();
log_buffer_index = 0;
}
void custom_log_add(esp_log_level_t level, const char *tag,
const char *format, ...)
{
if (xSemaphoreTake(log_mutex, pdMS_TO_TICKS(100)) == pdTRUE) {
custom_log_entry_t *entry = &log_buffer[log_buffer_index];
entry->timestamp = esp_timer_get_time();
entry->level = level;
strncpy(entry->tag, tag, sizeof(entry->tag) - 1);
// Formatar mensagem
va_list args;
va_start(args, format);
vsnprintf(entry->message, sizeof(entry->message), format, args);
va_end(args);
log_buffer_index = (log_buffer_index + 1) % LOG_BUFFER_SIZE;
xSemaphoreGive(log_mutex);
}
}
void custom_log_dump(void)
{
if (xSemaphoreTake(log_mutex, pdMS_TO_TICKS(1000)) == pdTRUE) {
ESP_LOGI(TAG_MAIN, "=== Dump do Log Customizado ===");
for (int i = 0; i < LOG_BUFFER_SIZE; i++) {
custom_log_entry_t *entry = &log_buffer[i];
if (entry->timestamp > 0) {
ESP_LOGI(TAG_MAIN, "[%llu] [%s] %s",
entry->timestamp, entry->tag, entry->message);
}
}
xSemaphoreGive(log_mutex);
}
}
/**
* Logging assíncrono para reduzir impacto na performance
*
* Mensagens são enfileiradas e processadas por task dedicada
*/
static QueueHandle_t log_queue = NULL;
typedef struct {
esp_log_level_t level;
char tag[16];
char message[128];
} async_log_msg_t;
void async_log_task(void *pvParameters)
{
async_log_msg_t msg;
while (1) {
if (xQueueReceive(log_queue, &msg, portMAX_DELAY) == pdTRUE) {
// Processar log fora do contexto crítico
switch (msg.level) {
case ESP_LOG_ERROR:
ESP_LOGE(msg.tag, "%s", msg.message);
break;
case ESP_LOG_WARN:
ESP_LOGW(msg.tag, "%s", msg.message);
break;
case ESP_LOG_INFO:
ESP_LOGI(msg.tag, "%s", msg.message);
break;
default:
ESP_LOGD(msg.tag, "%s", msg.message);
break;
}
}
}
}
void async_log_init(void)
{
log_queue = xQueueCreate(50, sizeof(async_log_msg_t));
xTaskCreate(async_log_task, "AsyncLog", 3072, NULL, 1, NULL);
}
void async_log(esp_log_level_t level, const char *tag, const char *format, ...)
{
async_log_msg_t msg;
msg.level = level;
strncpy(msg.tag, tag, sizeof(msg.tag) - 1);
va_list args;
va_start(args, format);
vsnprintf(msg.message, sizeof(msg.message), format, args);
va_end(args);
// Enfileirar sem bloquear se fila estiver cheia
xQueueSend(log_queue, &msg, 0);
}
void app_main(void)
{
ESP_LOGI(TAG_MAIN, "Demonstrando sistema de logging");
// Configurar níveis de log
configure_log_levels();
// Demonstrar diferentes níveis
demonstrate_log_levels();
// Exemplos de formatação
advanced_logging_examples();
// Logging de buffers
log_buffer_example();
// Inicializar sistemas de log customizado
custom_log_init();
async_log_init();
// Usar logging customizado
custom_log_add(ESP_LOG_INFO, TAG_MAIN, "Teste de log customizado");
// Dump após alguns logs
vTaskDelay(pdMS_TO_TICKS(1000));
custom_log_dump();
ESP_LOGI(TAG_MAIN, "Sistema de logging configurado e testado");
}Profiling e Análise de Performance
Otimizar performance de sistemas embarcados requer primeiro compreender onde tempo de CPU está sendo gasto e quais operações consomem mais recursos. O ESP-IDF oferece várias ferramentas de profiling que permitem medir precisamente duração de operações, identificar gargalos e validar que otimizações produziram melhorias reais.
O timer de alta resolução esp_timer oferece precisão de microsegundo para medir duração de operações individuais. Esta precisão é essencial para identificar hotspots em código onde pequenas otimizações podem ter impacto significativo. Simplesmente ler o timer antes e depois de seção de código fornece medição precisa de quanto tempo aquela operação levou.
A análise sistemática de performance envolve estabelecer baselines, fazer mudanças controladas e medir impacto objetivo. Intuições sobre o que é lento frequentemente estão erradas, e profiling revela surpresas sobre onde tempo realmente está sendo gasto. Código que parece simples pode esconder chamadas de biblioteca caras, enquanto loops aparentemente complexos podem ser otimizados agressivamente pelo compilador.
⚡ Técnicas de Otimização Comum
Depois de identificar gargalos através de profiling, várias técnicas de otimização podem melhorar performance dramaticamente. A chave é sempre medir antes e depois para confirmar que mudança realmente ajudou, pois otimizações prematuras frequentemente complicam código sem benefício real.
Reduzir chamadas de função em loops internos pode melhorar performance significativamente, especialmente quando função chamada é pequena. O compilador pode inline funções automaticamente mas nem sempre faz escolhas ótimas. Declarar funções pequenas como static inline sugere ao compilador que inlining é desejável, eliminando overhead de chamada de função.
Otimizações de cache envolvem organizar dados e código para maximizar localidade espacial e temporal. Acessar elementos de array sequencialmente é muito mais rápido que acesso aleatório porque hardware pode prefetch dados seguintes. Estruturas de dados devem ser organizadas para que campos frequentemente acessados juntos estejam próximos em memória.
Operações de ponto flutuante são relativamente caras em microcontroladores sem FPU dedicada. Quando possível, usar aritmética de inteiros ou fixed-point pode melhorar performance dramaticamente. Por exemplo, representar valores monetários como centavos em inteiros ao invés de reais em float elimina imprecisão e melhora velocidade.
Desenrolar loops manualmente reduz overhead de controle de loop e expõe mais oportunidades para otimização do compilador. Para loops com número fixo pequeno de iterações, desenrolar pode duplicar ou triplicar velocidade. No entanto, isto aumenta tamanho de código, então deve ser aplicado apenas em hotspots identificados por profiling.
#include "esp_timer.h"
#include "esp_system.h"
#include "esp_log.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include <math.h>
static const char *TAG = "PROFILING";
/**
* Macro para profiling simples de blocos de código
*
* Mede tempo de execução e registra automaticamente
*/
#define PROFILE_START(name) \
uint64_t _profile_start_##name = esp_timer_get_time(); \
const char *_profile_name_##name = #name;
#define PROFILE_END(name) \
uint64_t _profile_end_##name = esp_timer_get_time(); \
uint64_t _profile_elapsed_##name = _profile_end_##name - _profile_start_##name; \
ESP_LOGI(TAG, "PROFILE [%s]: %llu μs", _profile_name_##name, _profile_elapsed_##name);
/**
* Estrutura para estatísticas de profiling
*/
typedef struct {
const char *name;
uint64_t total_time_us;
uint64_t min_time_us;
uint64_t max_time_us;
uint32_t call_count;
} profile_stats_t;
#define MAX_PROFILES 20
static profile_stats_t profiles[MAX_PROFILES];
static int profile_count = 0;
/**
* Registrar medição de profiling com estatísticas
*/
void profile_record(const char *name, uint64_t elapsed_us)
{
profile_stats_t *profile = NULL;
// Procurar profile existente
for (int i = 0; i < profile_count; i++) {
if (strcmp(profiles[i].name, name) == 0) {
profile = &profiles[i];
break;
}
}
// Criar novo profile se não existir
if (profile == NULL && profile_count < MAX_PROFILES) {
profile = &profiles[profile_count++];
profile->name = name;
profile->total_time_us = 0;
profile->min_time_us = UINT64_MAX;
profile->max_time_us = 0;
profile->call_count = 0;
}
if (profile) {
profile->total_time_us += elapsed_us;
profile->call_count++;
if (elapsed_us < profile->min_time_us) {
profile->min_time_us = elapsed_us;
}
if (elapsed_us > profile->max_time_us) {
profile->max_time_us = elapsed_us;
}
}
}
/**
* Macro avançada para profiling com estatísticas
*/
#define PROFILE_FUNCTION_START() \
uint64_t _func_start = esp_timer_get_time();
#define PROFILE_FUNCTION_END() \
uint64_t _func_end = esp_timer_get_time(); \
profile_record(__func__, _func_end - _func_start);
/**
* Exibir relatório de profiling
*/
void profile_print_report(void)
{
ESP_LOGI(TAG, "=== Relatório de Profiling ===");
ESP_LOGI(TAG, "%-25s %10s %10s %10s %10s %10s",
"Função", "Chamadas", "Total(ms)", "Média(μs)", "Mín(μs)", "Máx(μs)");
ESP_LOGI(TAG, "------------------------------------------------------------------------------------");
for (int i = 0; i < profile_count; i++) {
profile_stats_t *p = &profiles[i];
uint64_t avg_us = p->total_time_us / p->call_count;
ESP_LOGI(TAG, "%-25s %10lu %10llu %10llu %10llu %10llu",
p->name,
p->call_count,
p->total_time_us / 1000,
avg_us,
p->min_time_us,
p->max_time_us);
}
}
/**
* Exemplo de função lenta não otimizada
*/
float slow_calculation_unoptimized(int iterations)
{
PROFILE_FUNCTION_START();
float result = 0.0f;
for (int i = 0; i < iterations; i++) {
// Operações de ponto flutuante caras
result += sqrtf((float)i) * sinf((float)i / 100.0f);
}
PROFILE_FUNCTION_END();
return result;
}
/**
* Versão otimizada usando inteiros onde possível
*/
float fast_calculation_optimized(int iterations)
{
PROFILE_FUNCTION_START();
float result = 0.0f;
// Pré-calcular constante
const float inv_100 = 1.0f / 100.0f;
for (int i = 0; i < iterations; i++) {
// Minimizar conversões de tipo
float fi = (float)i;
result += sqrtf(fi) * sinf(fi * inv_100);
}
PROFILE_FUNCTION_END();
return result;
}
/**
* Comparar performance de diferentes implementações
*/
void benchmark_implementations(void)
{
const int ITERATIONS = 10000;
const int RUNS = 10;
ESP_LOGI(TAG, "Executando benchmark com %d iterações, %d execuções",
ITERATIONS, RUNS);
// Aquecer cache
slow_calculation_unoptimized(100);
fast_calculation_optimized(100);
// Benchmark versão não otimizada
uint64_t start = esp_timer_get_time();
for (int i = 0; i < RUNS; i++) {
slow_calculation_unoptimized(ITERATIONS);
}
uint64_t slow_time = esp_timer_get_time() - start;
// Benchmark versão otimizada
start = esp_timer_get_time();
for (int i = 0; i < RUNS; i++) {
fast_calculation_optimized(ITERATIONS);
}
uint64_t fast_time = esp_timer_get_time() - start;
// Apresentar resultados
ESP_LOGI(TAG, "Versão não otimizada: %llu μs", slow_time);
ESP_LOGI(TAG, "Versão otimizada: %llu μs", fast_time);
ESP_LOGI(TAG, "Melhoria: %.1f%%",
100.0f * (1.0f - (float)fast_time / (float)slow_time));
}
/**
* Profiling de uso de memória
*/
void profile_memory_usage(void)
{
ESP_LOGI(TAG, "=== Profiling de Memória ===");
// Heap disponível
ESP_LOGI(TAG, "Heap livre: %lu bytes", esp_get_free_heap_size());
ESP_LOGI(TAG, "Heap mínimo histórico: %lu bytes",
esp_get_minimum_free_heap_size());
// Informações detalhadas de heap
multi_heap_info_t heap_info;
heap_caps_get_info(&heap_info, MALLOC_CAP_DEFAULT);
ESP_LOGI(TAG, "Total alocado: %lu bytes", heap_info.total_allocated_bytes);
ESP_LOGI(TAG, "Maior bloco livre: %lu bytes", heap_info.largest_free_block);
ESP_LOGI(TAG, "Blocos livres: %lu", heap_info.free_blocks);
ESP_LOGI(TAG, "Blocos alocados: %lu", heap_info.allocated_blocks);
// Calcular fragmentação
if (heap_info.total_free_bytes > 0) {
float fragmentation = 1.0f -
((float)heap_info.largest_free_block / heap_info.total_free_bytes);
ESP_LOGI(TAG, "Fragmentação estimada: %.1f%%", fragmentation * 100.0f);
}
}
/**
* Monitorar stack usage de tasks
*/
void profile_task_stacks(void)
{
ESP_LOGI(TAG, "=== Stack Usage das Tasks ===");
UBaseType_t num_tasks = uxTaskGetNumberOfTasks();
TaskStatus_t *task_array = malloc(num_tasks * sizeof(TaskStatus_t));
if (task_array) {
num_tasks = uxTaskGetSystemState(task_array, num_tasks, NULL);
ESP_LOGI(TAG, "%-20s %10s %10s %10s",
"Nome", "Stack", "Livre", "Uso(%)");
ESP_LOGI(TAG, "-------------------------------------------------------");
for (UBaseType_t i = 0; i < num_tasks; i++) {
uint32_t stack_size = task_array[i].usStackHighWaterMark * sizeof(StackType_t);
// Estimar tamanho total da stack (aproximado)
uint32_t total_stack = stack_size * 3; // Heurística
uint32_t used = total_stack - stack_size;
float usage = 100.0f * (float)used / (float)total_stack;
ESP_LOGI(TAG, "%-20s %10lu %10lu %9.1f%%",
task_array[i].pcTaskName,
total_stack,
stack_size,
usage);
}
free(task_array);
}
}
void app_main(void)
{
ESP_LOGI(TAG, "Demonstrando profiling e otimização");
// Profiling simples com macros
PROFILE_START(initialization);
vTaskDelay(pdMS_TO_TICKS(100));
PROFILE_END(initialization);
// Benchmark de implementações
benchmark_implementations();
// Profiling de memória
profile_memory_usage();
// Profiling de stacks
profile_task_stacks();
// Relatório de profiling acumulado
vTaskDelay(pdMS_TO_TICKS(1000));
profile_print_report();
ESP_LOGI(TAG, "Profiling completo");
}