Что нужно сделать, чтобы логировать с точностью до микросекунды?

Логирование с точностью до микросекунды

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

Основные подходы

1. Использование std::chrono с высокой точностью

С++11 предоставляет надёжный способ получения времени через std::chrono::high_resolution_clock.

#include <chrono>
#include <iostream>

auto now = std::chrono::high_resolution_clock::now();
auto duration = now.time_since_epoch();
auto micros = std::chrono::duration_cast<std::chrono::microseconds>(duration);

std::cout << "Микросекунды: " << micros.count() << std::endl;

Преимущества:

• Портативность через стандартную библиотеку
• Автоматический выбор самых точных часов в системе
• Работает на Linux, Windows, macOS

2. Платформо-зависимые решения

Linux (рекомендуется):

#include <time.h>

struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
long micros = ts.tv_sec * 1000000LL + ts.tv_nsec / 1000;

CLOCK_MONOTONIC гарантирует монотонное время (не скачет при синхронизации), что критично для логов.

Windows:

#include <windows.h>

LARGE_INTEGER frequency, counter;
QueryPerformanceFrequency(&frequency);
QueryPerformanceCounter(&counter);
double micros = (counter.QuadPart * 1000000.0) / frequency.QuadPart;

3. Оформление логирования

Для практического использования обёртываю в логгер:

#include <chrono>
#include <fstream>
#include <iomanip>
#include <sstream>

class MicrosecondLogger {
public:
    void log(const std::string& message) {
        auto now = std::chrono::high_resolution_clock::now();
        auto micros = std::chrono::duration_cast<std::chrono::microseconds>(
            now.time_since_epoch()).count();
        
        std::ofstream file("app.log", std::ios::app);
        file << "[" << micros << "] " << message << std::endl;
    }
};

Можно улучшить форматирование:

std::string format_timestamp() {
    auto now = std::chrono::high_resolution_clock::now();
    auto time_t = std::chrono::system_clock::to_time_t(now);
    auto micros = std::chrono::duration_cast<std::chrono::microseconds>(
        now.time_since_epoch()).count() % 1000000;
    
    std::stringstream ss;
    ss << std::put_time(std::localtime(&time_t), "%Y-%m-%d %H:%M:%S")
       << "." << std::setfill(0) << std::setw(6) << micros;
    return ss.str();
}

Критические моменты

Монотонность времени

• Для логирования операций используй CLOCK_MONOTONIC (Linux), не CLOCK_REALTIME
• CLOCK_REALTIME может прыгать назад при синхронизации NTP

Производительность

• Вызов high_resolution_clock дёшев, но при частом логировании может накапливаться
• На высоконагруженных системах используй асинхронное логирование

Точность платформы

• Linux: обычно наносекундная точность, но микросекунда гарантирована
• Windows: зависит от частоты таймера, может быть 100ns-15ms
• Проверь actual_granularity через clock_getres()

Рекомендация для production

Для production backend-систем использую:

1. std::chrono::high_resolution_clock для переносимости
2. Асинхронное логирование (не писать в файл из каждого лога)
3. CLOCK_MONOTONIC на Linux для надёжности
4. Форматирование: отдельно дата+время и микросекунды для читаемости

Пример асинхронного логгера:

class AsyncLogger {
    std::queue<std::string> queue;
    std::thread writer_thread;
    
public:
    void log(const std::string& msg) {
        queue.push(format_with_micros(msg));
    }
};

Этот подход гарантирует микросекундную точность без влияния на производительность основного приложения.