Replace rasdaman logging with easylogging

[George Merticariu]

Right now debugging info is produced in few different ways:

• RMDebug macros (RMDBGENTER, RMDBGEXIT, etc.), very complex and allow fine grained control, but seem somewhat broken
• ENTER/LEAVE/TALK - very simple, provide indentation, but only global control is possible
• The tile cache introduces TENTER/TTALK/TLEAVE which allow to turn on ENTER/LEAVE/TALK selectively only in the tile cache
• RMInit::logOut, RMInit::dbgOut - simple output to the log, no possibility to turn off, typically used for outputing warnings/errors and other important info

These should be harmonized into a single method, which is hopefully both powerful and simple.

The decision in this ticket is to substitute all these with easylogging, already used in rasnet.
The main arguments for using easylogging are the following:

• It provides thread safe logging.
• It can be configured at runtime by providing a configuration file.(e.g. log formats can be configured, log levels can be disabled if they are not of interest)
• It offers a range of different log levels.
• There is no clear documentation on what loggers are available in rasdaman and what capabilities they have.

[Dimitar Misev]

What about replacing the existing rasdaman logging with the easylogging? I assume easylogging is a better solution, otherwise why did you decide to use it?

[Alex Dumitru]

I vote for keeping easylogging as well. Should be simple to replace the current logging mechanism, just redefine the existing rasdaman log macros to easy logging macros.

[Alex Toader]

The main arguments for using easylogging are the following:

1. It provides thread safe logging.
2. It can be configured at runtime by providing a configuration file.(e.g. log formats can be configured, log levels can be disabled if they are not of interest)
3. It offers a range of different log levels.
4. There is no clear documentation on what loggers are available in rasdaman and what capabilities they have.

[Peter Baumann]

Nothing against easylogging - but much against having divergent mechanisms. So we might also go for the new one, _but_ that entails going through the whole code and adjusting RMInit and Debug. From my feeling this is a tremendous work - any resources on the horizon?

[Dimitar Misev]

I think this task would fit for Jinbo, unless someone else is already working on it?

Alex or Vlad, can you give some directions to Jinbo?

[Dimitar Misev]

I think we can move to this ticket next.

1. check this to familiarize with easylogging: ​https://github.com/easylogging/easyloggingpp#introduction
2. check how is easylogging configured and used in
   • rasmgr_x/src/main.cc → rasmgr/rasmgr_main.cc
   • rascontrol_x/src/rascontrol_main.cc → rascontrol/rascontrol.cc
   • enable by default in server/rasserver_main.cc
3. Finally substitute the RMDBGENTER, RMDBGEXIT, ENTER/LEAVE, … with the easylogging macros.

[Dimitar Misev]

So currently there's an issue with easylogging, even though LTRACE/LDEBUG is disabled they still seem to evaluate and cause easylogging to lock/unlock..

           95.4  .........      11.14 / 11.16        QtDomainOperation::evaluate(std::vector<QtData*, std::allocator<QtData*> >*) [11]
[12]       95.4      11.14       0.09 / 11.06      Tile::Tile(Tile const*, r_Minterval const&, std::set<unsigned int, std::less<unsigned int>, std::allocator<unsigned int> > const*)
           45.4  .........       5.30 / 5.30         Tile::getContents() [15]
           41.9  .........       4.90 / 9.34         easyloggingpp::internal::Writer::Writer(std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, unsigned int, unsigned int, char const*, char const*, unsigned long, bool, int, int) [13]
            2.9  .........       0.34 / 0.72         easyloggingpp::internal::Writer::~Writer() [28]
            1.9  .........       0.22 / 0.48         std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(char const*, std::allocator<char> const&) [43]
            0.7  .........       0.08 / 0.08         Tile::getContents() const [75]

As you can see in the profile above, only

easyloggingpp::internal::Writer::Writer(std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, unsigned int, unsigned int, char const*, char const*, unsigned long, bool, int, int) [13]

inside the Tile constructor (tile.cc:164) which comes from an LTRACE, comprises 41.9% of the execution:

    while(!projTileIter.isDone())
    {
        cellTile = newTileIter.nextCell();
        cellProj = projTileIter.nextCell();
        LTRACE << "offset in original: " << (int)(cellProj-(projTile)->getContents()) << " {" << (int)*cellProj << "} offset in result: " << (int)((int)(cellTile-getContents())) << " {" << (int)*cellTile << "}";
        // execute operation on cell
        (*op)(cellTile, cellProj);
    }

So currently commenting out these three lines fixes the performance:

• tile.cc:164
• dbobject.cc:356
• dbtile.cc:137

This is only for the evaluation of a single query however..

select avg_cells(c[0:3000,0:3000]) from testBig as c

So we need to fix this properly, and not by hunting and commenting out debug statements.

[Dimitar Misev]

It's solved now by turnning on/off TRACE messages only at compile time.

We still need to be careful, because TRACE messages sometimes contain function calls and computations which also affect performance, so in that case it's best to wrap them in

#ifdef DEBUG
  LTRACE << ...
#endif

[Peter Baumann]

that's exactly what debug.hh has been doing, but centrally, not with every statement. We might learn from it and adapt easylogging use accordingly.

[Peter Baumann]

well done, just

• add std header to log-server.conf and others
• add documentation (cf rasmgr.conf as a role model

[Alex Dumitru]

@Peter, I've opened a new ticket for documentation, the initial issue seems solved with the latest patch.