void ActiveObjectMgr::step(
float dtime, const std::function<void(ClientActiveObject *)> &f)
{
- g_profiler->avg("Client::ActiveObjectMgr: num of objects",
- m_active_objects.size());
+ g_profiler->avg("ActiveObjectMgr: CAO count [#]", m_active_objects.size());
for (auto &ao_it : m_active_objects) {
f(ao_it.second);
}
*/
const float map_timer_and_unload_dtime = 5.25;
if(m_map_timer_and_unload_interval.step(dtime, map_timer_and_unload_dtime)) {
- ScopeProfiler sp(g_profiler, "Client: map timer and unload");
std::vector<v3s16> deleted_blocks;
m_env.getMap().timerUpdate(map_timer_and_unload_dtime,
g_settings->getFloat("client_unload_unused_data_timeout"),
/*
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;
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;
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
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);
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;
}
// 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
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
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
*/
*/
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) {
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();
}
}
}
+ 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,
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)
};
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;
};
//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;
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);
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);
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);
}
-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");
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)) {
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)
{
void Game::updateFrame(ProfilerGraph *graph, RunStats *stats, f32 dtime,
const CameraOrientation &cam)
{
+ TimeTaker tt_update("Game::updateFrame()");
LocalPlayer *player = client->getEnv().getLocalPlayer();
/*
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),
*/
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 &&
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 */
// Profiler text (size is updated when text is updated)
m_guitext_profiler = gui::StaticText::add(guienv, L"<Profiler>",
core::rect<s32>(0, 0, 0, 0), false, false, guiroot);
+ m_guitext_profiler->setOverrideFont(g_fontengine->getFont(
+ g_fontengine->getDefaultFontSize() * 0.9f, FM_Mono));
m_guitext_profiler->setBackgroundColor(video::SColor(120, 0, 0, 0));
m_guitext_profiler->setVisible(false);
- m_guitext_profiler->setWordWrap(true);
}
void GameUI::update(const RunStats &stats, Client *client, MapDrawControl *draw_control,
{
if (m_profiler_current_page != 0) {
std::ostringstream os(std::ios_base::binary);
- g_profiler->printPage(os, m_profiler_current_page, m_profiler_max_page);
+ os << " Profiler page " << (int)m_profiler_current_page <<
+ ", elapsed: " << g_profiler->getElapsedMs() << " ms)" << std::endl;
- std::wstring text = translate_string(utf8_to_wide(os.str()));
- setStaticText(m_guitext_profiler, text.c_str());
-
- s32 w = g_fontengine->getTextWidth(text);
-
- if (w < 400)
- w = 400;
-
- u32 text_height = g_fontengine->getTextHeight();
+ int lines = g_profiler->print(os, m_profiler_current_page, m_profiler_max_page);
+ ++lines;
- core::position2di upper_left, lower_right;
-
- upper_left.X = 6;
- upper_left.Y = (text_height + 5) * 2;
- lower_right.X = 12 + w;
- lower_right.Y = upper_left.Y + (text_height + 1) * MAX_PROFILER_TEXT_ROWS;
-
- s32 screen_height = RenderingEngine::get_video_driver()->getScreenSize().Height;
+ std::wstring text = utf8_to_wide(os.str());
+ setStaticText(m_guitext_profiler, text.c_str());
- if (lower_right.Y > screen_height * 2 / 3)
- lower_right.Y = screen_height * 2 / 3;
+ core::dimension2d<u32> size = m_guitext_profiler->getOverrideFont()->
+ getDimension(text.c_str());
+ core::position2di upper_left(6, 50);
+ core::position2di lower_right = upper_left;
+ lower_right.X += size.Width + 10;
+ lower_right.Y += size.Height;
m_guitext_profiler->setRelativePosition(core::rect<s32>(upper_left, lower_right));
}
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;
&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());
/*
CachedMapBlockData* MeshUpdateQueue::cacheBlock(Map *map, v3s16 p, UpdateMode mode,
size_t *cache_hit_counter)
{
+ CachedMapBlockData *cached_block = nullptr;
std::map<v3s16, CachedMapBlockData*>::iterator it =
m_cache.find(p);
+
if (it != m_cache.end()) {
- // Already in cache
- CachedMapBlockData *cached_block = it->second;
+ cached_block = it->second;
+
if (mode == SKIP_UPDATE_IF_ALREADY_CACHED) {
if (cache_hit_counter)
(*cache_hit_counter)++;
return cached_block;
}
- MapBlock *b = map->getBlockNoCreateNoEx(p);
- if (b) {
- if (cached_block->data == NULL)
- cached_block->data =
- new MapNode[MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE];
- memcpy(cached_block->data, b->getData(),
- MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE * sizeof(MapNode));
- } else {
- delete[] cached_block->data;
- cached_block->data = NULL;
- }
- return cached_block;
}
- // Not yet in cache
- CachedMapBlockData *cached_block = new CachedMapBlockData();
- m_cache[p] = cached_block;
+ if (!cached_block) {
+ // Not yet in cache
+ cached_block = new CachedMapBlockData();
+ m_cache[p] = cached_block;
+ }
+
MapBlock *b = map->getBlockNoCreateNoEx(p);
if (b) {
- cached_block->data =
- new MapNode[MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE];
+ if (!cached_block->data)
+ cached_block->data =
+ new MapNode[MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE];
memcpy(cached_block->data, b->getData(),
MAP_BLOCKSIZE * MAP_BLOCKSIZE * MAP_BLOCKSIZE * sizeof(MapNode));
+ } else {
+ delete[] cached_block->data;
+ cached_block->data = nullptr;
}
return cached_block;
}
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);
{
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;
std::vector<NearbyCollisionInfo> cinfo;
{
//TimeTaker tt2("collisionMoveSimple collect boxes");
- ScopeProfiler sp2(g_profiler, "collisionMoveSimple collect boxes avg", SPT_AVG);
+ ScopeProfiler sp2(g_profiler, "collisionMoveSimple(): collect boxes", SPT_AVG);
v3f newpos_f = *pos_f + *speed_f * dtime;
v3f minpos_f(
if(collideWithObjects)
{
- ScopeProfiler sp2(g_profiler, "collisionMoveSimple objects avg", SPT_AVG);
- //TimeTaker tt3("collisionMoveSimple collect object boxes");
-
/* add object boxes to cinfo */
std::vector<ActiveObject*> objects;
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) {
{
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);
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++) {
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);
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 */
*/
#include "profiler.h"
+#include "porting.h"
static Profiler main_profiler;
Profiler *g_profiler = &main_profiler;
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()
}
delete m_timer;
}
+
+Profiler::Profiler()
+{
+ m_start_time = porting::getTimeMs();
+}
+
+void Profiler::add(const std::string &name, float value)
+{
+ MutexAutoLock lock(m_mutex);
+ {
+ /* No average shall have been used; mark add used as -2 */
+ std::map<std::string, int>::iterator n = m_avgcounts.find(name);
+ if (n == m_avgcounts.end()) {
+ m_avgcounts[name] = -2;
+ } else {
+ if (n->second == -1)
+ n->second = -2;
+ assert(n->second == -2);
+ }
+ }
+ {
+ std::map<std::string, float>::iterator n = m_data.find(name);
+ if (n == m_data.end())
+ m_data[name] = value;
+ else
+ n->second += value;
+ }
+}
+
+void Profiler::avg(const std::string &name, float value)
+{
+ MutexAutoLock lock(m_mutex);
+ int &count = m_avgcounts[name];
+
+ assert(count != -2);
+ count = MYMAX(count, 0) + 1;
+ m_data[name] += value;
+}
+
+void Profiler::clear()
+{
+ MutexAutoLock lock(m_mutex);
+ for (auto &it : m_data) {
+ it.second = 0;
+ }
+ m_avgcounts.clear();
+ m_start_time = porting::getTimeMs();
+}
+
+float Profiler::getValue(const std::string &name) const
+{
+ auto numerator = m_data.find(name);
+ if (numerator == m_data.end())
+ return 0.f;
+
+ auto denominator = m_avgcounts.find(name);
+ if (denominator != m_avgcounts.end()) {
+ if (denominator->second >= 1)
+ return numerator->second / denominator->second;
+ }
+
+ return numerator->second;
+}
+
+int Profiler::getAvgCount(const std::string &name) const
+{
+ auto n = m_avgcounts.find(name);
+
+ if (n != m_avgcounts.end() && n->second >= 1)
+ return n->second;
+
+ return 1;
+}
+
+u64 Profiler::getElapsedMs() const
+{
+ return porting::getTimeMs() - m_start_time;
+}
+
+int Profiler::print(std::ostream &o, u32 page, u32 pagecount)
+{
+ GraphValues values;
+ getPage(values, page, pagecount);
+ char num_buf[50];
+
+ for (const auto &i : values) {
+ o << " " << i.first << " ";
+ if (i.second == 0) {
+ o << std::endl;
+ continue;
+ }
+
+ s32 space = 44 - i.first.size();
+ for (s32 j = 0; j < space; j++) {
+ if ((j & 1) && j < space - 1)
+ o << ".";
+ else
+ o << " ";
+ }
+ porting::mt_snprintf(num_buf, sizeof(num_buf), "% 4ix % 3g",
+ getAvgCount(i.first), i.second);
+ o << num_buf << std::endl;
+ }
+ return values.size();
+}
+
+void Profiler::getPage(GraphValues &o, u32 page, u32 pagecount)
+{
+ MutexAutoLock lock(m_mutex);
+
+ u32 minindex, maxindex;
+ paging(m_data.size(), page, pagecount, minindex, maxindex);
+
+ for (const auto &i : m_data) {
+ if (maxindex == 0)
+ break;
+ maxindex--;
+
+ if (minindex != 0) {
+ minindex--;
+ continue;
+ }
+
+ o[i.first] = i.second / getAvgCount(i.first);
+ }
+}
#include "util/timetaker.h"
#include "util/numeric.h" // paging()
-#define MAX_PROFILER_TEXT_ROWS 20
-
// Global profiler
class Profiler;
extern Profiler *g_profiler;
class Profiler
{
public:
- Profiler() = default;
+ Profiler();
- void add(const std::string &name, float value)
- {
- MutexAutoLock lock(m_mutex);
- {
- /* No average shall have been used; mark add used as -2 */
- std::map<std::string, int>::iterator n = m_avgcounts.find(name);
- if(n == m_avgcounts.end())
- m_avgcounts[name] = -2;
- else{
- if(n->second == -1)
- n->second = -2;
- assert(n->second == -2);
- }
- }
- {
- std::map<std::string, float>::iterator n = m_data.find(name);
- if(n == m_data.end())
- m_data[name] = value;
- else
- n->second += value;
- }
- }
+ void add(const std::string &name, float value);
+ void avg(const std::string &name, float value);
+ void clear();
- void avg(const std::string &name, float value)
- {
- MutexAutoLock lock(m_mutex);
- int &count = m_avgcounts[name];
+ float getValue(const std::string &name) const;
+ int getAvgCount(const std::string &name) const;
+ u64 getElapsedMs() const;
- assert(count != -2);
- count = MYMAX(count, 0) + 1;
- m_data[name] += value;
- }
-
- void clear()
- {
- MutexAutoLock lock(m_mutex);
- for (auto &it : m_data) {
- it.second = 0;
- }
- m_avgcounts.clear();
- }
-
- void print(std::ostream &o)
- {
- printPage(o, 1, 1);
- }
-
- float getValue(const std::string &name) const
- {
- std::map<std::string, float>::const_iterator numerator = m_data.find(name);
- if (numerator == m_data.end())
- return 0.f;
-
- std::map<std::string, int>::const_iterator denominator = m_avgcounts.find(name);
- if (denominator != m_avgcounts.end()){
- if (denominator->second >= 1)
- return numerator->second / denominator->second;
- }
-
- return numerator->second;
- }
-
- void printPage(std::ostream &o, u32 page, u32 pagecount)
- {
- MutexAutoLock lock(m_mutex);
+ typedef std::map<std::string, float> GraphValues;
- u32 minindex, maxindex;
- paging(m_data.size(), page, pagecount, minindex, maxindex);
-
- for (std::map<std::string, float>::const_iterator i = m_data.begin();
- i != m_data.end(); ++i) {
- if (maxindex == 0)
- break;
- maxindex--;
-
- if (minindex != 0) {
- minindex--;
- continue;
- }
-
- int avgcount = 1;
- std::map<std::string, int>::const_iterator n = m_avgcounts.find(i->first);
- if (n != m_avgcounts.end()) {
- if(n->second >= 1)
- avgcount = n->second;
- }
- o << " " << i->first << ": ";
- s32 clampsize = 40;
- s32 space = clampsize - i->first.size();
- for(s32 j = 0; j < space; j++) {
- if (j % 2 == 0 && j < space - 1)
- o << "-";
- else
- o << " ";
- }
- o << (i->second / avgcount);
- o << std::endl;
- }
- }
+ // Returns the line count
+ int print(std::ostream &o, u32 page = 1, u32 pagecount = 1);
+ void getPage(GraphValues &o, u32 page, u32 pagecount);
- typedef std::map<std::string, float> GraphValues;
void graphAdd(const std::string &id, float value)
{
std::map<std::string, float> m_data;
std::map<std::string, int> m_avgcounts;
std::map<std::string, float> m_graphvalues;
+ u64 m_start_time;
};
enum ScopeProfilerType{
void Server::AsyncRunStep(bool initial_step)
{
- g_profiler->add("Server::AsyncRunStep (num)", 1);
float dtime;
{
if((dtime < 0.001) && !initial_step)
return;
- g_profiler->add("Server::AsyncRunStep with dtime (num)", 1);
-
- //infostream<<"Server steps "<<dtime<<std::endl;
- //infostream<<"Server::AsyncRunStep(): dtime="<<dtime<<std::endl;
+ ScopeProfiler sp(g_profiler, "Server::AsyncRunStep()", SPT_AVG);
{
MutexAutoLock lock1(m_step_dtime_mutex);
}
m_env->reportMaxLagEstimate(max_lag);
// Step environment
- ScopeProfiler sp(g_profiler, "SEnv step");
- ScopeProfiler sp2(g_profiler, "SEnv step avg", SPT_AVG);
m_env->step(dtime);
}
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 =
*/
{
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
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()) {
// 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 {
MutexAutoLock envlock(m_env_mutex);
//TODO check if one big lock could be faster then multiple small ones
- ScopeProfiler sp(g_profiler, "Server: sel and send blocks to clients");
-
std::vector<PrioritySortedBlockTransfer> queue;
u32 total_sending = 0;
{
- ScopeProfiler sp2(g_profiler, "Server: selecting blocks for sending");
+ ScopeProfiler sp2(g_profiler, "Server::SendBlocks(): Collect list");
std::vector<session_t> clients = m_clients.getClientIDs();
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;
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)
void ActiveObjectMgr::step(
float dtime, const std::function<void(ServerActiveObject *)> &f)
{
- g_profiler->avg("Server::ActiveObjectMgr: num of objects",
- m_active_objects.size());
+ g_profiler->avg("ActiveObjectMgr: SAO count [#]", m_active_objects.size());
for (auto &ao_it : m_active_objects) {
f(ao_it.second);
}
void ServerEnvironment::step(float dtime)
{
+ ScopeProfiler sp2(g_profiler, "ServerEnv::step()", SPT_AVG);
/* Step time of day */
stepTimeOfDay(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)
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
*/
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;
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);
}
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;
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();
}
*/
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) {
projects / oweals / minetest.git / commitdiff