Opened 2 years ago

Closed 21 months ago

#903 closed enhancement (fixed)

Replace rasdaman logging with easylogging

Reported by: gmerticariu Owned by: vzamfir
Priority: major Milestone: 9.2
Component: rasnet Version: development
Keywords: Cc: pbaumann, mdumitru, atoader
Complexity: Medium

Description (last modified by dmisev)

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.

Change History (15)

comment:1 Changed 2 years ago by gmerticariu

  • Cc mdumitru added; adumitru removed
  • Summary changed from Use already existing rasdaman loggin mechanism in rasnet to Use already existing rasdaman logging mechanism in rasnet

comment:2 Changed 2 years ago by dmisev

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?

comment:3 Changed 2 years ago by mdumitru

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.

comment:4 Changed 2 years ago by atoader

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.

comment:5 Changed 2 years ago by pbaumann

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?

comment:6 Changed 2 years ago by dmisev

  • Milestone set to 9.1
  • Owner changed from gmerticariu to jzhang
  • Status changed from new to assigned

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?

comment:7 Changed 2 years ago by dmisev

  • Description modified (diff)
  • Owner changed from jzhang to vzamfir
  • Priority changed from minor to major
  • Type changed from defect to enhancement

comment:8 Changed 2 years ago by dmisev

  • Milestone changed from 9.1 to 9.2

comment:9 Changed 2 years ago by dmisev

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.

comment:10 Changed 2 years ago by dmisev

  • Summary changed from Use already existing rasdaman logging mechanism in rasnet to Replace rasdaman logging with easylogging

comment:11 Changed 23 months ago by dmisev

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.

comment:12 Changed 23 months ago by dmisev

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

comment:13 Changed 23 months ago by pbaumann

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.

comment:14 Changed 21 months ago by pbaumann

well done, just

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

comment:15 Changed 21 months ago by mdumitru

  • Resolution set to fixed
  • Status changed from assigned to closed

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

Note: See TracTickets for help on using tickets.