Replace all the dbgprt in the pattern matcher code by fine logging

[ngeiswei]

It's all in the title. It's not convenient to uncomment DEBUG macros. And it's clearly something that is being done often.

[linas]

the problem with fine logging is that it hurts performance significantly. We really should turn both fine logging and debug logging into compile-time functions, so that no code is generated if they are disabled.

The other problem with the design of the logger is that you cannot turn it on only for some modules, but not others. Typically, you don't want to turn on debugging for everything, but only for the system that you are actually debugging at the moment.

I conclude: to make the logger actually useful, it needs to be radically redesigned; right now, its just not really usable. I usally avoid using it for exactly this reason: the #ifdef DEBUG method is much easier to use, and much more powerful, that the Logger class.

So: do NOT convert to fine logging until the Logger class is fixed so that its .. well, not totally broken.

[linas]

If I remember correctly, the glib libraries had a fairly flexible logging system (glib from gnome/gtk). I do not recall if it was a compile-time option, though. I'm guessing KDE has one too. Perhaps there is some other industry-standard logger maybe in boost, that is more sophisticated than what we have.

[linas]

Anyway, swithcng to a higher-quality logger would not avoid the need to #define DEBUG, since you would still need to leave it turned off for the normal, non-debug case.

[ngeiswei]

Agreed, switching to more powerful logging system would be good.

Regarding performances, I usually use conditionals with logger().isFineEnabled() to only execute the logging code if it has any computational load.

Being able to unable or disable at run-time is a good thing as it prevents from wasting time recompiling, but sure only if that doesn't introduce an overhead.

All that said, I find myself enabling/disabling PM debugs very often, I would personally find it more convenient to use the logging system, however limited it currently is, assuming it doesn't introduce any performance overhead, of course.

Anyway, I don't have time to do that now, and yeah, maybe it's about time to move to a better logging system.

[linas]

I'm surprised .. why would you ever need to enable debug on the pattern matcher?

[linas]

(much less "very often")

[ngeiswei]

I don't know if that was meant to be a joke, but the URE relies enormously on the PM, debugging the URE often entails knowing what the PM does.

[linas]

Not a joke. I cannot imagine how tracing the PM can help debug the URE in any way. Why would you even care? The PM gives you an answer; are you concerned that the answer is wrong? How does tracing it provide you with new knowledge? Why would the operation of it's internals affect you?

[ngeiswei]

@linas (and others), we really need a convenient way to log what the pattern matcher is doing. I've needed to do that for nearly every rule I've coded.

Enabling DEBUG here and there that print messages on the stdout isn't convenient, you need to search the DEBUG defines, comment out code, recompile, and then you get stuff printed in the stdout that you can relate to the logging messages of the other components like the URE, etc.

I agree that our logging system is too limited but it's still better than printing debug messages on the stdout. Regarding performance, using logger().isEnabled(), one can avoid the run-time overhead. Of course, if I'm to do that I'll test performance before and after, to be sure I'm not introducing any overhead.

Alternatively, I've been looking at boost log

http://www.boost.org/doc/libs/1_55_0/libs/log/doc/html/log/tutorial/trivial_filtering.html

Notice the " Remember that the streaming expression is only executed if the record passed filtering. Don't specify business-critical calls in the streaming expression, as these calls may not get invoked if the record is filtered away. " Meaning that when disabled it shouldn't affect performance. I bet it also has the other goodies you mentions (filter by components, etc). But we already have important things on our plates, I don't think anybody here is ready to spend 2 weeks of her time to integrate a new logger... (though maybe we should do that).

[ngeiswei]

Regarding logging per components, here what we used to do with the old embodiment, each log message has the name of the component in it, so if the message concerns the pattern matcher the message would look like

<time> [PM] My message about PM

if it's about the URE, the message would look like

<time> [URE] My message about the URE

after than we had in the scripts folder a scripts to grep the log and filter only what one is looking for. Basically something like

grep '<regex for time> [PM]'

to see only the message about the pattern matcher.

What do you say, are you excited by our current logger now? ;-)

[linas]

As you wish, none of this matches up very much with my workflow.

[linas]

See note on pull req #343. I have been living with this change for a while now, and every time I have to use it, I curse. It is (a) hard to use and (b) mangles the debug messages. I am about ready to revert; maybe this sounded like a good idea, but in practice it is just another pain-point making development just that much harder than it needs to be.

[linas]

In fact, I'm reverting now. Its nonsense, and I just don't want to put up with it any longer.

[ngeiswei]

Wowowo, this change has made my life so much easier, there is definitely something contradictory in the way we debug, please explain what is so non-sense.

Just do

(cog-logger-set-stdout #t)

if you want the log to be printed as before. On top of that it supports scheme string format. I mean this stuff is just awesome for debugging, I'm really puzzled!!!

[ngeiswei]

@linas Here's what I suggest, you add a macro so that the messages are printed to the stdout instead of being fed to the log. In any case to use the previous implementation you'd have to enable a macro at compile time, so it won't make any difference for you. But for guys like me, who enjoy not to have to recompile in order to enable debugging message (you're in the guile shell, you think "oh shit, I'd like to know what's going on, let's set a finer log level"), no need to quite the shell, no need to look into another file if you really don't want to, it's awesome, but anyway. Feel free to add what you're comfortable with, but please don't take the current functionality away.

[linas]

I recompile 30 or 40 times a day. Recompiling is not a problem. What is a problem is having to cut-n-paste magic incantations every time I want to debug.

Its also a hassle when there are other components doing fine logging, e.g the cogsever, they spew and everything just scrolls off the screen before you can even see the output. So you have to locate these OTHER loggers, and disable them, and then recompile anyway, hope you got them all, and do this 2-3 times.

So, instantly you loose half an hour just trying to get logging to behave,before you can even use it once.

And this happens every time; so if you push to git, you have to undo the changes, and redo them. Half an hour just to get started. and 3 or 4 recompiles. Its a total waste of time.

On Wed, Dec 23, 2015 at 6:24 PM, ngeiswei notifications@github.com wrote:

@linas https://github.com/linas Here's what I suggest, you add a macro so that the messages are printed to the stdout instead of being fed to the log. In any case to use the previous implementation you'd have to enable a macro at compile time, so it won't make any difference for you. But for guys like me, who enjoy not to have to recompile in order to enable debugging message (you're in the guile shell, you think "oh shit, I'd like to know what's going on, let's set a finer log level"), no need to quite the shell, no need to look into another file if you really don't want to, it's awesome, but anyway. Feel free to add what you're comfortable with, but please don't take the current functionality away.

— Reply to this email directly or view it on GitHub https://github.com/opencog/atomspace/issues/147#issuecomment-167013066.

[ngeiswei]

Regarding the incantations hard to remember, the logger scheme doc is here

http://wiki.opencog.org/wikihome/index.php/Scheme#Logger

it's not enough though, I'll fix that soon.

Regarding the C++ ones, I guess maybe I could put a wiki page for it, would that make it more convenient?

Now regarding pattern matcher logging. I agree the situation is not ideal, I still prefer to use the imperfect logging system than stdout prints, but I can understand you'd disagree. I stand by my first suggestion, change it to make it as easy as you find it to use, but please let the existing functionality in place. If that isn't possible, let's discuss and find a compromise.