Change debug render time logging to use microseconds

This commit is contained in:
Kae 2023-07-03 16:04:17 +10:00
parent 8ee9c97f54
commit 11e00a8ded
6 changed files with 33 additions and 11 deletions

View File

@ -386,20 +386,26 @@ void ClientApplication::render() {
WorldClientPtr worldClient = m_universeClient->worldClient(); WorldClientPtr worldClient = m_universeClient->worldClient();
RendererPtr renderer = Application::renderer(); RendererPtr renderer = Application::renderer();
if (worldClient) { if (worldClient) {
int64_t start = Time::monotonicMilliseconds(); auto start = Time::monotonicMicroseconds();
renderer->switchEffectConfig("world"); renderer->switchEffectConfig("world");
worldClient->render(m_renderData, TilePainter::BorderTileSize); worldClient->render(m_renderData, TilePainter::BorderTileSize);
LogMap::set("render_world_client", strf(u8"{:05d}µs", Time::monotonicMicroseconds() - start));
start = Time::monotonicMicroseconds();
m_worldPainter->render(m_renderData, [&]() { worldClient->waitForLighting(); }); m_worldPainter->render(m_renderData, [&]() { worldClient->waitForLighting(); });
LogMap::set("render_world_painter", strf(u8"{:05d}µs", Time::monotonicMicroseconds() - start));
start = Time::monotonicMicroseconds();
m_mainInterface->renderInWorldElements(); m_mainInterface->renderInWorldElements();
LogMap::set("render_world_elements", strf(u8"{:05d}µs", Time::monotonicMicroseconds() - start));
renderer->switchEffectConfig("default"); renderer->switchEffectConfig("default");
LogMap::set("render_world", strf("{}ms", Time::monotonicMilliseconds() - start)); LogMap::set("render_world_total", strf(u8"{:05d}µs", Time::monotonicMicroseconds() - start));
} }
int64_t start = Time::monotonicMilliseconds(); auto start = Time::monotonicMicroseconds();
m_mainInterface->render(); m_mainInterface->render();
m_cinematicOverlay->render(); m_cinematicOverlay->render();
LogMap::set("render_ui", strf("{}ms", Time::monotonicMilliseconds() - start)); LogMap::set("render_interface", strf(u8"{:05d}µs", Time::monotonicMicroseconds() - start));
} }
if (!m_errorScreen->accepted()) if (!m_errorScreen->accepted())

View File

@ -20,6 +20,10 @@ int64_t Time::monotonicMilliseconds() {
return ticksToMilliseconds(monotonicTicks(), monotonicTickFrequency()); return ticksToMilliseconds(monotonicTicks(), monotonicTickFrequency());
} }
int64_t Time::monotonicMicroseconds() {
return ticksToMicroseconds(monotonicTicks(), monotonicTickFrequency());
}
String Time::printDuration(double time) { String Time::printDuration(double time) {
String hours; String hours;
String minutes; String minutes;
@ -58,6 +62,11 @@ int64_t Time::ticksToMilliseconds(int64_t ticks, int64_t tickFrequency) {
return (ticks + ticksPerMs / 2) / ticksPerMs; return (ticks + ticksPerMs / 2) / ticksPerMs;
} }
int64_t Time::ticksToMicroseconds(int64_t ticks, int64_t tickFrequency) {
int64_t ticksPerUs = (tickFrequency + 500000) / 1000000;
return (ticks + ticksPerUs / 2) / ticksPerUs;
}
int64_t Time::secondsToTicks(double seconds, int64_t tickFrequency) { int64_t Time::secondsToTicks(double seconds, int64_t tickFrequency) {
return round(seconds * tickFrequency); return round(seconds * tickFrequency);
} }
@ -66,6 +75,10 @@ int64_t Time::millisecondsToTicks(int64_t milliseconds, int64_t tickFrequency) {
return milliseconds * ((tickFrequency + 500) / 1000); return milliseconds * ((tickFrequency + 500) / 1000);
} }
int64_t Time::microsecondsToTicks(int64_t microseconds, int64_t tickFrequency) {
return microseconds * ((tickFrequency + 500000) / 1000000);
}
Clock::Clock(bool start) { Clock::Clock(bool start) {
m_elapsedTicks = 0; m_elapsedTicks = 0;
m_running = false; m_running = false;

View File

@ -14,6 +14,7 @@ namespace Time {
double monotonicTime(); double monotonicTime();
int64_t monotonicMilliseconds(); int64_t monotonicMilliseconds();
int64_t monotonicMicroseconds();
// Pretty print a duration of time (In days, hours, minutes, seconds, and milliseconds) // Pretty print a duration of time (In days, hours, minutes, seconds, and milliseconds)
String printDuration(double time); String printDuration(double time);
@ -34,8 +35,10 @@ namespace Time {
double ticksToSeconds(int64_t ticks, int64_t tickFrequency); double ticksToSeconds(int64_t ticks, int64_t tickFrequency);
int64_t ticksToMilliseconds(int64_t ticks, int64_t tickFrequency); int64_t ticksToMilliseconds(int64_t ticks, int64_t tickFrequency);
int64_t ticksToMicroseconds(int64_t ticks, int64_t tickFrequency);
int64_t secondsToTicks(double seconds, int64_t tickFrequency); int64_t secondsToTicks(double seconds, int64_t tickFrequency);
int64_t millisecondsToTicks(int64_t milliseconds, int64_t tickFrequency); int64_t millisecondsToTicks(int64_t milliseconds, int64_t tickFrequency);
int64_t microsecondsToTicks(int64_t microseconds, int64_t tickFrequency);
} }
// Keeps track of elapsed real time since a given moment. Guaranteed // Keeps track of elapsed real time since a given moment. Guaranteed

View File

@ -1263,7 +1263,7 @@ void MainInterface::renderDebug() {
m_guiContext->setFont(m_config->debugFont); m_guiContext->setFont(m_config->debugFont);
m_guiContext->setLineSpacing(0.5f); m_guiContext->setLineSpacing(0.5f);
m_guiContext->setFontProcessingDirectives(m_config->debugFontDirectives); m_guiContext->setFontProcessingDirectives(m_config->debugFontDirectives);
m_guiContext->setFontColor(Color::Green.toRgba()); m_guiContext->setFontColor(Color::White.toRgba());
m_guiContext->setFontMode(FontMode::Normal); m_guiContext->setFontMode(FontMode::Normal);
bool clearMap = m_debugMapClearTimer.wrapTick(); bool clearMap = m_debugMapClearTimer.wrapTick();
@ -1277,7 +1277,7 @@ void MainInterface::renderDebug() {
int counter = 0; int counter = 0;
for (auto const& pair : logMapValues) { for (auto const& pair : logMapValues) {
TextPositioning positioning = {Vec2F(m_config->debugOffset[0], windowHeight() - m_config->debugOffset[1] - m_config->fontSize * interfaceScale() * counter++)}; TextPositioning positioning = {Vec2F(m_config->debugOffset[0], windowHeight() - m_config->debugOffset[1] - m_config->fontSize * interfaceScale() * counter++)};
String& text = formatted.emplace_back(strf("^white;{}^lightgray;:^reset; {}", pair.first, pair.second)); String& text = formatted.emplace_back(strf("{}^lightgray;:^green,set; {}", pair.first, pair.second));
m_debugTextRect.combine(m_guiContext->determineTextSize(text, positioning).padded(m_config->debugBackgroundPad)); m_debugTextRect.combine(m_guiContext->determineTextSize(text, positioning).padded(m_config->debugBackgroundPad));
} }

View File

@ -1452,13 +1452,13 @@ void WorldClient::lightingMain() {
return; return;
if (m_renderData) { if (m_renderData) {
int64_t start = Time::monotonicMilliseconds(); int64_t start = Time::monotonicMicroseconds();
lightingTileGather(); lightingTileGather();
m_lightingCalculator.calculate(m_renderData->lightMap); m_lightingCalculator.calculate(m_renderData->lightMap);
m_renderData = nullptr; m_renderData = nullptr;
LogMap::set("render_light_calc", strf("{}ms", Time::monotonicMilliseconds() - start)); LogMap::set("render_world_async_lighting_calc_time", strf(u8"{:05d}µs", Time::monotonicMicroseconds() - start));
} }
m_lightingCond.wait(m_lightingMutex); m_lightingCond.wait(m_lightingMutex);

View File

@ -70,9 +70,9 @@ void WorldPainter::render(WorldRenderData& renderData, function<void()> lightWai
m_environmentPainter->renderFrontOrbiters(orbiterAndPlanetRatio, Vec2F(m_camera.screenSize()), renderData.skyRenderData); m_environmentPainter->renderFrontOrbiters(orbiterAndPlanetRatio, Vec2F(m_camera.screenSize()), renderData.skyRenderData);
if (lightWaiter) { if (lightWaiter) {
int64_t start = Time::monotonicMilliseconds(); auto start = Time::monotonicMicroseconds();
lightWaiter(); lightWaiter();
LogMap::set("render_light_wait", strf("{}ms", Time::monotonicMilliseconds() - start)); LogMap::set("render_world_async_lighting_wait_time", strf(u8"{:05d}µs", Time::monotonicMicroseconds() - start));
} }
if (renderData.isFullbright) { if (renderData.isFullbright) {