leonarski_fandClaude Opus 5.5
5421c569ed
A TimingMark (common/Logger.h) logs "TIMING <section> <seconds>" at debug level when a section ends, so the lines go to <prefix>_log.txt and stay off the terminal. Marked: each pass of RunPipeline (pre-pass, probe, output) and its first-pass indexing, image pass, scale/merge/symmetry phase, output files and census wait; inside the scale/merge phase every merge (labelled by its role: P1, P1 space-group search, P1 all observations, the adopted group, P1 cross-check, quality guard), the post-refinement, the space-group search and its two SearchSpaceGroup arms, adoption, analyses, the P1 cross-check wait, model validation and writing; inside RotationScaleMerge the ingest and, per arm, partial scaling, combine and fulls scaling, correction surfaces and the merge; the console's steps; and the results report. tools/rugnux_timing.py tabulates the tail of a log. Only the log changes: the outputs are byte-identical. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01SVmAWnzCmRKAXVUCdc4iNi
95 lines
3.4 KiB
C++
95 lines
3.4 KiB
C++
// SPDX-FileCopyrightText: 2024 Filip Leonarski, Paul Scherrer Institute <filip.leonarski@psi.ch>
|
|
// SPDX-License-Identifier: GPL-3.0-only
|
|
|
|
#pragma once
|
|
|
|
#include <cstdint>
|
|
#include <chrono>
|
|
#include <iostream>
|
|
#include <mutex>
|
|
#include <memory>
|
|
#include <string>
|
|
|
|
#include <spdlog/spdlog.h>
|
|
#include <spdlog/fmt/fmt.h>
|
|
|
|
namespace spdlog {
|
|
class logger;
|
|
}
|
|
|
|
class LogBufferSink;
|
|
|
|
class Logger {
|
|
std::shared_ptr<spdlog::logger> spdlog_logger;
|
|
std::shared_ptr<LogBufferSink> buffer; // only on a Buffered() logger
|
|
explicit Logger(std::shared_ptr<LogBufferSink> sink);
|
|
|
|
std::string service;
|
|
std::string hostname;
|
|
public:
|
|
Logger(const std::string &service_name, const std::string &file_name = "");
|
|
void ErrorException(const std::exception &e);
|
|
|
|
void Info(const std::string& msg) { spdlog_logger->info(msg); }
|
|
void Warning(const std::string& msg) { spdlog_logger->warn(msg); }
|
|
void Error(const std::string& msg) { spdlog_logger->error(msg); }
|
|
void Debug(const std::string& msg) { spdlog_logger->debug(msg); }
|
|
|
|
template<typename... Args>
|
|
void Info(fmt::format_string<Args...> fmt, Args &&... args) {
|
|
spdlog_logger->info(fmt, std::forward<Args>(args)...);
|
|
}
|
|
|
|
template<typename... Args>
|
|
void Error(fmt::format_string<Args...> fmt, Args &&... args) {
|
|
spdlog_logger->error(fmt, std::forward<Args>(args)...);
|
|
}
|
|
|
|
template<typename... Args>
|
|
void Debug(fmt::format_string<Args...> fmt, Args &&... args) {
|
|
spdlog_logger->debug(fmt, std::forward<Args>(args)...);
|
|
}
|
|
|
|
template<typename... Args>
|
|
void Warning(fmt::format_string<Args...> fmt, Args &&... args) {
|
|
spdlog_logger->warn(fmt, std::forward<Args>(args)...);
|
|
}
|
|
|
|
Logger& Verbose(bool input);
|
|
|
|
// Every Logger made after this call writes to `sink` alone instead of the console, keeps every
|
|
// level down to debug (the sink decides what it shows), and skips the version line each Logger
|
|
// otherwise opens with. For a program that owns its terminal: rugnux sends the whole log to a file
|
|
// next to its outputs and shows only warnings and errors among its own step lines.
|
|
static void RouteAll(spdlog::sink_ptr sink);
|
|
|
|
// A logger that keeps its lines instead of printing them, for work run beside other work that
|
|
// logs: ReplayInto hands them to `to` afterwards, in order and as one block, so the two do not
|
|
// interleave.
|
|
static Logger Buffered();
|
|
void ReplayInto(Logger &to) const;
|
|
};
|
|
|
|
// Times one section of a run: logs "TIMING <section> <seconds>" at debug level when the section ends -
|
|
// at Stop(), or when the mark goes out of scope, whichever comes first. rugnux keeps debug lines off the
|
|
// terminal and in <prefix>_log.txt; tools/rugnux_timing.py turns them into a table.
|
|
class TimingMark {
|
|
Logger &logger;
|
|
std::string section;
|
|
std::chrono::steady_clock::time_point start = std::chrono::steady_clock::now();
|
|
bool stopped = false;
|
|
public:
|
|
TimingMark(Logger &in_logger, std::string in_section)
|
|
: logger(in_logger), section(std::move(in_section)) {}
|
|
TimingMark(const TimingMark &) = delete;
|
|
TimingMark &operator=(const TimingMark &) = delete;
|
|
~TimingMark() { Stop(); }
|
|
void Stop() {
|
|
if (stopped)
|
|
return;
|
|
stopped = true;
|
|
logger.Debug("TIMING {} {:.3f}", section,
|
|
std::chrono::duration<double>(std::chrono::steady_clock::now() - start).count());
|
|
}
|
|
};
|