improve logging in main application for users

fixes #47
This commit is contained in:
PancakeTAS 2025-07-17 02:40:24 +02:00 committed by Pancake
parent ce26c8a9e6
commit d6abc006a9
7 changed files with 96 additions and 208 deletions

View file

@ -1,10 +1,15 @@
#pragma once
#include <cstdint>
namespace Benchmark {
///
/// Run the benchmark.
///
void run();
/// @param width The width of the benchmark.
/// @param height The height of the benchmark.
///
[[noreturn]] void run(uint32_t width, uint32_t height);
}

View file

@ -1,74 +0,0 @@
#pragma once
#include <format>
#include <fstream>
#include <iostream>
#include <mutex>
#include <set>
#include <string>
#include <string_view>
namespace Log {
namespace Internal {
extern bool isSetup;
extern std::set<std::string> debugModules;
extern bool debugAllModules;
extern std::ofstream logFile;
extern std::mutex logMutex;
void setup();
}
template<typename... Args>
void log(std::string_view color, std::string_view module,
std::format_string<Args...> fmt, Args&&... args) {
Internal::setup();
const std::string prefix = std::format("lsfg-vk({}): ", module);
const std::string message = std::format(fmt, std::forward<Args>(args)...);
const std::lock_guard<std::mutex> lock(Internal::logMutex);
std::cerr << color << prefix << message << "\033[0m" << '\n';
if (Internal::logFile.is_open()) {
Internal::logFile << prefix << message << '\n';
Internal::logFile.flush();
}
}
const std::string_view WHITE = "\033[1;37m";
const std::string_view YELLOW = "\033[1;33m";
const std::string_view RED = "\033[1;31m";
template<typename... Args>
void info(std::string_view module, std::format_string<Args...> fmt, Args&&... args) {
log(WHITE, module, fmt, std::forward<Args>(args)...);
}
template<typename... Args>
void warn(std::string_view module, std::format_string<Args...> fmt, Args&&... args) {
log(YELLOW, module, fmt, std::forward<Args>(args)...);
}
template<typename... Args>
void error(std::string_view module, std::format_string<Args...> fmt, Args&&... args) {
log(RED, module, fmt, std::forward<Args>(args)...);
}
const std::string_view GRAY = "\033[1;90m";
#ifdef LSFG_NO_DEBUG
template<typename... Args>
void debug(std::string_view, std::format_string<Args...>, Args&&...) {}
#else
template<typename... Args>
void debug(std::string_view module, std::format_string<Args...> fmt, Args&&... args) {
Internal::setup();
if (Internal::debugAllModules || Internal::debugModules.contains(std::string(module)))
log(GRAY, module, fmt, std::forward<Args>(args)...);
}
#endif
}

View file

@ -92,7 +92,7 @@ namespace {
if (event->len <= 0 || event->mask & IN_IGNORED)
continue;
std::string name(reinterpret_cast<char*>(event->name));
const std::string name(reinterpret_cast<char*>(event->name));
if (name != filename)
continue;

View file

@ -1,44 +1,19 @@
#include "config/config.hpp"
#include "extract/extract.hpp"
#include "utils/benchmark.hpp"
#include "utils/utils.hpp"
#include <cstdlib>
#include <exception>
#include <stdexcept>
#include <iostream>
#include <cstdint>
#include <cstdlib>
#include <string>
#include <thread>
namespace {
/// Check if the library is preloaded or Vulkan loaded.
bool isPreload() {
const char* preload = std::getenv("LD_PRELOAD");
if (!preload || *preload == '\0')
return false;
const std::string preload_str(preload);
return preload_str.find("liblsfg-vk.so") != std::string::npos;
}
/// Check if a benchmark is requested.
bool requestedBenchmark() {
const char* benchmark = std::getenv("LSFG_BENCHMARK");
if (!benchmark || *benchmark == '\0')
return false;
const std::string benchmark_str(benchmark);
return benchmark_str == "1";
}
__attribute__((constructor)) void lsfgvk_init() {
if (isPreload()) {
if (requestedBenchmark()) {
// TODO: Call benchmark function.
exit(0);
}
// TODO: health check, maybe?
std::cerr << "lsfg-vk: This library is not meant to be preloaded, unless you are running a benchmark.\n";
exit(1);
}
// read configuration (might block)
// read configuration
const std::string file = Utils::getConfigFile();
try {
Config::loadAndWatchConfig(file);
@ -59,7 +34,7 @@ namespace {
// exit silently if not enabled
auto& conf = Config::activeConf;
if (!conf.enable)
if (!conf.enable && name != "benchmark")
return;
// print config
@ -79,5 +54,46 @@ namespace {
exit(0);
}
std::cerr << "lsfg-vk: Shaders extracted successfully.\n";
// run benchmark if requested
const char* benchmark_flag = std::getenv("LSFG_BENCHMARK");
if (!benchmark_flag)
return;
const std::string resolution(benchmark_flag);
uint32_t width{};
uint32_t height{};
try {
const size_t x = resolution.find('x');
if (x == std::string::npos)
throw std::runtime_error("Unable to find 'x' in benchmark string");
const std::string width_str = resolution.substr(0, x);
const std::string height_str = resolution.substr(x + 1);
if (width_str.empty() || height_str.empty())
throw std::runtime_error("Invalid resolution");
const int32_t w = std::stoi(width_str);
const int32_t h = std::stoi(height_str);
if (w < 0 || h < 0)
throw std::runtime_error("Resolution cannot be negative");
width = static_cast<uint32_t>(w);
height = static_cast<uint32_t>(h);
} catch (const std::exception& e) {
std::cerr << "lsfg-vk: An error occurred while trying to parse the resolution, exiting:\n";
std::cerr << "- " << e.what() << '\n';
}
std::thread benchmark([width, height]() {
try {
Benchmark::run(width, height);
} catch (const std::exception& e) {
std::cerr << "lsfg-vk: An error occurred during the benchmark:\n";
std::cerr << "- " << e.what() << '\n';
}
});
benchmark.detach();
conf.enable = false;
}
}

View file

@ -1,63 +1,47 @@
#include "utils/benchmark.hpp"
#include "config/config.hpp"
#include "extract/extract.hpp"
#include "extract/trans.hpp"
#include "utils/log.hpp"
#include <vulkan/vulkan_core.h>
#include <lsfg_3_1.hpp>
#include <lsfg_3_1p.hpp>
#include <unistd.h>
#include <cstdint>
#include <chrono>
#include <iostream>
#include <cstdlib>
#include <cstdint>
#include <iomanip>
#include <thread>
#include <chrono>
#include <string>
#include <vector>
using namespace Benchmark;
void Benchmark::run() {
// fetch benchmark parameters
const char* lsfgFlowScale = std::getenv("LSFG_FLOW_SCALE");
const char* lsfgHdr = std::getenv("LSFG_HDR");
const char* lsfgMultiplier = std::getenv("LSFG_MULTIPLIER");
const char* lsfgExtentWidth = std::getenv("LSFG_EXTENT_WIDTH");
const char* lsfgExtentHeight = std::getenv("LSFG_EXTENT_HEIGHT");
const char* lsfgPerfMode = std::getenv("LSFG_PERF_MODE");
const float flowScale = lsfgFlowScale
? std::stof(lsfgFlowScale) : 1.0F;
const bool isHdr = lsfgHdr
? *lsfgHdr == '1' : false;
const uint64_t multiplier = lsfgMultiplier
? std::stoull(std::string(lsfgMultiplier)) : 2;
const uint32_t width = lsfgExtentWidth
? static_cast<uint32_t>(std::stoul(lsfgExtentWidth)) : 1920;
const uint32_t height = lsfgExtentHeight
? static_cast<uint32_t>(std::stoul(lsfgExtentHeight)) : 1080;
const bool perfMode = lsfgPerfMode
? *lsfgPerfMode == '1' : false;
void Benchmark::run(uint32_t width, uint32_t height) {
const auto& conf = Config::activeConf;
auto* lsfgInitialize = LSFG_3_1::initialize;
auto* lsfgCreateContext = LSFG_3_1::createContext;
auto* lsfgPresentContext = LSFG_3_1::presentContext;
if (perfMode) {
if (conf.performance) {
lsfgInitialize = LSFG_3_1P::initialize;
lsfgCreateContext = LSFG_3_1P::createContext;
lsfgPresentContext = LSFG_3_1P::presentContext;
}
Log::info("bench", "Running {}x benchmark with {}x{} extent and flow scale of {} {} HDR",
multiplier, width, height, flowScale, isHdr ? "with" : "without");
// create the benchmark context
const char* lsfgDeviceUUID = std::getenv("LSFG_DEVICE_UUID");
const uint64_t deviceUUID = lsfgDeviceUUID
? std::stoull(std::string(lsfgDeviceUUID), nullptr, 16) : 0x1463ABAC;
setenv("DISABLE_LSFG", "1", 1); // NOLINT
Extract::extractShaders();
lsfgInitialize(
deviceUUID, // some magic number if not given
isHdr, 1.0F / flowScale, multiplier - 1,
conf.hdr, 1.0F / conf.flowScale, conf.multiplier - 1,
[](const std::string& name) -> std::vector<uint8_t> {
auto dxbc = Extract::getShader(name);
auto spirv = Extract::translateShader(dxbc);
@ -66,21 +50,24 @@ void Benchmark::run() {
);
const int32_t ctx = lsfgCreateContext(-1, -1, {},
{ .width = width, .height = height },
isHdr ? VK_FORMAT_R16G16B16A16_SFLOAT : VK_FORMAT_R8G8B8A8_UNORM
conf.hdr ? VK_FORMAT_R16G16B16A16_SFLOAT : VK_FORMAT_R8G8B8A8_UNORM
);
Log::info("bench", "Benchmark context created, ready to run");
unsetenv("DISABLE_LSFG"); // NOLINT
// run the benchmark (run 8*n + 1 so the fences are waited on)
const auto now = std::chrono::high_resolution_clock::now();
const uint64_t iterations = (8 * 500) + 1;
for (uint64_t count = 0; count < iterations; count++) {
const uint64_t iterations = 8 * 500UL;
std::cerr << "lsfg-vk: Benchmark started, running " << iterations << " iterations...\n";
for (uint64_t count = 0; count < iterations + 1; count++) {
lsfgPresentContext(ctx, -1, {});
if (count % 500 == 0)
Log::info("bench", "{:.2f}% done ({}/{})",
static_cast<float>(count) / static_cast<float>(iterations) * 100.0F,
count + 1, iterations);
if (count % 50 == 0 && count > 0)
std::cerr << "lsfg-vk: "
<< std::setprecision(2) << std::fixed
<< static_cast<float>(count) / static_cast<float>(iterations) * 100.0F
<< "% done (" << count + 1 << "/" << iterations << ")\r";
}
const auto then = std::chrono::high_resolution_clock::now();
@ -89,15 +76,21 @@ void Benchmark::run() {
const auto perIteration = static_cast<float>(ms) / static_cast<float>(iterations);
const uint64_t totalGen = (multiplier - 1) * iterations;
const uint64_t totalGen = (conf.multiplier - 1) * iterations;
const auto genFps = static_cast<float>(totalGen) / (static_cast<float>(ms) / 1000.0F);
const uint64_t totalFrames = iterations * multiplier;
const uint64_t totalFrames = iterations * conf.multiplier;
const auto totalFps = static_cast<float>(totalFrames) / (static_cast<float>(ms) / 1000.0F);
Log::info("bench", "Benchmark completed in {} ms", ms);
Log::info("bench", "Time per iteration: {:.2f} ms", perIteration);
Log::info("bench", "Generation FPS: {:.2f}", genFps);
Log::info("bench", "Final FPS: {:.2f}", totalFps);
Log::info("bench", "Benchmark finished, exiting");
std::cerr << "lsfg-vk: Benchmark completed in " << ms << " ms\n";
std::cerr << " Time taken per real frame: "
<< std::setprecision(2) << std::fixed << perIteration << " ms\n";
std::cerr << " Generated " << totalGen << " frames in total at "
<< std::setprecision(2) << std::fixed << genFps << " FPS\n";
std::cerr << " Total of " << totalFrames << " frames presented at "
<< std::setprecision(2) << std::fixed << totalFps << " FPS\n";
// sleep for a second, then exit
std::this_thread::sleep_for(std::chrono::seconds(1));
_exit(0);
}

View file

@ -1,50 +0,0 @@
#include "utils/log.hpp"
#include <unistd.h>
#include <set>
#include <fstream>
#include <mutex>
#include <cstdlib>
#include <ios>
#include <sstream>
#include <string>
using namespace Log;
bool Internal::isSetup{};
std::set<std::string> Internal::debugModules;
bool Internal::debugAllModules{};
std::ofstream Internal::logFile;
std::mutex Internal::logMutex;
void Internal::setup() {
if (isSetup) return;
isSetup = true;
// open log file
const char* env_log_file = std::getenv("LSFG_LOG_FILE");
if (env_log_file) {
std::ostringstream filename;
filename << getpid() << "_" << env_log_file;
logFile.open(filename.str(), std::ios::app);
}
// parse debug modules
const char* env_log_debug = std::getenv("LSFG_LOG_DEBUG");
if (!env_log_debug)
return;
const std::string debugModulesStr(env_log_debug);
std::stringstream ss(debugModulesStr);
std::string item;
while (std::getline(ss, item, ',')) {
if (item == "all") {
debugAllModules = true;
return;
}
debugModules.insert(item);
}
}

View file

@ -1,5 +1,4 @@
#include "utils/utils.hpp"
#include "utils/log.hpp"
#include "common/exception.hpp"
#include "layer.hpp"
@ -82,12 +81,8 @@ std::vector<const char*> Utils::addExtensions(const char* const* extensions, siz
[e](const char* extName) {
return std::string(extName) == std::string(e);
});
if (it == ext.end()) {
Log::debug("hooks-init", "Adding extension: {}", e);
if (it == ext.end())
ext.push_back(e);
} else {
Log::debug("hooks-init", "Extension {} already present", e);
}
}
return ext;
@ -214,6 +209,9 @@ void Utils::resetLimitN(const std::string& id) noexcept {
/// Get the process name
std::string Utils::getProcessName() {
const char* benchmark_flag = std::getenv("LSFG_BENCHMARK");
if (benchmark_flag)
return "benchmark";
std::array<char, 4096> exe{};
const ssize_t exe_len = readlink("/proc/self/exe", exe.data(), exe.size() - 1);
if (exe_len <= 0)