Feature [TFS 1.4] OTS statistics (C++/Lua/SQL) by kondra

[matheusjp2]

@Gesior.pl
I'm testing in otx the result is very cool, a doubt is there a way to disable it? or put hours in hours
I also noticed that it doesn't show the amount of players online, it's always 0

[9/7/2023 19:49:58]
Thread: 1 Cpu usage: 1.23292% Idle: 98.9552% Other: -0.188133% Players online: 0
 Time (ms)     Calls     Rel usage %    Real usage % Description
       210      9370       56.82251%        0.70058% functor
        67       300       18.22563%        0.22471% boost::bind(&Game::checkCreatures, this)
        66      3464       18.07986%        0.22291% boost::bind(&Game::checkCreatureWalk, &g_game, id)
        14       599        3.96441%        0.04888% boost::bind(&GlobalEvents::think, this)
         7       120        1.93587%        0.02387% boost::bind(&Game::checkDecay, this)
         2        17        0.68945%        0.00850% &Game::playerMove
         0        30        0.23004%        0.00284% boost::bind(&GlobalEvents::timer, this)

 

[Gesior.pl]

@Gesior.pl
I'm testing in otx the result is very cool, a doubt is there a way to disable it? or put hours in hours
I also noticed that it doesn't show the amount of players online, it's always 0

[9/7/2023 19:49:58]
Thread: 1 Cpu usage: 1.23292% Idle: 98.9552% Other: -0.188133% Players online: 0
 Time (ms)     Calls     Rel usage %    Real usage % Description
       210      9370       56.82251%        0.70058% functor
        67       300       18.22563%        0.22471% boost::bind(&Game::checkCreatures, this)
        66      3464       18.07986%        0.22291% boost::bind(&Game::checkCreatureWalk, &g_game, id)
        14       599        3.96441%        0.04888% boost::bind(&GlobalEvents::think, this)
         7       120        1.93587%        0.02387% boost::bind(&Game::checkDecay, this)
         2        17        0.68945%        0.00850% &Game::playerMove
         0        30        0.23004%        0.00284% boost::bind(&GlobalEvents::timer, this)

OTX2 version ( OTS Statistics by kondra by gesior · Pull Request #737 · mattyx14/otxserver (https://github.com/mattyx14/otxserver/pull/737) ) is missing 1 line that counts players online.
In game.cpp under ( otxserver/sources/game.cpp at otxserv2 · mattyx14/otxserver (https://github.com/mattyx14/otxserver/blob/otxserv2/sources/game.cpp#L4802C1-L4805C77) ):

void Game::checkCreatures()
{
    checkCreatureEvent = g_scheduler.addEvent(createSchedulerTask(
        EVENT_CHECK_CREATURE_INTERVAL, boost::bind(&Game::checkCreatures, this)));

Add:

g_stats.playersOnline = getPlayersOnline();

OTX2 version does not have config.lua support. IDK why you would like to disable stats. They are extremely useful, because they work all time.
You get some random lag at 2 AM with 150 online -> you get report about it and probable reason.

If you got problem with amount of data generated by stats, you can remove logs folder, so it will stop saving results in files - it will show some errors in console, ignore them.
You can also edit report times:

otxserver/sources/stats.cpp at otxserv2 · mattyx14/otxserver

OTX Server from:. Contribute to mattyx14/otxserver development by creating an account on GitHub.

github.com

 

[matheusjp2]

OTX2 version ( OTS Statistics by kondra by gesior · Pull Request #737 · mattyx14/otxserver (https://github.com/mattyx14/otxserver/pull/737) ) is missing 1 line that counts players online.
In game.cpp under ( otxserver/sources/game.cpp at otxserv2 · mattyx14/otxserver (https://github.com/mattyx14/otxserver/blob/otxserv2/sources/game.cpp#L4802C1-L4805C77) ):

void Game::checkCreatures()
{
    checkCreatureEvent = g_scheduler.addEvent(createSchedulerTask(
        EVENT_CHECK_CREATURE_INTERVAL, boost::bind(&Game::checkCreatures, this)));

Add:

g_stats.playersOnline = getPlayersOnline();

OTX2 version does not have config.lua support. IDK why you would like to disable stats. They are extremely useful, because they work all time.
You get some random lag at 2 AM with 150 online -> you get report about it and probable reason.

If you got problem with amount of data generated by stats, you can remove logs folder, so it will stop saving results in files - it will show some errors in console, ignore them.
You can also edit report times:

otxserver/sources/stats.cpp at otxserv2 · mattyx14/otxserver

OTX Server from:. Contribute to mattyx14/otxserver development by creating an account on GitHub.

github.com

it is due to the size of the file it was saving in 30 in 30 seconds
I'll try to put it in hours

 

[Matheuuss]

@Gesior.pl I tried to compile in windows this 0.4 that you made available. But it gives several errors, I tried with devcpp and VS2010. Do you have any secrets? And would have some modification in rev3996?

 

[Tbol]

Umm stupid question but how you disable it from printing logs? Collected enough information and i think its about time to disable it for now

 

[Gesior.pl]

Umm stupid question but how you disable it from printing logs? Collected enough information and i think its about time to disable it for now

In config.lua set statsDumpInterval to 0.

Threads will still pass stats data around, but instead of dumping them, 'stats thread' will just clear memory:

OTS Statistics by kondra ([email protected]) · gesior/forgottenserver-gesior@0ad4be6

A free and open-source MMORPG server emulator written in C++ - OTS Statistics by kondra (otclient@************) · gesior/forgottenserver-gesior@0ad4be6

github.com

There were versions where you could enable/disable stats code by compiler flag, but I don't think it's a good idea. Your server may start lagging anytime - when some player find new bug/new attack. Then you just need to edit config.lua, /reload config and it will start logging within 30 seconds.
I would say it's most common case. People start server. It uses 20% CPU with 100 online for a week and then it starts using 99% with 120 online. Just because some player did some quest/started hunting some place. They had to add stats, recompile engine and restart OTS. Now you can start new server with stats in engine and enable logging, when it will be needed.

 

[Tbol]

In config.lua set statsDumpInterval to 0.

Threads will still pass stats data around, but instead of dumping them, 'stats thread' will just clear memory:

OTS Statistics by kondra ([email protected]) · gesior/forgottenserver-gesior@0ad4be6

A free and open-source MMORPG server emulator written in C++ - OTS Statistics by kondra (otclient@************) · gesior/forgottenserver-gesior@0ad4be6

github.com

There were versions where you could enable/disable stats code by compiler flag, but I don't think it's a good idea. Your server may start lagging anytime - when some player find new bug/new attack. Then you just need to edit config.lua, /reload config and it will start logging within 30 seconds.
I would say it's most common case. People start server. It uses 20% CPU with 100 online for a week and then it starts using 99% with 120 online. Just because some player did some quest/started hunting some place. They had to add stats, recompile engine and restart OTS. Now you can start new server with stats in engine and enable logging, when it will be needed.

But isnt it hits trough performance still if statsDumpInterval interval is set to 0? Because threads will still pass like you mentioned?

 

[Gesior.pl]

But isnt it hits trough performance still if statsDumpInterval interval is set to 0? Because threads will still pass like you mentioned?

'Tasks' (dispatcher events) are passed between threads, not copied, so it's not CPU/RAM intensive operation. Only overheads are:

• threads synchronization - to pass "Task" from 'dispatcher thread' to vector in 'stats thread', but stats thread is almost never locked, so it should easily handle hundreds of thousands per second
• 2 extra strings in each Task (C++ function name and description ex. player who executed it name)
• each Lua script execution generates some kind of 'Task' (with .lua file name and function name) and passes it to 'stats thread' - in case of some servers (probably 0.4) and addEvent/mods it may copy whole Lua function code as it's "name"
• each SQL query's first 256 characters are copied and sent to 'stats thread'

As someone posted in this thread. There are other tools to measure what uses CPU in C++ app. Some tools does not affect CPU usage, but are very inaccurate ['perf']. Some tools increase CPU usage by 1000%, but are super accurate [debug tools tracking every single C++ function execution].
OTS stats are somewhere between them. Adds 1-5% of CPU usage - most on stats thread, not dispatcher - to get pretty accurate and easy to read reports.

It should not be a problem, because your server should not use over 80% CPU with maximum number of players online. If it does, it lags for sure in game.
That's why most popular OTSes run with stats enabled all time. Remember that lag may occur at night, some players may report it on morning and without stats enabled all time, you won't be able to check what lagged or if server lagged at all. If nothing is in stats, it means that server did not lag and it was some network problem. You can even detect network lag on dedic with stats: if players report lags on X hour, check OTS CPU usage in last 30 seconds in dispatcher.log. If it went down at reported time, probably number of network packets decreased = network lagged.

If you really need to save every CPU cycle, you can disable stats in sources. Compile server with parameter 'DISABLE_STATS=1':

cmake -DDISABLE_STATS=1 ..

(it's -DDIS.. with double D, first is to tell cmake it's parameter 'Definition')
Then it will only add 2 empty strings to each Task (in place of C++ function name and description), but will not track Lua/SQL (copy Lua code/SQL queries) and 'stats thread' won't start.

 

[omaraboud]

Compiled without any problems but I don't know why my stats are not saving. Files are not generated at all.

 

[omaraboud]

@Gesior.pl any help?

 

[Error 502]

Compiled without any problems but I don't know why my stats are not saving. Files are not generated at all.

1.- your server which protocol and version is ?
2.- did you create the logs/stats folder?
3.- does the folder or user have write privileges?
4.- use, std::cout << ".........................................................." << std::endl;
, see if it will at least call the function

 

[kor]

@Gesior.pl From this commit std::bind was replaced with lambdas and I can't manage to adjust kondrah stat system (scheduler and task part) to compile. Are you able adapt this feature for current TFS code, please?

 

[Albert José]

Reuploaded it:

#2641 optimized item decay algorithm, timestamp (offline) decay · gesior/forgottenserver-gesior@c6865c8

A free and open-source MMORPG server emulator written in C++ - #2641 optimized item decay algorithm, timestamp (offline) decay · gesior/forgottenserver-gesior@c6865c8

github.com

It's based on some 2019 TFS version that does not compile anymore, but I've tested it in 2019 and everything worked fine.

I took a look at the commits and saw that compared to version 1.4 some things have changed, items now have a decayTo (ITEM_ATTRIBUTE_DECAYTO = 1 << 23,) attribute, which in the case of adjustment ends up being replaced by ITEM_ATTRIBUTE_DECAY_TIMESTAMP = 1 << 23, @Gesior.pl, any chance to update this enhancement to this new version? I had instaled the OTS stats on my 1.4 TFS server and checkDecay is the main "slow lua code" on my report:

[30/01/2024 11:14:52] Execution time: 14803 ms - std::bind(mainLoader, argc, argv, &serviceManager) - main
[30/01/2024 11:14:52] Execution time: 63 ms - std::bind(&Game::checkDecay, this) - start
[30/01/2024 11:14:53] Execution time: 62 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:14:54] Execution time: 90 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:14:55] Execution time: 59 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:14:56] Execution time: 59 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:14:57] Execution time: 60 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:14:58] Execution time: 59 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:14:59] Execution time: 58 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:00] Execution time: 62 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:01] Execution time: 59 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:02] Execution time: 61 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:03] Execution time: 58 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:04] Execution time: 58 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:05] Execution time: 58 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:06] Execution time: 59 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:07] Execution time: 60 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:08] Execution time: 59 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:09] Execution time: 58 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:10] Execution time: 58 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:11] Execution time: 59 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:12] Execution time: 60 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:13] Execution time: 58 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:14] Execution time: 58 ms - std::bind(&Game::checkDecay, this) - checkDecay
[30/01/2024 11:15:15] Execution time: 57 ms - std::bind(&Game::checkDecay, this) - checkDecay

 

[Gesior.pl]

decayTo (ITEM_ATTRIBUTE_DECAYTO = 1 << 23,) attribute, which in the case of adjustment ends up being replaced by ITEM_ATTRIBUTE_DECAY_TIMESTAMP = 1 << 23

If there is other feature that uses 1 << 23, you should add ITEM_ATTRIBUTE_DECAY_TIMESTAMP with 24. TFS supports up to 31 item attributes (or more in newest version, did not check).

Someone sent me link to repository with similar feature, but with cleaner code:

Optimized new decay algorithm · punkice3407/optimized_forgottenserver@0e011ff

This algorithm use timestamped durations wrapped over delta timers making it perfect O(1) lookup instead of traversing every decay-able item every second. Since it doesn't need to make any calc...

github.com

This version does not support 'timestamp decay' - offline decay ex. item disappears after 24 hours, no matter, if you were online or not.
It only optimizes checkDecay time: "Since it doesn't need to make any calculations to decay-able items it should be hundreds times faster."

Post automatically merged: Jan 30, 2024

From this commit std::bind was replaced with lambdas and I can't manage to adjust kondrah stat system (scheduler and task part) to compile. Are you able adapt this feature for current TFS code, please?

Lambdas are not a problem. To pass them to createTask function you need to add ( before lambda function and ) after it. Otherwise compiler will show error ‘createTask’ was not declared in this scope, if you try to pass lambda function with more than 1 argument.
Problem is that in newest TFS 1.5 they removed createTask macro and pass lambda functions directly to g_dispatcher.addTask. To add OTS stats, we must add createTask macro again to every call to addTask in code.

My code to test std::bind and lambdas:

#include <iostream>
#include <functional>

#define createTask(function) createTaskWithStats(function, #function, __FUNCTION__)

using TaskFunc = std::function<void(void)>;

void createTaskWithStats(TaskFunc &&f, const std::string &description, const std::string &extraDescription) {
  std::cout << "createTaskWithStats: " << description << " - " << extraDescription << std::endl;
}

class Protocol {
public:
  void release() {
    std::cout << "release" << std::endl;
  }
  void releaseThis() {
    std::cout << "releaseThis" << std::endl;
  }
  void releaseVar(int var) {
    std::cout << "releaseVar: " << var << std::endl;
  }
  void releaseVarThis(int var) {
    std::cout << "releaseVarThis: " << var << std::endl;
  }
  void runThisTests() {
    // old
    createTask(std::bind(&Protocol::releaseThis, this));
    // new
    createTask([this]() { releaseThis(); });
  }
};

int main() {
  // test with this
  auto protocol = new Protocol();
  protocol->runThisTests();

  // test with 1 param
  createTask(std::bind(&Protocol::release, protocol));
  createTask([protocol = protocol]() { protocol->release(); });

  // test with 2 params
  int var = 1;
  createTask(std::bind(&Protocol::releaseVar, protocol, var));
  // this fails with "‘createTask’ was not declared in this scope", added extra `(` and `)` around
  // createTask([protocol1 = protocol, var1 = var]() { protocol1->releaseVar(var1); });
  createTask(([protocol1 = protocol, var1 = var]() { protocol1->releaseVar(var1); }));

  return 0;
}

Results:

createTaskWithStats: std::bind(&Protocol::releaseThis, this) - runThisTests
createTaskWithStats: [this]() { releaseThis(); } - runThisTests
createTaskWithStats: std::bind(&Protocol::release, protocol) - main
createTaskWithStats: [protocol = protocol]() { protocol->release(); } - main
createTaskWithStats: std::bind(&Protocol::releaseVar, protocol, var) - main
createTaskWithStats: ([protocol1 = protocol, var1 = var]() { protocol1->releaseVar(var1); }) - main

 

[Gesior.pl]

Lambdas are not a problem. To pass them to createTask function you need to add ( before lambda function and ) after it. Otherwise compiler will show error ‘createTask’ was not declared in this scope, if you try to pass lambda function with more than 1 argument.

I though about possible solutions other that adding parenthesis to every lambda function in TFS (100+ lines to edit).

My first idea was to create function createTask (not macro) that takes std::function as parameter and pass it to macro, to read function's name using #function. It did not work. Macro reported createTask as every #function, not function passed as parameter.

My second idea was to make macro that adds ( and ) and calls other macro and it worked!

#include <iostream>
#include <functional>

#define realCreateTask(function) createTaskWithStats(function, #function, __FUNCTION__)
#define createTask(...) realCreateTask((__VA_ARGS__))

using TaskFunc = std::function<void(void)>;

void createTaskWithStats(TaskFunc &&f, const std::string &description, const std::string &extraDescription) {
  std::cout << "createTaskWithStats: " << description << " - " << extraDescription << std::endl;
}

class Protocol {
public:
  void release() {
    std::cout << "release" << std::endl;
  }
  void releaseThis() {
    std::cout << "releaseThis" << std::endl;
  }
  void releaseVar(int var) {
    std::cout << "releaseVar: " << var << std::endl;
  }
  void releaseVarThis(int var) {
    std::cout << "releaseVarThis: " << var << std::endl;
  }
  void runThisTests() {
    // old
    createTask(std::bind(&Protocol::releaseThis, this));
    // new
    createTask([this]() { releaseThis(); });
  }
};

int main() {
  // test with this
  auto protocol = new Protocol();
  protocol->runThisTests();

  // test with 1 param
  createTask(std::bind(&Protocol::release, protocol));
  createTask([protocol = protocol]() { protocol->release(); });

  // test with 2 params
  int var = 1;
  createTask(std::bind(&Protocol::releaseVar, protocol, var));
  // this fails with "‘createTask’ was not declared in this scope", added extra `(` and `)` around
  // createTask([protocol1 = protocol, var1 = var]() { protocol1->releaseVar(var1); });
  createTask(([protocol1 = protocol, var1 = var]() { protocol1->releaseVar(var1); }));

  return 0;
}

At least on Linux. I read on stackoverflow that there were some problems with lambdas and macros around 2015 with VS compiler, but maybe they are fixed already.