Rework drawtime and related timekeeping code to use microseconds

7 files changed, 101 insertions, 85 deletions

diff --git a/src/client/camera.cpp b/src/client/camera.cpp
index 3712d77ea..d1f19adb3 100644
--- a/src/client/camera.cpp
+++ b/src/client/camera.cpp
@@ -308,7 +308,7 @@ void Camera::addArmInertia(f32 player_yaw)
 	}
 }
 
-void Camera::update(LocalPlayer* player, f32 frametime, f32 busytime, f32 tool_reload_ratio)
+void Camera::update(LocalPlayer* player, f32 frametime, f32 tool_reload_ratio)
 {
 	// Get player position
 	// Smooth the movement when walking up stairs
diff --git a/src/client/camera.h b/src/client/camera.h
index 3e1cb4fdf..403d6024c 100644
--- a/src/client/camera.h
+++ b/src/client/camera.h
@@ -140,9 +140,7 @@ public:
 	void step(f32 dtime);
 
 	// Update the camera from the local player's position.
-	// busytime is used to adjust the viewing range.
-	void update(LocalPlayer* player, f32 frametime, f32 busytime,
-			f32 tool_reload_ratio);
+	void update(LocalPlayer* player, f32 frametime, f32 tool_reload_ratio);
 
 	// Update render distance
 	void updateViewingRange();
diff --git a/src/client/game.cpp b/src/client/game.cpp
index 7478e225f..8959b5f15 100644
--- a/src/client/game.cpp
+++ b/src/client/game.cpp
@@ -575,10 +575,19 @@ public:
 /****************************************************************************
  ****************************************************************************/
 
-const float object_hit_delay = 0.2;
+const static float object_hit_delay = 0.2;
 
 struct FpsControl {
-	u32 last_time, busy_time, sleep_time;
+	FpsControl() : last_time(0), busy_time(0), sleep_time(0) {}
+
+	void reset();
+
+	void limit(IrrlichtDevice *device, f32 *dtime);
+
+	u32 getBusyMs() const { return busy_time / 1000; }
+
+	// all values in microseconds (us)
+	u64 last_time, busy_time, sleep_time;
 };
 
 
@@ -712,7 +721,7 @@ protected:
 	void updatePlayerControl(const CameraOrientation &cam);
 	void step(f32 *dtime);
 	void processClientEvents(CameraOrientation *cam);
-	void updateCamera(u32 busy_time, f32 dtime);
+	void updateCamera(f32 dtime);
 	void updateSound(f32 dtime);
 	void processPlayerInteraction(f32 dtime, bool show_hud, bool show_debug);
 	/*!
@@ -743,8 +752,6 @@ protected:
 	void updateShadows();
 
 	// Misc
-	void limitFps(FpsControl *fps_timings, f32 *dtime);
-
 	void showOverlayMessage(const char *msg, float dtime, int percent,
 			bool draw_clouds = true);
 
@@ -1056,14 +1063,14 @@ void Game::run()
 	RunStats stats              = { 0 };
 	CameraOrientation cam_view_target  = { 0 };
 	CameraOrientation cam_view  = { 0 };
-	FpsControl draw_times       = { 0 };
+	FpsControl draw_times;
 	f32 dtime; // in seconds
 
 	/* Clear the profiler */
 	Profiler::GraphValues dummyvalues;
 	g_profiler->graphGet(dummyvalues);
 
-	draw_times.last_time = m_rendering_engine->get_timer_time();
+	draw_times.reset();
 
 	set_light_table(g_settings->getFloat("display_gamma"));
 
@@ -1095,7 +1102,7 @@ void Game::run()
 		// Calculate dtime =
 		//    m_rendering_engine->run() from this iteration
 		//  + Sleep time until the wanted FPS are reached
-		limitFps(&draw_times, &dtime);
+		draw_times.limit(device, &dtime);
 
 		// Prepare render data for next iteration
 
@@ -1125,7 +1132,7 @@ void Game::run()
 		step(&dtime);
 		processClientEvents(&cam_view_target);
 		updateDebugState();
-		updateCamera(draw_times.busy_time, dtime);
+		updateCamera(dtime);
 		updateSound(dtime);
 		processPlayerInteraction(dtime, m_game_ui->m_flags.show_hud,
 			m_game_ui->m_flags.show_basic_debug);
@@ -1495,15 +1502,15 @@ bool Game::connectToServer(const GameStartData &start_data,
 	try {
 		input->clear();
 
-		FpsControl fps_control = { 0 };
+		FpsControl fps_control;
 		f32 dtime;
 		f32 wait_time = 0; // in seconds
 
-		fps_control.last_time = m_rendering_engine->get_timer_time();
+		fps_control.reset();
 
 		while (m_rendering_engine->run()) {
 
-			limitFps(&fps_control, &dtime);
+			fps_control.limit(device, &dtime);
 
 			// Update client and server
 			client->step(dtime);
@@ -1570,14 +1577,14 @@ bool Game::getServerContent(bool *aborted)
 {
 	input->clear();
 
-	FpsControl fps_control = { 0 };
+	FpsControl fps_control;
 	f32 dtime; // in seconds
 
-	fps_control.last_time = m_rendering_engine->get_timer_time();
+	fps_control.reset();
 
 	while (m_rendering_engine->run()) {
 
-		limitFps(&fps_control, &dtime);
+		fps_control.limit(device, &dtime);
 
 		// Update client and server
 		client->step(dtime);
@@ -1774,10 +1781,10 @@ void Game::updateProfilers(const RunStats &stats, const FpsControl &draw_times,
 	}
 
 	// Update update graphs
-	g_profiler->graphAdd("Time non-rendering [ms]",
+	g_profiler->graphAdd("Time non-rendering [us]",
 		draw_times.busy_time - stats.drawtime);
 
-	g_profiler->graphAdd("Sleep [ms]", draw_times.sleep_time);
+	g_profiler->graphAdd("Sleep [us]", draw_times.sleep_time);
 	g_profiler->graphAdd("FPS", 1.0f / dtime);
 }
 
@@ -1810,9 +1817,9 @@ void Game::updateStats(RunStats *stats, const FpsControl &draw_times,
 	/* Busytime average and jitter calculation
 	 */
 	jp = &stats->busy_time_jitter;
-	jp->avg = jp->avg + draw_times.busy_time * 0.02;
+	jp->avg = jp->avg + draw_times.getBusyMs() * 0.02;
 
-	jitter = draw_times.busy_time - jp->avg;
+	jitter = draw_times.getBusyMs() - jp->avg;
 
 	if (jitter > jp->max)
 		jp->max = jitter;
@@ -2932,7 +2939,7 @@ void Game::updateChat(f32 dtime)
 	m_game_ui->updateChatSize();
 }
 
-void Game::updateCamera(u32 busy_time, f32 dtime)
+void Game::updateCamera(f32 dtime)
 {
 	LocalPlayer *player = client->getEnv().getLocalPlayer();
 
@@ -2971,7 +2978,7 @@ void Game::updateCamera(u32 busy_time, f32 dtime)
 	float tool_reload_ratio = runData.time_from_last_punch / full_punch_interval;
 
 	tool_reload_ratio = MYMIN(tool_reload_ratio, 1.0);
-	camera->update(player, dtime, busy_time / 1000.0f, tool_reload_ratio);
+	camera->update(player, dtime, tool_reload_ratio);
 	camera->step(dtime);
 
 	v3f camera_position = camera->getPosition();
@@ -3848,6 +3855,24 @@ void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 	}
 
 	/*
+		Damage camera tilt
+	*/
+	if (player->hurt_tilt_timer > 0.0f) {
+		player->hurt_tilt_timer -= dtime * 6.0f;
+
+		if (player->hurt_tilt_timer < 0.0f)
+			player->hurt_tilt_strength = 0.0f;
+	}
+
+	/*
+		Update minimap pos and rotation
+	*/
+	if (mapper && m_game_ui->m_flags.show_hud) {
+		mapper->setPos(floatToInt(player->getPosition(), BS));
+		mapper->setAngle(player->getYaw());
+	}
+
+	/*
 		Get chat messages from client
 	*/
 
@@ -3920,11 +3945,11 @@ void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 	} while (false);
 
 	/*
-		Drawing begins
+		==================== Drawing begins ====================
 	*/
-	const video::SColor &skycolor = sky->getSkyColor();
+	const video::SColor skycolor = sky->getSkyColor();
 
-	TimeTaker tt_draw("Draw scene");
+	TimeTaker tt_draw("Draw scene", nullptr, PRECISION_MICRO);
 	driver->beginScene(true, true, skycolor);
 
 	bool draw_wield_tool = (m_game_ui->m_flags.show_hud &&
@@ -3963,25 +3988,7 @@ void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 	}
 
 	/*
-		Damage camera tilt
-	*/
-	if (player->hurt_tilt_timer > 0.0f) {
-		player->hurt_tilt_timer -= dtime * 6.0f;
-
-		if (player->hurt_tilt_timer < 0.0f)
-			player->hurt_tilt_strength = 0.0f;
-	}
-
-	/*
-		Update minimap pos and rotation
-	*/
-	if (mapper && m_game_ui->m_flags.show_hud) {
-		mapper->setPos(floatToInt(player->getPosition(), BS));
-		mapper->setAngle(player->getYaw());
-	}
-
-	/*
-		End scene
+		==================== End scene ====================
 	*/
 	if (++m_reset_HW_buffer_counter > 500) {
 		/*
@@ -4004,11 +4011,12 @@ void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 		driver->removeAllHardwareBuffers();
 		m_reset_HW_buffer_counter = 0;
 	}
+
 	driver->endScene();
 
 	stats->drawtime = tt_draw.stop(true);
-	g_profiler->avg("Game::updateFrame(): draw scene [ms]", stats->drawtime);
-	g_profiler->graphAdd("Update frame [ms]", tt_update.stop(true));
+	g_profiler->graphAdd("Draw scene [us]", stats->drawtime);
+	g_profiler->avg("Game::updateFrame(): update frame [ms]", tt_update.stop(true));
 }
 
 /* Log times and stuff for visualization */
@@ -4052,47 +4060,46 @@ void Game::updateShadows()
  Misc
  ****************************************************************************/
 
-/* On some computers framerate doesn't seem to be automatically limited
- */
-inline void Game::limitFps(FpsControl *fps_timings, f32 *dtime)
+void FpsControl::reset()
 {
-	// not using getRealTime is necessary for wine
-	device->getTimer()->tick(); // Maker sure device time is up-to-date
-	u32 time = device->getTimer()->getTime();
-	u32 last_time = fps_timings->last_time;
-
-	if (time > last_time)  // Make sure time hasn't overflowed
-		fps_timings->busy_time = time - last_time;
-	else
-		fps_timings->busy_time = 0;
+	last_time = porting::getTimeUs();
+}
 
-	u32 frametime_min = 1000 / (
+/*
+ * On some computers framerate doesn't seem to be automatically limited
+ */
+void FpsControl::limit(IrrlichtDevice *device, f32 *dtime)
+{
+	const u64 frametime_min = 1000000.0f / (
 		device->isWindowFocused() && !g_menumgr.pausesGame()
 			? g_settings->getFloat("fps_max")
 			: g_settings->getFloat("fps_max_unfocused"));
 
-	if (fps_timings->busy_time < frametime_min) {
-		fps_timings->sleep_time = frametime_min - fps_timings->busy_time;
-		device->sleep(fps_timings->sleep_time);
+	u64 time = porting::getTimeUs();
+
+	if (time > last_time) // Make sure time hasn't overflowed
+		busy_time = time - last_time;
+	else
+		busy_time = 0;
+
+	if (busy_time < frametime_min) {
+		sleep_time = frametime_min - busy_time;
+		if (sleep_time > 1000)
+			sleep_ms(sleep_time / 1000);
 	} else {
-		fps_timings->sleep_time = 0;
+		sleep_time = 0;
 	}
 
-	/* Get the new value of the device timer. Note that device->sleep() may
-	 * not sleep for the entire requested time as sleep may be interrupted and
-	 * therefore it is arguably more accurate to get the new time from the
-	 * device rather than calculating it by adding sleep_time to time.
-	 */
-
-	device->getTimer()->tick(); // Update device timer
-	time = device->getTimer()->getTime();
+	// Read the timer again to accurately determine how long we actually slept,
+	// rather than calculating it by adding sleep_time to time.
+	time = porting::getTimeUs();
 
-	if (time > last_time)  // Make sure last_time hasn't overflowed
-		*dtime = (time - last_time) / 1000.0;
+	if (time > last_time) // Make sure last_time hasn't overflowed
+		*dtime = (time - last_time) / 1000000.0f;
 	else
 		*dtime = 0;
 
-	fps_timings->last_time = time;
+	last_time = time;
 }
 
 void Game::showOverlayMessage(const char *msg, float dtime, int percent, bool draw_clouds)
diff --git a/src/client/game.h b/src/client/game.h
index fbbf106db..d87e747c5 100644
--- a/src/client/game.h
+++ b/src/client/game.h
@@ -33,7 +33,7 @@ struct Jitter {
 };
 
 struct RunStats {
-	u32 drawtime;
+	u64 drawtime; // (us)
 
 	Jitter dtime_jitter, busy_time_jitter;
 };
diff --git a/src/client/gameui.cpp b/src/client/gameui.cpp
index ecb8e0ec4..bae5241b1 100644
--- a/src/client/gameui.cpp
+++ b/src/client/gameui.cpp
@@ -104,16 +104,16 @@ void GameUI::update(const RunStats &stats, Client *client, MapDrawControl *draw_
 
 	// Minimal debug text must only contain info that can't give a gameplay advantage
 	if (m_flags.show_minimal_debug) {
-		static float drawtime_avg = 0;
-		drawtime_avg = drawtime_avg * 0.95 + stats.drawtime * 0.05;
-		u16 fps = 1.0 / stats.dtime_jitter.avg;
+		const u16 fps = 1.0 / stats.dtime_jitter.avg;
+		m_drawtime_avg *= 0.95f;
+		m_drawtime_avg += 0.05f * (stats.drawtime / 1000);
 
 		std::ostringstream os(std::ios_base::binary);
 		os << std::fixed
 			<< PROJECT_NAME_C " " << g_version_hash
 			<< " | FPS: " << fps
 			<< std::setprecision(0)
-			<< " | drawtime: " << drawtime_avg << "ms"
+			<< " | drawtime: " << m_drawtime_avg << "ms"
 			<< std::setprecision(1)
 			<< " | dtime jitter: "
 			<< (stats.dtime_jitter.max_fraction * 100.0) << "%"
diff --git a/src/client/gameui.h b/src/client/gameui.h
index 3f31f1b57..cc9377bdc 100644
--- a/src/client/gameui.h
+++ b/src/client/gameui.h
@@ -110,6 +110,8 @@ public:
 private:
 	Flags m_flags;
 
+	float m_drawtime_avg = 0;
+
 	gui::IGUIStaticText *m_guitext = nullptr;  // First line of debug text
 	gui::IGUIStaticText *m_guitext2 = nullptr; // Second line of debug text
 
diff --git a/src/gui/profilergraph.cpp b/src/gui/profilergraph.cpp
index b29285e2f..f71ef3799 100644
--- a/src/gui/profilergraph.cpp
+++ b/src/gui/profilergraph.cpp
@@ -94,20 +94,29 @@ void ProfilerGraph::draw(s32 x_left, s32 y_bottom, video::IVideoDriver *driver,
 				show_min = 0;
 		}
 
-		s32 texth = 15;
+		const s32 texth = 15;
 		char buf[10];
-		porting::mt_snprintf(buf, sizeof(buf), "%.3g", show_max);
+		if (floorf(show_max) == show_max)
+			porting::mt_snprintf(buf, sizeof(buf), "%.5g", show_max);
+		else
+			porting::mt_snprintf(buf, sizeof(buf), "%.3g", show_max);
 		font->draw(utf8_to_wide(buf).c_str(),
 				core::rect<s32>(textx, y - graphh, textx2,
 						y - graphh + texth),
 				meta.color);
-		porting::mt_snprintf(buf, sizeof(buf), "%.3g", show_min);
+
+		if (floorf(show_min) == show_min)
+			porting::mt_snprintf(buf, sizeof(buf), "%.5g", show_min);
+		else
+			porting::mt_snprintf(buf, sizeof(buf), "%.3g", show_min);
 		font->draw(utf8_to_wide(buf).c_str(),
 				core::rect<s32>(textx, y - texth, textx2, y), meta.color);
+
 		font->draw(utf8_to_wide(id).c_str(),
 				core::rect<s32>(textx, y - graphh / 2 - texth / 2, textx2,
 						y - graphh / 2 + texth / 2),
 				meta.color);
+
 		s32 graph1y = y;
 		s32 graph1h = graphh;
 		bool relativegraph = (show_min != 0 && show_min != show_max);