From 539f016c1b1a706da2c113435ec60bb39c868f4b Mon Sep 17 00:00:00 2001 From: SmallJoker Date: Tue, 13 Aug 2019 19:56:55 +0200 Subject: 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 +++++------ 10 files changed, 86 insertions(+), 175 deletions(-) (limited to 'src/client') 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); -- cgit v1.2.3