From 539f016c1b1a706da2c113435ec60bb39c868f4b Mon Sep 17 00:00:00 2001 From: SmallJoker Date: Tue, 13 Aug 2019 19:56:55 +0200 Subject: [PATCH] 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 | 3 +- src/client/client.cpp | 1 - src/client/clientenvironment.cpp | 7 +- src/client/clientmap.cpp | 123 +++++++------------------ src/client/clientmap.h | 2 - src/client/clouds.cpp | 2 +- src/client/game.cpp | 44 ++++----- src/client/gameui.cpp | 35 +++----- src/client/mapblock_mesh.cpp | 5 +- src/client/mesh_generator_thread.cpp | 39 ++++---- src/collision.cpp | 12 +-- src/emerge.cpp | 4 - src/mapgen/mapgen.cpp | 4 +- src/network/connection.cpp | 4 +- src/profiler.cpp | 130 ++++++++++++++++++++++++++- src/profiler.h | 112 +++-------------------- src/server.cpp | 26 ++---- src/server/activeobjectmgr.cpp | 3 +- src/serverenvironment.cpp | 20 +++-- 19 files changed, 254 insertions(+), 322 deletions(-) diff --git a/src/client/activeobjectmgr.cpp b/src/client/activeobjectmgr.cpp index 9fd8490f2..05ded3d8c 100644 --- a/src/client/activeobjectmgr.cpp +++ b/src/client/activeobjectmgr.cpp @@ -35,8 +35,7 @@ void ActiveObjectMgr::clear() void ActiveObjectMgr::step( float dtime, const std::function &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); } diff --git a/src/client/client.cpp b/src/client/client.cpp index aeae0eaa0..e78b9bb8a 100644 --- a/src/client/client.cpp +++ b/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 deleted_blocks; m_env.getMap().timerUpdate(map_timer_and_unload_dtime, g_settings->getFloat("client_unload_unused_data_timeout"), diff --git a/src/client/clientenvironment.cpp b/src/client/clientenvironment.cpp index 9d92e51a6..e1b20ec84 100644 --- a/src/client/clientenvironment.cpp +++ b/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; diff --git a/src/client/clientmap.cpp b/src/client/clientmap.cpp index 70fb34767..8a182b14a 100644 --- a/src/client/clientmap.cpp +++ b/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) }; diff --git a/src/client/clientmap.h b/src/client/clientmap.h index 8402bb00d..172e3a1d6 100644 --- a/src/client/clientmap.h +++ b/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; }; diff --git a/src/client/clouds.cpp b/src/client/clouds.cpp index 13051f32c..887a62f25 100644 --- a/src/client/clouds.cpp +++ b/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; diff --git a/src/client/game.cpp b/src/client/game.cpp index f12570720..841357810 100644 --- a/src/client/game.cpp +++ b/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 */ diff --git a/src/client/gameui.cpp b/src/client/gameui.cpp index 6eb8bfd34..674d07fa6 100644 --- a/src/client/gameui.cpp +++ b/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"", core::rect(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 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(upper_left, lower_right)); } diff --git a/src/client/mapblock_mesh.cpp b/src/client/mapblock_mesh.cpp index 6b5ba9f9d..2bfaa7a4f 100644 --- a/src/client/mapblock_mesh.cpp +++ b/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; diff --git a/src/client/mesh_generator_thread.cpp b/src/client/mesh_generator_thread.cpp index be4bcc1f4..53b980eeb 100644 --- a/src/client/mesh_generator_thread.cpp +++ b/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::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); diff --git a/src/collision.cpp b/src/collision.cpp index e911e6f8c..a443be7ab 100644 --- a/src/collision.cpp +++ b/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 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 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) { diff --git a/src/emerge.cpp b/src/emerge.cpp index 510e7590f..fc1da4ee7 100644 --- a/src/emerge.cpp +++ b/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); diff --git a/src/mapgen/mapgen.cpp b/src/mapgen/mapgen.cpp index 2a6bcf347..29131d56e 100644 --- a/src/mapgen/mapgen.cpp +++ b/src/mapgen/mapgen.cpp @@ -422,7 +422,7 @@ void Mapgen::updateLiquid(UniqueQueue *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); diff --git a/src/network/connection.cpp b/src/network/connection.cpp index 9fb43179d..913088da7 100644 --- a/src/network/connection.cpp +++ b/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 */ diff --git a/src/profiler.cpp b/src/profiler.cpp index f8d4fc181..be8be591e 100644 --- a/src/profiler.cpp +++ b/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::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::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); + } +} diff --git a/src/profiler.h b/src/profiler.h index 6704afd51..b4a0657f9 100644 --- a/src/profiler.h +++ b/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::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::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::const_iterator numerator = m_data.find(name); - if (numerator == m_data.end()) - return 0.f; - - std::map::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 GraphValues; - u32 minindex, maxindex; - paging(m_data.size(), page, pagecount, minindex, maxindex); - - for (std::map::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::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 GraphValues; void graphAdd(const std::string &id, float value) { @@ -175,6 +86,7 @@ private: std::map m_data; std::map m_avgcounts; std::map m_graphvalues; + u64 m_start_time; }; enum ScopeProfilerType{ diff --git a/src/server.cpp b/src/server.cpp index 4aa926917..386817c8f 100644 --- a/src/server.cpp +++ b/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 "<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 queue; u32 total_sending = 0; { - ScopeProfiler sp2(g_profiler, "Server: selecting blocks for sending"); + ScopeProfiler sp2(g_profiler, "Server::SendBlocks(): Collect list"); std::vector 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) diff --git a/src/server/activeobjectmgr.cpp b/src/server/activeobjectmgr.cpp index 01d9d5ae8..984ae7794 100644 --- a/src/server/activeobjectmgr.cpp +++ b/src/server/activeobjectmgr.cpp @@ -44,8 +44,7 @@ void ActiveObjectMgr::clear(const std::function void ActiveObjectMgr::step( float dtime, const std::function &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); } diff --git a/src/serverenvironment.cpp b/src/serverenvironment.cpp index 32f656f32..1af3cf6d7 100644 --- a/src/serverenvironment.cpp +++ b/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) { -- 2.25.1