Better F6 profiler (#8750)

Update the profiler names to make more sense of what they actually represent
Move the profiler code from header to its source file
Use monospace font to align lines
Format the statistics line to align better with surrounding values
Refresh the profiler each 3 seconds (roughly)

src/client/activeobjectmgr.cpp

@@ -35,8 +35,7 @@ void ActiveObjectMgr::clear()
 void ActiveObjectMgr::step(
 		float dtime, const std::function<void(ClientActiveObject *)> &f)
 {
-	g_profiler->avg("Client::ActiveObjectMgr: num of objects",
-			m_active_objects.size());
+	g_profiler->avg("ActiveObjectMgr: CAO count [#]", m_active_objects.size());
 	for (auto &ao_it : m_active_objects) {
 		f(ao_it.second);
 	}

src/client/client.cpp

@@ -366,7 +366,6 @@ void Client::step(float dtime)
 	*/
 	const float map_timer_and_unload_dtime = 5.25;
 	if(m_map_timer_and_unload_interval.step(dtime, map_timer_and_unload_dtime)) {
-		ScopeProfiler sp(g_profiler, "Client: map timer and unload");
 		std::vector<v3s16> deleted_blocks;
 		m_env.getMap().timerUpdate(map_timer_and_unload_dtime,
 			g_settings->getFloat("client_unload_unused_data_timeout"),

src/client/clientenvironment.cpp

@@ -285,15 +285,14 @@ void ClientEnvironment::step(float dtime)
 	/*
 		Step and handle simple objects
 	*/
-	g_profiler->avg("CEnv: num of simple objects", m_simple_objects.size());
+	g_profiler->avg("ClientEnv: CSO count [#]", m_simple_objects.size());
 	for (auto i = m_simple_objects.begin(); i != m_simple_objects.end();) {
-		auto cur = i;
-		ClientSimpleObject *simple = *cur;
+		ClientSimpleObject *simple = *i;
 
 		simple->step(dtime);
 		if(simple->m_to_be_removed) {
 			delete simple;
-			i = m_simple_objects.erase(cur);
+			i = m_simple_objects.erase(i);
 		}
 		else {
 			++i;

src/client/clientmap.cpp

@@ -116,7 +116,6 @@ void ClientMap::getBlocksInViewRange(v3s16 cam_pos_nodes,
 void ClientMap::updateDrawList()
 {
 	ScopeProfiler sp(g_profiler, "CM::updateDrawList()", SPT_AVG);
-	g_profiler->add("CM::updateDrawList() count", 1);
 
 	for (auto &i : m_drawlist) {
 		MapBlock *block = i.second;
@@ -138,23 +137,10 @@ void ClientMap::updateDrawList()
 	v3s16 p_blocks_max;
 	getBlocksInViewRange(cam_pos_nodes, &p_blocks_min, &p_blocks_max);
 
-	// Number of blocks in rendering range
-	u32 blocks_in_range = 0;
+	// Number of blocks with mesh in rendering range
+	u32 blocks_in_range_with_mesh = 0;
 	// Number of blocks occlusion culled
 	u32 blocks_occlusion_culled = 0;
-	// Number of blocks in rendering range but don't have a mesh
-	u32 blocks_in_range_without_mesh = 0;
-	// Blocks that had mesh that would have been drawn according to
-	// rendering range (if max blocks limit didn't kick in)
-	u32 blocks_would_have_drawn = 0;
-	// Blocks that were drawn and had a mesh
-	u32 blocks_drawn = 0;
-	// Blocks which had a corresponding meshbuffer for this pass
-	//u32 blocks_had_pass_meshbuf = 0;
-	// Blocks from which stuff was actually drawn
-	//u32 blocks_without_stuff = 0;
-	// Distance to farthest drawn block
-	float farthest_drawn = 0;
 
 	// No occlusion culling when free_move is on and camera is
 	// inside ground
@@ -185,11 +171,11 @@ void ClientMap::updateDrawList()
 
 		u32 sector_blocks_drawn = 0;
 
-		for (auto block : sectorblocks) {
+		for (MapBlock *block : sectorblocks) {
 			/*
-			Compare block position to camera position, skip
-			if not seen on display
-		*/
+				Compare block position to camera position, skip
+				if not seen on display
+			*/
 
 			if (block->mesh)
 				block->mesh->updateCameraOffset(m_camera_offset);
@@ -203,20 +189,20 @@ void ClientMap::updateDrawList()
 					camera_direction, camera_fov, range, &d))
 				continue;
 
-			blocks_in_range++;
 
 			/*
 				Ignore if mesh doesn't exist
 			*/
-			if (!block->mesh) {
-				blocks_in_range_without_mesh++;
+			if (!block->mesh)
 				continue;
-			}
+
+			blocks_in_range_with_mesh++;
 
 			/*
 				Occlusion culling
 			*/
-			if (occlusion_culling_enabled && isBlockOccluded(block, cam_pos_nodes)) {
+			if ((!m_control.range_all && d > m_control.wanted_range * BS) ||
+					(occlusion_culling_enabled && isBlockOccluded(block, cam_pos_nodes))) {
 				blocks_occlusion_culled++;
 				continue;
 			}
@@ -224,36 +210,20 @@ void ClientMap::updateDrawList()
 			// This block is in range. Reset usage timer.
 			block->resetUsageTimer();
 
-			// Limit block count in case of a sudden increase
-			blocks_would_have_drawn++;
-			if (blocks_drawn >= m_control.wanted_max_blocks &&
-					!m_control.range_all &&
-					d > m_control.wanted_range * BS)
-				continue;
-
 			// Add to set
 			block->refGrab();
 			m_drawlist[block->getPos()] = block;
 
 			sector_blocks_drawn++;
-			blocks_drawn++;
-			if (d / BS > farthest_drawn)
-				farthest_drawn = d / BS;
-
 		} // foreach sectorblocks
 
 		if (sector_blocks_drawn != 0)
 			m_last_drawn_sectors.insert(sp);
 	}
 
-	g_profiler->avg("CM: blocks in range", blocks_in_range);
-	g_profiler->avg("CM: blocks occlusion culled", blocks_occlusion_culled);
-	if (blocks_in_range != 0)
-		g_profiler->avg("CM: blocks in range without mesh (frac)",
-				(float)blocks_in_range_without_mesh / blocks_in_range);
-	g_profiler->avg("CM: blocks drawn", blocks_drawn);
-	g_profiler->avg("CM: farthest drawn", farthest_drawn);
-	g_profiler->avg("CM: wanted max blocks", m_control.wanted_max_blocks);
+	g_profiler->avg("MapBlock meshes in range [#]", blocks_in_range_with_mesh);
+	g_profiler->avg("MapBlocks occlusion culled [#]", blocks_occlusion_culled);
+	g_profiler->avg("MapBlocks drawn [#]", m_drawlist.size());
 }
 
 struct MeshBufList
@@ -306,9 +276,9 @@ void ClientMap::renderMap(video::IVideoDriver* driver, s32 pass)
 
 	std::string prefix;
 	if (pass == scene::ESNRP_SOLID)
-		prefix = "CM: solid: ";
+		prefix = "renderMap(SOLID): ";
 	else
-		prefix = "CM: transparent: ";
+		prefix = "renderMap(TRANSPARENT): ";
 
 	/*
 		This is called two times per frame, reset on the non-transparent one
@@ -316,14 +286,6 @@ void ClientMap::renderMap(video::IVideoDriver* driver, s32 pass)
 	if (pass == scene::ESNRP_SOLID)
 		m_last_drawn_sectors.clear();
 
-	/*
-		Get time for measuring timeout.
-
-		Measuring time is very useful for long delays when the
-		machine is swapping a lot.
-	*/
-	std::time_t time1 = time(0);
-
 	/*
 		Get animation parameters
 	*/
@@ -340,26 +302,15 @@ void ClientMap::renderMap(video::IVideoDriver* driver, s32 pass)
 	*/
 
 	u32 vertex_count = 0;
-	u32 meshbuffer_count = 0;
 
 	// For limiting number of mesh animations per frame
 	u32 mesh_animate_count = 0;
-	u32 mesh_animate_count_far = 0;
-
-	// Blocks that were drawn and had a mesh
-	u32 blocks_drawn = 0;
-	// Blocks which had a corresponding meshbuffer for this pass
-	u32 blocks_had_pass_meshbuf = 0;
-	// Blocks from which stuff was actually drawn
-	u32 blocks_without_stuff = 0;
+	//u32 mesh_animate_count_far = 0;
 
 	/*
 		Draw the selected MapBlocks
 	*/
 
-	{
-	ScopeProfiler sp(g_profiler, prefix + "drawing blocks", SPT_AVG);
-
 	MeshBufListList drawbufs;
 
 	for (auto &i : m_drawlist) {
@@ -381,15 +332,13 @@ void ClientMap::renderMap(video::IVideoDriver* driver, s32 pass)
 			assert(mapBlockMesh);
 			// Pretty random but this should work somewhat nicely
 			bool faraway = d >= BS * 50;
-			//bool faraway = d >= m_control.wanted_range * BS;
 			if (mapBlockMesh->isAnimationForced() || !faraway ||
-					mesh_animate_count_far < (m_control.range_all ? 200 : 50)) {
+					mesh_animate_count < (m_control.range_all ? 200 : 50)) {
+
 				bool animated = mapBlockMesh->animate(faraway, animation_time,
 					crack, daynight_ratio);
 				if (animated)
 					mesh_animate_count++;
-				if (animated && faraway)
-					mesh_animate_count_far++;
 			} else {
 				mapBlockMesh->decreaseAnimationForceTimer();
 			}
@@ -437,46 +386,33 @@ void ClientMap::renderMap(video::IVideoDriver* driver, s32 pass)
 		}
 	}
 
+	TimeTaker draw("Drawing mesh buffers");
+
 	// Render all layers in order
 	for (auto &lists : drawbufs.lists) {
-		int timecheck_counter = 0;
 		for (MeshBufList &list : lists) {
-			timecheck_counter++;
-			if (timecheck_counter > 50) {
-				timecheck_counter = 0;
-				std::time_t time2 = time(0);
-				if (time2 > time1 + 4) {
-					infostream << "ClientMap::renderMap(): "
-						"Rendering takes ages, returning."
-						<< std::endl;
-					return;
-				}
+			// Check and abort if the machine is swapping a lot
+			if (draw.getTimerTime() > 2000) {
+				infostream << "ClientMap::renderMap(): Rendering took >2s, " <<
+						"returning." << std::endl;
+				return;
 			}
-
 			driver->setMaterial(list.m);
 
 			for (scene::IMeshBuffer *buf : list.bufs) {
 				driver->drawMeshBuffer(buf);
 				vertex_count += buf->getVertexCount();
-				meshbuffer_count++;
 			}
 		}
 	}
-	} // ScopeProfiler
+	g_profiler->avg(prefix + "draw meshes [ms]", draw.stop(true));
 
 	// Log only on solid pass because values are the same
 	if (pass == scene::ESNRP_SOLID) {
-		g_profiler->avg("CM: animated meshes", mesh_animate_count);
-		g_profiler->avg("CM: animated meshes (far)", mesh_animate_count_far);
+		g_profiler->avg("renderMap(): animated meshes [#]", mesh_animate_count);
 	}
 
-	g_profiler->avg(prefix + "vertices drawn", vertex_count);
-	if (blocks_had_pass_meshbuf != 0)
-		g_profiler->avg(prefix + "meshbuffers per block",
-			(float)meshbuffer_count / (float)blocks_had_pass_meshbuf);
-	if (blocks_drawn != 0)
-		g_profiler->avg(prefix + "empty blocks (frac)",
-			(float)blocks_without_stuff / blocks_drawn);
+	g_profiler->avg(prefix + "vertices drawn [#]", vertex_count);
 }
 
 static bool getVisibleBrightness(Map *map, const v3f &p0, v3f dir, float step,
@@ -555,6 +491,7 @@ static bool getVisibleBrightness(Map *map, const v3f &p0, v3f dir, float step,
 int ClientMap::getBackgroundBrightness(float max_d, u32 daylight_factor,
 		int oldvalue, bool *sunlight_seen_result)
 {
+	ScopeProfiler sp(g_profiler, "CM::getBackgroundBrightness", SPT_AVG);
 	static v3f z_directions[50] = {
 		v3f(-100, 0, 0)
 	};

src/client/clientmap.h

@@ -31,8 +31,6 @@ struct MapDrawControl
 	bool range_all = false;
 	// Wanted drawing range
 	float wanted_range = 0.0f;
-	// Maximum number of blocks to draw
-	u32 wanted_max_blocks = 0;
 	// show a wire frame for debugging
 	bool show_wireframe = false;
 };

src/client/clouds.cpp

@@ -99,7 +99,7 @@ void Clouds::render()
 	//if(SceneManager->getSceneNodeRenderPass() != scene::ESNRP_SOLID)
 		return;
 
-	ScopeProfiler sp(g_profiler, "Rendering of clouds, avg", SPT_AVG);
+	ScopeProfiler sp(g_profiler, "Clouds::render()", SPT_AVG);
 
 	int num_faces_to_draw = m_enable_3d ? 6 : 1;
 

src/client/game.cpp

@@ -689,8 +689,8 @@ protected:
 	bool handleCallbacks();
 	void processQueues();
 	void updateProfilers(const RunStats &stats, const FpsControl &draw_times, f32 dtime);
-	void addProfilerGraphs(const RunStats &stats, const FpsControl &draw_times, f32 dtime);
 	void updateStats(RunStats *stats, const FpsControl &draw_times, f32 dtime);
+	void updateProfilerGraphs(ProfilerGraph *graph);
 
 	// Input related
 	void processUserInput(f32 dtime);
@@ -751,7 +751,6 @@ protected:
 			const ItemStack &selected_item, const ItemStack &hand_item, f32 dtime);
 	void updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 			const CameraOrientation &cam);
-	void updateProfilerGraphs(ProfilerGraph *graph);
 
 	// Misc
 	void limitFps(FpsControl *fps_timings, f32 *dtime);
@@ -1082,10 +1081,12 @@ void Game::run()
 			previous_screen_size = current_screen_size;
 		}
 
-		/* Must be called immediately after a device->run() call because it
-		 * uses device->getTimer()->getTime()
-		 */
+		// Calculate dtime =
+		//    RenderingEngine::run() from this iteration
+		//  + Sleep time until the wanted FPS are reached
 		limitFps(&draw_times, &dtime);
+		
+		// Prepare render data for next iteration
 
 		updateStats(&stats, draw_times, dtime);
 		updateInteractTimers(dtime);
@@ -1722,7 +1723,8 @@ void Game::processQueues()
 }
 
 
-void Game::updateProfilers(const RunStats &stats, const FpsControl &draw_times, f32 dtime)
+void Game::updateProfilers(const RunStats &stats, const FpsControl &draw_times,
+		f32 dtime)
 {
 	float profiler_print_interval =
 			g_settings->getFloat("profiler_print_interval");
@@ -1730,7 +1732,7 @@ void Game::updateProfilers(const RunStats &stats, const FpsControl &draw_times,
 
 	if (profiler_print_interval == 0) {
 		print_to_log = false;
-		profiler_print_interval = 5;
+		profiler_print_interval = 3;
 	}
 
 	if (profiler_interval.step(dtime, profiler_print_interval)) {
@@ -1743,25 +1745,14 @@ void Game::updateProfilers(const RunStats &stats, const FpsControl &draw_times,
 		g_profiler->clear();
 	}
 
-	addProfilerGraphs(stats, draw_times, dtime);
-}
-
+	// Update update graphs
+	g_profiler->graphAdd("Time non-rendering [ms]",
+		draw_times.busy_time - stats.drawtime);
 
-void Game::addProfilerGraphs(const RunStats &stats,
-		const FpsControl &draw_times, f32 dtime)
-{
-	g_profiler->graphAdd("mainloop_other",
-			draw_times.busy_time / 1000.0f - stats.drawtime / 1000.0f);
-
-	if (draw_times.sleep_time != 0)
-		g_profiler->graphAdd("mainloop_sleep", draw_times.sleep_time / 1000.0f);
-	g_profiler->graphAdd("mainloop_dtime", dtime);
-
-	g_profiler->add("Elapsed time", dtime);
-	g_profiler->avg("FPS", 1. / dtime);
+	g_profiler->graphAdd("Sleep [ms]", draw_times.sleep_time);
+	g_profiler->graphAdd("FPS", 1.0f / dtime);
 }
 
-
 void Game::updateStats(RunStats *stats, const FpsControl &draw_times,
 		f32 dtime)
 {
@@ -3612,6 +3603,7 @@ void Game::handleDigging(const PointedThing &pointed, const v3s16 &nodepos,
 void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 		const CameraOrientation &cam)
 {
+	TimeTaker tt_update("Game::updateFrame()");
 	LocalPlayer *player = client->getEnv().getLocalPlayer();
 
 	/*
@@ -3636,7 +3628,6 @@ void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 		direct_brightness = time_brightness;
 		sunlight_seen = true;
 	} else {
-		ScopeProfiler sp(g_profiler, "Detecting background light", SPT_AVG);
 		float old_brightness = sky->getBrightness();
 		direct_brightness = client->getEnv().getClientMap()
 				.getBackgroundBrightness(MYMIN(runData.fog_range * 1.2, 60 * BS),
@@ -3810,7 +3801,7 @@ void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 	*/
 	const video::SColor &skycolor = sky->getSkyColor();
 
-	TimeTaker tt_draw("mainloop: draw");
+	TimeTaker tt_draw("Draw scene");
 	driver->beginScene(true, true, skycolor);
 
 	bool draw_wield_tool = (m_game_ui->m_flags.show_hud &&
@@ -3870,7 +3861,8 @@ void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
 	driver->endScene();
 
 	stats->drawtime = tt_draw.stop(true);
-	g_profiler->graphAdd("mainloop_draw", stats->drawtime / 1000.0f);
+	g_profiler->avg("Game::updateFrame(): draw scene [ms]", stats->drawtime);
+	g_profiler->graphAdd("Update frame [ms]", tt_update.stop(true));
 }
 
 /* Log times and stuff for visualization */

src/client/gameui.cpp

@@ -80,9 +80,10 @@ void GameUI::init()
 	// Profiler text (size is updated when text is updated)
 	m_guitext_profiler = gui::StaticText::add(guienv, L"<Profiler>",
 		core::rect<s32>(0, 0, 0, 0), false, false, guiroot);
+	m_guitext_profiler->setOverrideFont(g_fontengine->getFont(
+		g_fontengine->getDefaultFontSize() * 0.9f, FM_Mono));
 	m_guitext_profiler->setBackgroundColor(video::SColor(120, 0, 0, 0));
 	m_guitext_profiler->setVisible(false);
-	m_guitext_profiler->setWordWrap(true);
 }
 
 void GameUI::update(const RunStats &stats, Client *client, MapDrawControl *draw_control,
@@ -239,29 +240,21 @@ void GameUI::updateProfiler()
 {
 	if (m_profiler_current_page != 0) {
 		std::ostringstream os(std::ios_base::binary);
-		g_profiler->printPage(os, m_profiler_current_page, m_profiler_max_page);
+		os << "   Profiler page " << (int)m_profiler_current_page <<
+				", elapsed: " << g_profiler->getElapsedMs() << " ms)" << std::endl;
 
-		std::wstring text = translate_string(utf8_to_wide(os.str()));
-		setStaticText(m_guitext_profiler, text.c_str());
-
-		s32 w = g_fontengine->getTextWidth(text);
-
-		if (w < 400)
-			w = 400;
-
-		u32 text_height = g_fontengine->getTextHeight();
+		int lines = g_profiler->print(os, m_profiler_current_page, m_profiler_max_page);
+		++lines;
 
-		core::position2di upper_left, lower_right;
-
-		upper_left.X  = 6;
-		upper_left.Y  = (text_height + 5) * 2;
-		lower_right.X = 12 + w;
-		lower_right.Y = upper_left.Y + (text_height + 1) * MAX_PROFILER_TEXT_ROWS;
-
-		s32 screen_height = RenderingEngine::get_video_driver()->getScreenSize().Height;
+		std::wstring text = utf8_to_wide(os.str());
+		setStaticText(m_guitext_profiler, text.c_str());
 
-		if (lower_right.Y > screen_height * 2 / 3)
-			lower_right.Y = screen_height * 2 / 3;
+		core::dimension2d<u32> size = m_guitext_profiler->getOverrideFont()->
+				getDimension(text.c_str());
+		core::position2di upper_left(6, 50);
+		core::position2di lower_right = upper_left;
+		lower_right.X += size.Width + 10;
+		lower_right.Y += size.Height; 
 
 		m_guitext_profiler->setRelativePosition(core::rect<s32>(upper_left, lower_right));
 	}

src/client/mapblock_mesh.cpp

@@ -942,10 +942,7 @@ static void updateFastFaceRow(
 
 				makeFastFace(tile, lights[0], lights[1], lights[2], lights[3],
 						pf, sp, face_dir_corrected, scale, dest);
-
-				g_profiler->avg("Meshgen: faces drawn by tiling", 0);
-				for (int i = 1; i < continuous_tiles_count; i++)
-					g_profiler->avg("Meshgen: faces drawn by tiling", 1);
+				g_profiler->avg("Meshgen: Tiles per face [#]", continuous_tiles_count);
 			}
 
 			continuous_tiles_count = 1;

src/client/mesh_generator_thread.cpp

@@ -98,7 +98,7 @@ void MeshUpdateQueue::addBlock(Map *map, v3s16 p, bool ack_block_to_server, bool
 					&cache_hit_counter);
 		cached_blocks.push_back(cached_block);
 	}
-	g_profiler->avg("MeshUpdateQueue MapBlock cache hit %",
+	g_profiler->avg("MeshUpdateQueue: MapBlocks from cache [%]",
 			100.0f * cache_hit_counter / cached_blocks.size());
 
 	/*
@@ -162,39 +162,36 @@ QueuedMeshUpdate *MeshUpdateQueue::pop()
 CachedMapBlockData* MeshUpdateQueue::cacheBlock(Map *map, v3s16 p, UpdateMode mode,
 			size_t *cache_hit_counter)
 {
+	CachedMapBlockData *cached_block = nullptr;
 	std::map<v3s16, CachedMapBlockData*>::iterator it =
 			m_cache.find(p);
+
 	if (it != m_cache.end()) {
-		// Already in cache
-		CachedMapBlockData *cached_block = it->second;
+		cached_block = it->second;
+
 		if (mode == SKIP_UPDATE_IF_ALREADY_CACHED) {
 			if (cache_hit_counter)
 				(*cache_hit_counter)++;
 			return cached_block;
 		}
-		MapBlock *b = map->getBlockNoCreateNoEx(p);
-		if (b) {
-			if (cached_block->data == NULL)
-				cached_block->data =
-						new MapNode[MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE];
-			memcpy(cached_block->data, b->getData(),
-					MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE * sizeof(MapNode));
-		} else {
-			delete[] cached_block->data;
-			cached_block->data = NULL;
-		}
-		return cached_block;
 	}
 
-	// Not yet in cache
-	CachedMapBlockData *cached_block = new CachedMapBlockData();
-	m_cache[p] = cached_block;
+	if (!cached_block) {
+		// Not yet in cache
+		cached_block = new CachedMapBlockData();
+		m_cache[p] = cached_block;
+	}
+
 	MapBlock *b = map->getBlockNoCreateNoEx(p);
 	if (b) {
-		cached_block->data =
-				new MapNode[MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE];
+		if (!cached_block->data)
+			cached_block->data =
+					new MapNode[MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE];
 		memcpy(cached_block->data, b->getData(),
 				MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE * sizeof(MapNode));
+	} else {
+		delete[] cached_block->data;
+		cached_block->data = nullptr;
 	}
 	return cached_block;
 }
@@ -292,7 +289,7 @@ void MeshUpdateThread::doUpdate()
 	while ((q = m_queue_in.pop())) {
 		if (m_generation_interval)
 			sleep_ms(m_generation_interval);
-		ScopeProfiler sp(g_profiler, "Client: Mesh making");
+		ScopeProfiler sp(g_profiler, "Client: Mesh making (sum)");
 
 		MapBlockMesh *mesh_new = new MapBlockMesh(q->data, m_camera_offset);
 

src/collision.cpp

@@ -220,8 +220,8 @@ collisionMoveResult collisionMoveSimple(Environment *env, IGameDef *gamedef,
 {
 	static bool time_notification_done = false;
 	Map *map = &env->getMap();
-	//TimeTaker tt("collisionMoveSimple");
-	ScopeProfiler sp(g_profiler, "collisionMoveSimple avg", SPT_AVG);
+
+	ScopeProfiler sp(g_profiler, "collisionMoveSimple()", SPT_AVG);
 
 	collisionMoveResult result;
 
@@ -255,7 +255,7 @@ collisionMoveResult collisionMoveSimple(Environment *env, IGameDef *gamedef,
 	std::vector<NearbyCollisionInfo> cinfo;
 	{
 	//TimeTaker tt2("collisionMoveSimple collect boxes");
-	ScopeProfiler sp2(g_profiler, "collisionMoveSimple collect boxes avg", SPT_AVG);
+	ScopeProfiler sp2(g_profiler, "collisionMoveSimple(): collect boxes", SPT_AVG);
 
 	v3f newpos_f = *pos_f + *speed_f * dtime;
 	v3f minpos_f(
@@ -351,9 +351,6 @@ collisionMoveResult collisionMoveSimple(Environment *env, IGameDef *gamedef,
 
 	if(collideWithObjects)
 	{
-		ScopeProfiler sp2(g_profiler, "collisionMoveSimple objects avg", SPT_AVG);
-		//TimeTaker tt3("collisionMoveSimple collect object boxes");
-
 		/* add object boxes to cinfo */
 
 		std::vector<ActiveObject*> objects;
@@ -428,9 +425,6 @@ collisionMoveResult collisionMoveSimple(Environment *env, IGameDef *gamedef,
 	int loopcount = 0;
 
 	while(dtime > BS * 1e-10f) {
-		//TimeTaker tt3("collisionMoveSimple dtime loop");
-        	ScopeProfiler sp2(g_profiler, "collisionMoveSimple dtime loop avg", SPT_AVG);
-
 		// Avoid infinite loop
 		loopcount++;
 		if (loopcount >= 100) {

src/emerge.cpp

@@ -637,12 +637,8 @@ void *EmergeThread::run()
 			{
 				ScopeProfiler sp(g_profiler,
 					"EmergeThread: Mapgen::makeChunk", SPT_AVG);
-				TimeTaker t("mapgen::make_block()");
 
 				m_mapgen->makeChunk(&bmdata);
-
-				if (!enable_mapgen_debug_info)
-					t.stop(true); // Hide output
 			}
 
 			block = finishGen(pos, &bmdata, &modified_blocks);

src/mapgen/mapgen.cpp

@@ -422,7 +422,7 @@ void Mapgen::updateLiquid(UniqueQueue<v3s16> *trans_liquid, v3s16 nmin, v3s16 nm
 
 void Mapgen::setLighting(u8 light, v3s16 nmin, v3s16 nmax)
 {
-	ScopeProfiler sp(g_profiler, "EmergeThread: mapgen lighting update", SPT_AVG);
+	ScopeProfiler sp(g_profiler, "EmergeThread: update lighting", SPT_AVG);
 	VoxelArea a(nmin, nmax);
 
 	for (int z = a.MinEdge.Z; z <= a.MaxEdge.Z; z++) {
@@ -479,7 +479,7 @@ void Mapgen::lightSpread(VoxelArea &a, v3s16 p, u8 light)
 void Mapgen::calcLighting(v3s16 nmin, v3s16 nmax, v3s16 full_nmin, v3s16 full_nmax,
 	bool propagate_shadow)
 {
-	ScopeProfiler sp(g_profiler, "EmergeThread: mapgen lighting update", SPT_AVG);
+	ScopeProfiler sp(g_profiler, "EmergeThread: update lighting", SPT_AVG);
 	//TimeTaker t("updateLighting");
 
 	propagateSunlight(nmin, nmax, propagate_shadow);

src/network/connection.cpp

@@ -849,8 +849,8 @@ void Peer::RTTStatistics(float rtt, const std::string &profiler_id,
 								jitter * (1/num_samples);
 
 		if (!profiler_id.empty()) {
-			g_profiler->graphAdd(profiler_id + "_rtt", rtt);
-			g_profiler->graphAdd(profiler_id + "_jitter", jitter);
+			g_profiler->graphAdd(profiler_id + " RTT [ms]", rtt * 1000.f);
+			g_profiler->graphAdd(profiler_id + " jitter [ms]", jitter * 1000.f);
 		}
 	}
 	/* save values required for next loop */

src/profiler.cpp

@@ -18,6 +18,7 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 */
 
 #include "profiler.h"
+#include "porting.h"
 
 static Profiler main_profiler;
 Profiler *g_profiler = &main_profiler;
@@ -26,8 +27,9 @@ ScopeProfiler::ScopeProfiler(
 		m_profiler(profiler),
 		m_name(name), m_type(type)
 {
+	m_name.append(" [ms]");
 	if (m_profiler)
-		m_timer = new TimeTaker(m_name);
+		m_timer = new TimeTaker(m_name, nullptr, PRECISION_MILLI);
 }
 
 ScopeProfiler::~ScopeProfiler()
@@ -52,3 +54,129 @@ ScopeProfiler::~ScopeProfiler()
 	}
 	delete m_timer;
 }
+
+Profiler::Profiler()
+{
+	m_start_time = porting::getTimeMs();
+}
+
+void Profiler::add(const std::string &name, float value)
+{
+	MutexAutoLock lock(m_mutex);
+	{
+		/* No average shall have been used; mark add used as -2 */
+		std::map<std::string, int>::iterator n = m_avgcounts.find(name);
+		if (n == m_avgcounts.end()) {
+			m_avgcounts[name] = -2;
+		} else {
+			if (n->second == -1)
+				n->second = -2;
+			assert(n->second == -2);
+		}
+	}
+	{
+		std::map<std::string, float>::iterator n = m_data.find(name);
+		if (n == m_data.end())
+			m_data[name] = value;
+		else
+			n->second += value;
+	}
+}
+
+void Profiler::avg(const std::string &name, float value)
+{
+	MutexAutoLock lock(m_mutex);
+	int &count = m_avgcounts[name];
+
+	assert(count != -2);
+	count = MYMAX(count, 0) + 1;
+	m_data[name] += value;
+}
+
+void Profiler::clear()
+{
+	MutexAutoLock lock(m_mutex);
+	for (auto &it : m_data) {
+		it.second = 0;
+	}
+	m_avgcounts.clear();
+	m_start_time = porting::getTimeMs();
+}
+
+float Profiler::getValue(const std::string &name) const
+{
+	auto numerator = m_data.find(name);
+	if (numerator == m_data.end())
+		return 0.f;
+
+	auto denominator = m_avgcounts.find(name);
+	if (denominator != m_avgcounts.end()) {
+		if (denominator->second >= 1)
+			return numerator->second / denominator->second;
+	}
+
+	return numerator->second;
+}
+
+int Profiler::getAvgCount(const std::string &name) const
+{
+	auto n = m_avgcounts.find(name);
+
+	if (n != m_avgcounts.end() && n->second >= 1)
+		return n->second;
+
+	return 1;
+}
+
+u64 Profiler::getElapsedMs() const
+{
+	return porting::getTimeMs() - m_start_time;
+}
+
+int Profiler::print(std::ostream &o, u32 page, u32 pagecount)
+{
+	GraphValues values;
+	getPage(values, page, pagecount);
+	char num_buf[50];
+
+	for (const auto &i : values) {
+		o << "  " << i.first << " ";
+		if (i.second == 0) {
+			o << std::endl;
+			continue;
+		}
+
+		s32 space = 44 - i.first.size();
+		for (s32 j = 0; j < space; j++) {
+			if ((j & 1) && j < space - 1)
+				o << ".";
+			else
+				o << " ";
+		}
+		porting::mt_snprintf(num_buf, sizeof(num_buf), "% 4ix % 3g",
+				getAvgCount(i.first), i.second);
+		o << num_buf << std::endl;
+	}
+	return values.size();
+}
+
+void Profiler::getPage(GraphValues &o, u32 page, u32 pagecount)
+{
+	MutexAutoLock lock(m_mutex);
+
+	u32 minindex, maxindex;
+	paging(m_data.size(), page, pagecount, minindex, maxindex);
+
+	for (const auto &i : m_data) {
+		if (maxindex == 0)
+			break;
+		maxindex--;
+
+		if (minindex != 0) {
+			minindex--;
+			continue;
+		}
+
+		o[i.first] = i.second / getAvgCount(i.first);
+	}
+}

src/profiler.h

@@ -29,8 +29,6 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 #include "util/timetaker.h"
 #include "util/numeric.h"      // paging()
 
-#define MAX_PROFILER_TEXT_ROWS 20
-
 // Global profiler
 class Profiler;
 extern Profiler *g_profiler;
@@ -42,109 +40,22 @@ extern Profiler *g_profiler;
 class Profiler
 {
 public:
-	Profiler() = default;
+	Profiler();
 
-	void add(const std::string &name, float value)
-	{
-		MutexAutoLock lock(m_mutex);
-		{
-			/* No average shall have been used; mark add used as -2 */
-			std::map<std::string, int>::iterator n = m_avgcounts.find(name);
-			if(n == m_avgcounts.end())
-				m_avgcounts[name] = -2;
-			else{
-				if(n->second == -1)
-					n->second = -2;
-				assert(n->second == -2);
-			}
-		}
-		{
-			std::map<std::string, float>::iterator n = m_data.find(name);
-			if(n == m_data.end())
-				m_data[name] = value;
-			else
-				n->second += value;
-		}
-	}
+	void add(const std::string &name, float value);
+	void avg(const std::string &name, float value);
+	void clear();
 
-	void avg(const std::string &name, float value)
-	{
-		MutexAutoLock lock(m_mutex);
-		int &count = m_avgcounts[name];
+	float getValue(const std::string &name) const;
+	int getAvgCount(const std::string &name) const;
+	u64 getElapsedMs() const;
 
-		assert(count != -2);
-		count = MYMAX(count, 0) + 1;
-		m_data[name] += value;
-	}
-
-	void clear()
-	{
-		MutexAutoLock lock(m_mutex);
-		for (auto &it : m_data) {
-			it.second = 0;
-		}
-		m_avgcounts.clear();
-	}
-
-	void print(std::ostream &o)
-	{
-		printPage(o, 1, 1);
-	}
-
-	float getValue(const std::string &name) const
-	{
-		std::map<std::string, float>::const_iterator numerator = m_data.find(name);
-		if (numerator == m_data.end())
-			return 0.f;
-
-		std::map<std::string, int>::const_iterator denominator = m_avgcounts.find(name);
-		if (denominator != m_avgcounts.end()){
-			if (denominator->second >= 1)
-				return numerator->second / denominator->second;
-		}
-
-		return numerator->second;
-	}
-
-	void printPage(std::ostream &o, u32 page, u32 pagecount)
-	{
-		MutexAutoLock lock(m_mutex);
+	typedef std::map<std::string, float> GraphValues;
 
-		u32 minindex, maxindex;
-		paging(m_data.size(), page, pagecount, minindex, maxindex);
-
-		for (std::map<std::string, float>::const_iterator i = m_data.begin();
-				i != m_data.end(); ++i) {
-			if (maxindex == 0)
-				break;
-			maxindex--;
-
-			if (minindex != 0) {
-				minindex--;
-				continue;
-			}
-
-			int avgcount = 1;
-			std::map<std::string, int>::const_iterator n = m_avgcounts.find(i->first);
-			if (n != m_avgcounts.end()) {
-				if(n->second >= 1)
-					avgcount = n->second;
-			}
-			o << "  " << i->first << ": ";
-			s32 clampsize = 40;
-			s32 space = clampsize - i->first.size();
-			for(s32 j = 0; j < space; j++) {
-				if (j % 2 == 0 && j < space - 1)
-					o << "-";
-				else
-					o << " ";
-			}
-			o << (i->second / avgcount);
-			o << std::endl;
-		}
-	}
+	// Returns the line count
+	int print(std::ostream &o, u32 page = 1, u32 pagecount = 1);
+	void getPage(GraphValues &o, u32 page, u32 pagecount);
 
-	typedef std::map<std::string, float> GraphValues;
 
 	void graphAdd(const std::string &id, float value)
 	{
@@ -175,6 +86,7 @@ private:
 	std::map<std::string, float> m_data;
 	std::map<std::string, int> m_avgcounts;
 	std::map<std::string, float> m_graphvalues;
+	u64 m_start_time;
 };
 
 enum ScopeProfilerType{

src/server.cpp

@@ -470,7 +470,6 @@ void Server::step(float dtime)
 
 void Server::AsyncRunStep(bool initial_step)
 {
-	g_profiler->add("Server::AsyncRunStep (num)", 1);
 
 	float dtime;
 	{
@@ -486,10 +485,7 @@ void Server::AsyncRunStep(bool initial_step)
 	if((dtime < 0.001) && !initial_step)
 		return;
 
-	g_profiler->add("Server::AsyncRunStep with dtime (num)", 1);
-
-	//infostream<<"Server steps "<<dtime<<std::endl;
-	//infostream<<"Server::AsyncRunStep(): dtime="<<dtime<<std::endl;
+	ScopeProfiler sp(g_profiler, "Server::AsyncRunStep()", SPT_AVG);
 
 	{
 		MutexAutoLock lock1(m_step_dtime_mutex);
@@ -535,8 +531,6 @@ void Server::AsyncRunStep(bool initial_step)
 		}
 		m_env->reportMaxLagEstimate(max_lag);
 		// Step environment
-		ScopeProfiler sp(g_profiler, "SEnv step");
-		ScopeProfiler sp2(g_profiler, "SEnv step avg", SPT_AVG);
 		m_env->step(dtime);
 	}
 
@@ -626,7 +620,7 @@ void Server::AsyncRunStep(bool initial_step)
 
 		m_clients.lock();
 		const RemoteClientMap &clients = m_clients.getClientList();
-		ScopeProfiler sp(g_profiler, "Server: checking added and deleted objs");
+		ScopeProfiler sp(g_profiler, "Server: update visible objects");
 
 		// Radius inside which objects are active
 		static thread_local const s16 radius =
@@ -762,7 +756,7 @@ void Server::AsyncRunStep(bool initial_step)
 	*/
 	{
 		MutexAutoLock envlock(m_env_mutex);
-		ScopeProfiler sp(g_profiler, "Server: sending object messages");
+		ScopeProfiler sp(g_profiler, "Server: send SAO messages");
 
 		// Key = object id
 		// Value = data sent by object
@@ -972,7 +966,7 @@ void Server::AsyncRunStep(bool initial_step)
 			counter = 0.0;
 			MutexAutoLock lock(m_env_mutex);
 
-			ScopeProfiler sp(g_profiler, "Server: saving stuff");
+			ScopeProfiler sp(g_profiler, "Server: map saving (sum)");
 
 			// Save ban file
 			if (m_banmanager->isModified()) {
@@ -1106,7 +1100,7 @@ void Server::ProcessData(NetworkPacket *pkt)
 	// Environment is locked first.
 	MutexAutoLock envlock(m_env_mutex);
 
-	ScopeProfiler sp(g_profiler, "Server::ProcessData");
+	ScopeProfiler sp(g_profiler, "Server: Process network packet (sum)");
 	u32 peer_id = pkt->getPeerId();
 
 	try {
@@ -2258,14 +2252,12 @@ void Server::SendBlocks(float dtime)
 	MutexAutoLock envlock(m_env_mutex);
 	//TODO check if one big lock could be faster then multiple small ones
 
-	ScopeProfiler sp(g_profiler, "Server: sel and send blocks to clients");
-
 	std::vector<PrioritySortedBlockTransfer> queue;
 
 	u32 total_sending = 0;
 
 	{
-		ScopeProfiler sp2(g_profiler, "Server: selecting blocks for sending");
+		ScopeProfiler sp2(g_profiler, "Server::SendBlocks(): Collect list");
 
 		std::vector<session_t> clients = m_clients.getClientIDs();
 
@@ -2294,6 +2286,7 @@ void Server::SendBlocks(float dtime)
 	u32 max_blocks_to_send = (m_env->getPlayerCount() + g_settings->getU32("max_users")) *
 		g_settings->getU32("max_simultaneous_block_sends_per_client") / 4 + 1;
 
+	ScopeProfiler sp(g_profiler, "Server::SendBlocks(): Send to clients");
 	for (const PrioritySortedBlockTransfer &block_to_send : queue) {
 		if (total_sending >= max_blocks_to_send)
 			break;
@@ -3697,10 +3690,7 @@ void dedicated_server_loop(Server &server, bool &kill)
 	for(;;) {
 		// This is kind of a hack but can be done like this
 		// because server.step() is very light
-		{
-			ScopeProfiler sp(g_profiler, "dedicated server sleep");
-			sleep_ms((int)(steplen*1000.0));
-		}
+		sleep_ms((int)(steplen*1000.0));
 		server.step(steplen);
 
 		if (server.isShutdownRequested() || kill)

src/server/activeobjectmgr.cpp

@@ -44,8 +44,7 @@ void ActiveObjectMgr::clear(const std::function<bool(ServerActiveObject *, u16)>
 void ActiveObjectMgr::step(
 		float dtime, const std::function<void(ServerActiveObject *)> &f)
 {
-	g_profiler->avg("Server::ActiveObjectMgr: num of objects",
-			m_active_objects.size());
+	g_profiler->avg("ActiveObjectMgr: SAO count [#]", m_active_objects.size());
 	for (auto &ao_it : m_active_objects) {
 		f(ao_it.second);
 	}

src/serverenvironment.cpp

@@ -1200,6 +1200,7 @@ void ServerEnvironment::clearObjects(ClearObjectsMode mode)
 
 void ServerEnvironment::step(float dtime)
 {
+	ScopeProfiler sp2(g_profiler, "ServerEnv::step()", SPT_AVG);
 	/* Step time of day */
 	stepTimeOfDay(dtime);
 
@@ -1224,7 +1225,7 @@ void ServerEnvironment::step(float dtime)
 		Handle players
 	*/
 	{
-		ScopeProfiler sp(g_profiler, "SEnv: handle players avg", SPT_AVG);
+		ScopeProfiler sp(g_profiler, "ServerEnv: move players", SPT_AVG);
 		for (RemotePlayer *player : m_players) {
 			// Ignore disconnected players
 			if (player->getPeerId() == PEER_ID_INEXISTENT)
@@ -1239,7 +1240,7 @@ void ServerEnvironment::step(float dtime)
 		Manage active block list
 	*/
 	if (m_active_blocks_management_interval.step(dtime, m_cache_active_block_mgmt_interval)) {
-		ScopeProfiler sp(g_profiler, "SEnv: manage act. block list avg per interval", SPT_AVG);
+		ScopeProfiler sp(g_profiler, "ServerEnv: update active blocks", SPT_AVG);
 		/*
 			Get player block positions
 		*/
@@ -1305,7 +1306,7 @@ void ServerEnvironment::step(float dtime)
 		Mess around in active blocks
 	*/
 	if (m_active_blocks_nodemetadata_interval.step(dtime, m_cache_nodetimer_interval)) {
-		ScopeProfiler sp(g_profiler, "SEnv: mess in act. blocks avg per interval", SPT_AVG);
+		ScopeProfiler sp(g_profiler, "ServerEnv: Run node timers", SPT_AVG);
 
 		float dtime = m_cache_nodetimer_interval;
 
@@ -1385,10 +1386,10 @@ void ServerEnvironment::step(float dtime)
 				break;
 			}
 		}
-		g_profiler->avg("SEnv: active blocks", m_active_blocks.m_abm_list.size());
-		g_profiler->avg("SEnv: active blocks cached", blocks_cached);
-		g_profiler->avg("SEnv: active blocks scanned for ABMs", blocks_scanned);
-		g_profiler->avg("SEnv: ABMs run", abms_run);
+		g_profiler->avg("ServerEnv: active blocks", m_active_blocks.m_abm_list.size());
+		g_profiler->avg("ServerEnv: active blocks cached", blocks_cached);
+		g_profiler->avg("ServerEnv: active blocks scanned for ABMs", blocks_scanned);
+		g_profiler->avg("ServerEnv: ABMs run", abms_run);
 
 		timer.stop(true);
 	}
@@ -1402,7 +1403,7 @@ void ServerEnvironment::step(float dtime)
 		Step active objects
 	*/
 	{
-		ScopeProfiler sp(g_profiler, "SEnv: step act. objs avg", SPT_AVG);
+		ScopeProfiler sp(g_profiler, "ServerEnv: Run SAO::step()", SPT_AVG);
 
 		// This helps the objects to send data at the same time
 		bool send_recommended = false;
@@ -1431,7 +1432,6 @@ void ServerEnvironment::step(float dtime)
 		Manage active objects
 	*/
 	if (m_object_management_interval.step(dtime, 0.5)) {
-		ScopeProfiler sp(g_profiler, "SEnv: remove removed objs avg /.5s", SPT_AVG);
 		removeRemovedObjects();
 	}
 
@@ -1686,6 +1686,8 @@ u16 ServerEnvironment::addActiveObjectRaw(ServerActiveObject *object,
 */
 void ServerEnvironment::removeRemovedObjects()
 {
+	ScopeProfiler sp(g_profiler, "ServerEnvironment::removeRemovedObjects()", SPT_AVG);
+
 	auto clear_cb = [this] (ServerActiveObject *obj, u16 id) {
 		// This shouldn't happen but check it
 		if (!obj) {