• There is NO official Otland's Discord server and NO official Otland's server list. The Otland's Staff does not manage any Discord server or server list. Moderators or administrator of any Discord server or server lists have NO connection to the Otland's Staff. Do not get scammed!

[C++] Monitoring execution time of LUA scripts and avoiding freezes

Stellow

C++/C#/PHP/LUA
Joined
Oct 23, 2008
Messages
1,106
Reaction score
214
Location
Germany
GitHub
eubrunomiguel
Hello guys, for months I was facing some problem with one of my client's server, on which it would simply freezes without any abomination on bandwidth. I knew that I had peeks on main memory, but still could not locate what was causing it. Was it some distro configuration that I have implemented on the past? Or some LUA functions? Well, turns out, with an advice from @Xikini I could monitor LUA function execution time and locate the error.

This is a simply implementation, but it turns out, I could easily see LUA functions taking up to 1000+ms on its execution time, not to much, but if consider it blocks the current thread, it turns out a lot.

For the geeks, I did the implementation using really basic structure, I did not want to globally instantiate a object to take care of the logging, because it would result in more functions calls and complexity. It would be better, but I did not want to mess up much with the code structure; I have opted for a simply class that would start counting, and on its destructor, did the real work in case time was overwhelmed. Could I maybe used some heap memory and pointers to avoid the extra memory on functions calls? hmm.. yes, but also, that would result in bad performance if not implemented correctly, nor keeping up with the memory layout itself.

Please feel free to criticize on how this basic implementation is set up, and maybe we can workout together on something more attractive.

Script.

On baseevent.h (because all the other LUA scripts functions are inheritanced from it) I created a class:

Code:
#include "database.h"

class EventLog
{
public:
    EventLog(std::string eventName) : _function(eventName), _time(OTSYS_TIME()), _eventName("") {}
    void setName(std::string name) {_eventName = name;};
    ~EventLog()
    {
        int64_t totalTime = OTSYS_TIME() - _time;
        if (totalTime > 50) // 50 ms
        {
            std::cout << _function << " execution time:" << totalTime << " ms. Logging..." << std::endl;
            
            Database* db = Database::instance();
            DBInsert stmt(db);
            stmt.setQuery("INSERT INTO `event_log` (function, time_ms, event_name) VALUES ");
            DBQuery query;
            query << "'" << _function << "'" << ", " << totalTime << ", " << "'" << _eventName << "'";
            stmt.addRow(query.str());
            stmt.execute();
        }
    }
    
private:
    std::string _function;
    std::string _eventName;
    int64_t _time;
};

Then, to log onLogout script for example, I simply call the function, set up few parameters, and let the destructor take care of it.

Code:
bool CreatureEvent::executeOnLogout(Player* player)   
//onLogout(cid)
...
 EventLog event("onLogout");
 event.setName(m_eventName);


It results something like this:

Screen_Shot_2016_09_23_at_1_42_17_PM.png
 
Cool. :p
But to be fair it was MatheusMkalo that made the function I linked you to. :rolleyes:
 
Hello guys, for months I was facing some problem with one of my client's server, on which it would simply freezes without any abomination on bandwidth. I knew that I had peeks on main memory, but still could not locate what was causing it. Was it some distro configuration that I have implemented on the past? Or some LUA functions? Well, turns out, with an advice from @Xikini I could monitor LUA function execution time and locate the error.

This is a simply implementation, but it turns out, I could easily see LUA functions taking up to 1000+ms on its execution time, not to much, but if consider it blocks the current thread, it turns out a lot.

For the geeks, I did the implementation using really basic structure, I did not want to globally instantiate a object to take care of the logging, because it would result in more functions calls and complexity. It would be better, but I did not want to mess up much with the code structure; I have opted for a simply class that would start counting, and on its destructor, did the real work in case time was overwhelmed. Could I maybe used some heap memory and pointers to avoid the extra memory on functions calls? hmm.. yes, but also, that would result in bad performance if not implemented correctly, nor keeping up with the memory layout itself.

Please feel free to criticize on how this basic implementation is set up, and maybe we can workout together on something more attractive.

Script.

On baseevent.h (because all the other LUA scripts functions are inheritanced from it) I created a class:

Code:
#include "database.h"

class EventLog
{
public:
    EventLog(std::string eventName) : _function(eventName), _time(OTSYS_TIME()), _eventName("") {}
    void setName(std::string name) {_eventName = name;};
    ~EventLog()
    {
        int64_t totalTime = OTSYS_TIME() - _time;
        if (totalTime > 50) // 50 ms
        {
            std::cout << _function << " execution time:" << totalTime << " ms. Logging..." << std::endl;
          
            Database* db = Database::instance();
            DBInsert stmt(db);
            stmt.setQuery("INSERT INTO `event_log` (function, time_ms, event_name) VALUES ");
            DBQuery query;
            query << "'" << _function << "'" << ", " << totalTime << ", " << "'" << _eventName << "'";
            stmt.addRow(query.str());
            stmt.execute();
        }
    }
  
private:
    std::string _function;
    std::string _eventName;
    int64_t _time;
};

Then, to log onLogout script for example, I simply call the function, set up few parameters, and let the destructor take care of it.

Code:
bool CreatureEvent::executeOnLogout(Player* player) 
//onLogout(cid)
...
 EventLog event("onLogout");
 event.setName(m_eventName);


It results something like this:

Screen_Shot_2016_09_23_at_1_42_17_PM.png
I would store a good amount of logs in a buffer before getting them to the database, or even better, not use database at all and output it to a file. (That if you intend to keep this running on production)
 
You can also save it 2 times.

First time when it starts (you can easly find potential crash issue)

Second time when it ends.
 
Back
Top