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); + + g_profiler->graphAdd("Sleep [ms]", draw_times.sleep_time); + g_profiler->graphAdd("FPS", 1.0f / dtime); } - -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); -} - - 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())); + int lines = g_profiler->print(os, m_profiler_current_page, m_profiler_max_page); + ++lines; + + std::wstring text = 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(); - - 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; - - 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,110 +40,23 @@ 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]; - - 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); - - 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; - } - } + float getValue(const std::string &name) const; + int getAvgCount(const std::string &name) const; + u64 getElapsedMs() const; typedef std::map GraphValues; + // Returns the line count + int print(std::ostream &o, u32 page = 1, u32 pagecount = 1); + void getPage(GraphValues &o, u32 page, u32 pagecount); + + void graphAdd(const std::string &id, float value) { MutexAutoLock lock(m_mutex); @@ -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) {