LibCore: Introduce REPORT_TIME() for per call timing information

This macro outputs the time taken to reach the end of the current scope
to the debug console. It also shows the average time, total cumulative
time and the total number of calls.

It is also possible to limit the amount of debug output using
`REPORT_TIME_EVERY(name, n)` to only print every `n` calls.
This commit is contained in:
Tim Ledbetter
2025-11-09 11:48:31 +00:00
committed by Jelle Raaijmakers
parent 298e934077
commit 1df94c4513
Notes: github-actions[bot] 2025-11-11 10:48:59 +00:00
3 changed files with 70 additions and 0 deletions

View File

@@ -47,6 +47,7 @@ set(SOURCES
MappedFile.cpp
MimeData.cpp
Notifier.cpp
ReportTime.cpp
Resource.cpp
ResourceImplementation.cpp
ResourceImplementationFile.cpp

View File

@@ -0,0 +1,34 @@
/*
* Copyright (c) 2025, Tim Ledbetter <tim.ledbetter@ladybird.org>
*
* SPDX-License-Identifier: BSD-2-Clause
*/
#include "ReportTime.h"
#include <AK/Format.h>
#include <AK/HashMap.h>
#include <AK/NumberFormat.h>
namespace Core {
static HashMap<ByteString, TimingInfo> g_timing_info_table;
void log_timing_info(ByteString const& name, AK::Duration const& elapsed_time, u64 print_every_n_calls)
{
auto& timing_info = g_timing_info_table.ensure(name);
timing_info.call_count++;
timing_info.cumulative_time_nanoseconds += elapsed_time.to_nanoseconds();
u64 average_nanoseconds = timing_info.cumulative_time_nanoseconds / timing_info.call_count;
if (timing_info.call_count % print_every_n_calls != 0)
return;
dbgln("[Timing info for: {}] current: {:10} | average: {:10} | total: {:10} | calls: {}",
name,
human_readable_short_time(elapsed_time),
human_readable_short_time(AK::Duration::from_nanoseconds(average_nanoseconds)),
human_readable_short_time(AK::Duration::from_nanoseconds(timing_info.cumulative_time_nanoseconds)),
timing_info.call_count);
}
}

View File

@@ -0,0 +1,35 @@
/*
* Copyright (c) 2025, Tim Ledbetter <tim.ledbetter@ladybird.org>
*
* SPDX-License-Identifier: BSD-2-Clause
*/
#pragma once
#include <AK/ScopeGuard.h>
#include <AK/Time.h>
#include <LibCore/ElapsedTimer.h>
namespace Core {
struct TimingInfo {
u64 cumulative_time_nanoseconds { 0 };
u64 call_count { 0 };
};
void log_timing_info(ByteString const& name, AK::Duration const& elapsed_time, u64 print_every_n_calls);
#define CONCAT(a, b) a##b
#define UNIQUE_NAME(base) CONCAT(base, __LINE__)
#define REPORT_TIME_EVERY(name, print_every_n_calls) \
auto UNIQUE_NAME(report_time_timer_) = Core::ElapsedTimer::start_new(Core::TimerType::Precise); \
ScopeGuard UNIQUE_NAME(report_time_guard_) = [&] { \
auto elapsed_time = UNIQUE_NAME(report_time_timer_).elapsed_time(); \
Core::log_timing_info(#name, elapsed_time, print_every_n_calls); \
};
#define REPORT_TIME(name) \
REPORT_TIME_EVERY(name, 1)
}