Opened 3 years ago

Closed 3 years ago

#707 closed defect (fixed)

log file output too verbose

Reported by: pbaumann Owned by: vliaukevich
Priority: minor Milestone:
Component: wiki Version: development
Keywords: Cc: dmisev
Complexity: Easy


Log output is containing internal debug output sometimes. In operational installations, this may flood the log file and create excessive file sizes.

Example (bold face is considered excessive):
[2014-03-18 12:57:25] request from
Request: 'insert into hdfTest values inv_hdf(#MDD0#, "sampletype=ushort")'...parsing...checking semantics...
QtConversion::checkType() for conversion inv_hdf assume the result marray <char>
evaluating...Error: in conversion factory during create: unsupported format: CVS
Error: QtConversion::evaluate(): conversion failed
Error: cannot parse query (1).
Error number: 381 Token: inv_hdf Line: 1 Column: 28
[2014-03-18 12:57:25] request completed in 1230 usecs.

Change History (14)

comment:1 Changed 3 years ago by vliaukevich

About last two bold lines in the example:
At least it makes sense to log only the first message in the place where the exception was thrown, as it is likely to be most informative (not just "conversion failed").

comment:2 Changed 3 years ago by vliaukevich

I found few situations, when an operation fails without logging the reason, but it throws an error with an appropriate error code, so that a client could see the reason of the failure. Is it okay or such failures should be also logged?
(Examples: "access denied, no permission", "Number of cells specified does not match the number of cells of the given spatial domain.")

Additionally, the major part of log files is messages about creating connections, transaction opening/closing, getting next tiles and MDDs. Maybe it would be better to reduce number of such messages as well?

comment:3 Changed 3 years ago by dmisev

I agree that all errors/warnings should be traceable in the logs as well.

Not sure about the second question, personally I have not found those messages about connection/transaction/etc. too useful.

comment:4 Changed 3 years ago by vliaukevich

We can log connections/transactions/etc only in case of their failure in normal installations, and report their correct behaviour in debug installations (via RMDB* macroses).

comment:5 Changed 3 years ago by pbaumann

what we trace actually is a second discussion. I was simply on syntactical level: the log contains output generated by trace macros. Probably someone has built another "private" logging facility that is statically enabled and disabled, rathern than using one of rmdebug.hh or debug.hh.

If anything needs to be converted from a -DDEBUG enabled trace to regular error/warning then this needs to conform with the standard type of output: one line, no function or "ENTER" prefix, etc.

In any case, output should be short and kept to an absolute minimum to avoid log flooding. Consider millions of requests coming in!

comment:6 Changed 3 years ago by dmisev

The benchmark measurements seem to be completely gone now from the log, can we return at least the query request time? It's useful to have this in the log, especially as it adds a timestamp as well. E.g.

[2014-03-18 12:57:25] request completed in 1230 usecs.
Last edited 3 years ago by dmisev (previous) (diff)

comment:7 Changed 3 years ago by vliaukevich

This information is still available with "--enable-debug".

Right now this "request completed in usecs" message is reported in a function, which doesn't have information about what type of request it processes, so such messages appear for all "open DB", "open TA", "getNextTile" requests together with actual queries times. Of course, it could be changed if we want to see timing reports for only part of requests (which part?).

comment:8 Changed 3 years ago by pbaumann

indeed, this is at a place where we have few control over selective output.
What about redesigning this into the forthcoming new c/s protocol in a place which is more suitable?

comment:9 Changed 3 years ago by vliaukevich

What is the c/s protocol?

comment:10 Changed 3 years ago by pbaumann

sorry for the slang; c/s = client-server; currently, we use RNP, and we will replace it by something more modern.

comment:11 Changed 3 years ago by dmisev

I think one timer for how much it takes to evaluate the query (somewhere in servercommm I believe), should be enough. The rest can be enabled only in debug mode, that is fine.

comment:12 Changed 3 years ago by pbaumann

hm, we we have 2 switches, for debug and timing (--enable-benchmark), why not use them in this sense. Mixing both (i) generates tons of output, hard to analyze and (ii) slows down performance due to the large log activity.
So suggesting to output all timers with --enable-benchmark.

Last edited 3 years ago by pbaumann (previous) (diff)

comment:13 Changed 3 years ago by dmisev

These lines should not be in the default non-debug output, they appear on insert:

QtInsert::evaluate() - allocated oid:71169 counter:139
QtInsert::evaluate() - returning oid:71169

comment:14 Changed 3 years ago by dmisev

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

I tested both modes and it all looks good, so closing the ticket.

Note: See TracTickets for help on using tickets.