С какой точностью работает логирование программы

Точность логирования в программах

Вопрос о точности логирования в основном касается временных меток (timestamp) и порядка событий. Это критично для отладки, анализа производительности и восстановления после ошибок. Рассмотрим все аспекты.

Типы точности логирования

1. Точность временных меток

Секунды (1s)

#include <ctime>
#include <iostream>

int main() {
    time_t now = std::time(nullptr);
    std::cout << "Логирование: " << now << std::endl;  // 1677620400
    return 0;
}
// Проблема: при 1000 событий в секунду невозможно определить порядок

Миллисекунды (1ms = 10^-3 s)

#include <chrono>
#include <iostream>

int main() {
    auto now = std::chrono::system_clock::now();
    auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
        now.time_since_epoch()
    ).count();
    std::cout << "[" << ms << "] Событие" << std::endl;
    return 0;
}
// Хорошо для большинства приложений

Микросекунды (1μs = 10^-6 s)

#include <chrono>
#include <iostream>

int main() {
    auto now = std::chrono::high_resolution_clock::now();
    auto us = std::chrono::duration_cast<std::chrono::microseconds>(
        now.time_since_epoch()
    ).count();
    std::cout << "[" << us << "] Evento" << std::endl;
    return 0;
}
// Необходимо для профилирования, анализа latency

Наносекунды (1ns = 10^-9 s)

#include <chrono>
#include <iostream>

int main() {
    auto now = std::chrono::high_resolution_clock::now();
    auto ns = std::chrono::duration_cast<std::chrono::nanoseconds>(
        now.time_since_epoch()
    ).count();
    std::cout << "[" << ns << "] Event" << std::endl;
    return 0;
}
// Для high-frequency trading, микроуправления, критических систем

Рекомендуемые точности для разных областей

Веб-приложения, backend:

• Минимум: миллисекунды (ms)
• Оптимум: миллисекунды с UTC timezone
• Пример: [2024-03-15 14:30:45.123] INFO: Request processed

Высоконагруженные системы (1000+ rps):

• Минимум: микросекунды (μs)
• Оптимум: микросекунды с thread ID
• Пример: [2024-03-15 14:30:45.123456 tid=5] Event

Системное программирование, драйверы:

• Минимум: микросекунды (μs)
• Оптимум: наносекунды (ns) для critical sections

Financial systems, high-frequency trading:

• Обязательно: наносекунды (ns)
• Пример: [1710513045123456789 ns] Trade executed

Примеры реализации логирования

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

#include <iostream>
#include <chrono>
#include <iomanip>
#include <sstream>
#include <ctime>

class Logger {
public:
    static std::string now_string() {
        auto now = std::chrono::system_clock::now();
        auto time_t_now = std::chrono::system_clock::to_time_t(now);
        auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
            now.time_since_epoch()
        ) % 1000;
        
        std::stringstream ss;
        ss << std::put_time(std::localtime(&time_t_now), "%Y-%m-%d %H:%M:%S")
           << . << std::setfill(0) << std::setw(3) << ms.count();
        
        return ss.str();
    }
    
    static void log(const std::string& message) {
        std::cout << "[" << now_string() << "] " << message << std::endl;
    }
};

int main() {
    Logger::log("Приложение запущено");
    Logger::log("Обработка запроса");
    Logger::log("Запрос завершён");
    return 0;
}

/* Вывод:
[2024-03-15 14:30:45.123] Приложение запущено
[2024-03-15 14:30:45.124] Обработка запроса
[2024-03-15 14:30:45.125] Запрос завершён
*/

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

#include <iostream>
#include <chrono>
#include <thread>
#include <iomanip>
#include <sstream>

class HighPrecisionLogger {
public:
    static void log(const std::string& level, const std::string& message) {
        auto now = std::chrono::high_resolution_clock::now();
        auto us = std::chrono::duration_cast<std::chrono::microseconds>(
            now.time_since_epoch()
        ).count();
        
        auto thread_id = std::this_thread::get_id();
        
        std::cout << "[" << us << " μs] "
                  << "[" << level << "] "
                  << "[tid=" << thread_id << "] "
                  << message << std::endl;
    }
};

int main() {
    HighPrecisionLogger::log("INFO", "Старт обработки");
    std::chrono::high_resolution_clock::sleep_for(
        std::chrono::microseconds(1500)
    );
    HighPrecisionLogger::log("INFO", "Конец обработки");
    return 0;
}

/* Примерный вывод:
[1710513045123000 μs] [INFO] [tid=...] Старт обработки
[1710513045124500 μs] [INFO] [tid=...] Конец обработки
*/

Факторы, влияющие на точность

1. Разрешение часов операционной системы

Linux:

• clock_gettime(CLOCK_REALTIME) — системное время, часто микросекундное
• clock_gettime(CLOCK_MONOTONIC) — монотонное время, не зависит от синхронизации NTP
• Реальное разрешение: часто 1 микросекунда или лучше

#include <ctime>
#include <iostream>

int main() {
    timespec ts;
    clock_gettime(CLOCK_MONOTONIC, &ts);
    
    long nanoseconds = ts.tv_nsec;
    std::cout << "Наносекунды: " << nanoseconds << std::endl;
    return 0;
}

Windows:

• QueryPerformanceCounter() — частота может быть от 1МГц до ГГц
• Часто 100 наносекунд

#include <windows.h>
#include <iostream>

int main() {
    LARGE_INTEGER frequency, counter;
    QueryPerformanceFrequency(&frequency);
    QueryPerformanceCounter(&counter);
    
    double nanoseconds = (counter.QuadPart * 1e9) / frequency.QuadPart;
    std::cout << "Наносекунды: " << nanoseconds << std::endl;
    return 0;
}

2. Синхронизация времени (NTP)

Для распределённых систем:

• NTP даёт точность ~10ms в локальной сети
• Для критичных систем: PTP (Precision Time Protocol) — микросекундная точность
• Важно логировать UTC time для синхронизации логов между машинами

#include <chrono>
#include <iostream>
#include <iomanip>
#include <ctime>

int main() {
    // Всегда используй UTC для логирования в распределённых системах
    auto now = std::chrono::system_clock::now();
    auto time_t_now = std::chrono::system_clock::to_time_t(now);
    
    // gmtime для UTC
    std::cout << std::put_time(std::gmtime(&time_t_now), "%Y-%m-%d %H:%M:%S UTC")
              << std::endl;
    return 0;
}

3. Асинхронное логирование

Если логирование происходит в отдельном потоке, временные метки могут быть смещены:

#include <iostream>
#include <thread>
#include <chrono>
#include <queue>
#include <mutex>

struct LogEvent {
    std::chrono::nanoseconds timestamp;
    std::string message;
};

class AsyncLogger {
private:
    std::queue<LogEvent> log_queue;
    std::mutex mutex;
    
public:
    void log(const std::string& message) {
        auto ts = std::chrono::high_resolution_clock::now()
                      .time_since_epoch();
        
        {
            std::lock_guard<std::mutex> lock(mutex);
            log_queue.push({ts, message});
        }
        // Логирование происходит асинхронно в другом потоке
    }
};

Лучшие практики логирования

1. Выбирай правильную точность:

• Миллисекунды для большинства приложений
• Микросекунды для высоконагруженных систем
• Наносекунды только если действительно нужно

2. Используй UTC для распределённых систем:

auto now = std::chrono::system_clock::now();
// Не используй локальное время в логах

3. Включай thread ID в high-concurrency приложениях:

std::cout << "[tid=" << std::this_thread::get_id() << "] message";

4. Используй структурированное логирование:

{"timestamp": "2024-03-15T14:30:45.123456Z", "level": "INFO", "message": "Event", "thread_id": 123}

5. Логируй с достаточной информацией:

• Уровень (DEBUG, INFO, WARN, ERROR)
• Компонент/модуль
• Thread ID (если многопоточно)
• Stack trace при ошибках

6. В production используй library, а не printf():

#include <spdlog/spdlog.h>

auto logger = spdlog::basic_logger_mt("file_logger", "logs/basic.txt");
logger->info("Событие с правильной временной меткой");