I have a simple proposal. write the granularity ad the beginning of each log message. Something like
LOG:TERSE blah blah
Then a couple of "greps" would make going through all the output less painful, wouldn't it?
I like it, let's check on the negative, anyone minds if we add this feature?
On Tue, Jul 3, 2012 at 3:51 PM, Javier Velazquez javi@salilab.org wrote:
> > I have a simple proposal. write the granularity ad the beginning of each > log message. Something like > > LOG:TERSE blah blah > > Then a couple of "greps" would make going through all the output less > painful, wouldn't it? > > ______________________________**_________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/**listinfo/imp-devhttps://salilab.org/mailman/listinfo/imp-dev >
I'm not sure I see the problem this is supposed to solve. And it would make often already long log lines even longer and harder to scan visually since the prefix is no longer meaningful. What is a scenario when you want to use this?
And why add the log level part? The context lines can't be readily tagged with the log level since there can be messages with several different levels within a different context (and they aren't all known when the line is produced). And I think it is too much information to stick all into one line. So I see that we can set it up so that you can get something that looks like WARN level output when running in TERSE. In addition, running things with VERBOSE slows runtimes down rather noticeably, so I'm not sure you would want to do that routinely while only looking at terse messages, for example.
On the implementation side, log messages are already scanned for newlines and indentation prefixes inserted, so adding other prefixes is easy.
On Jul 3, 2012, at 3:51 PM, Javier Velazquez wrote:
> > I have a simple proposal. write the granularity ad the beginning of each log message. Something like > > LOG:TERSE blah blah > > Then a couple of "greps" would make going through all the output less painful, wouldn't it? > > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev
Daniel, What exactly is the context? I guess this is what I really had in mind personally, but I'm not 100% sure what you mean by it, or how to use it (couldn't find any ref to it in the man page on logging). Is it someway of getting to know in which context a log message from a certain class was called? Is it possible to mute certain contexts in runtime (e.g., now I don't want to see logging from this class but only from that class, etc.). Barak
On Thu, Jul 5, 2012 at 7:10 AM, Daniel Russel drussel@gmail.com wrote:
> I'm not sure I see the problem this is supposed to solve. And it would > make often already long log lines even longer and harder to scan visually > since the prefix is no longer meaningful. What is a scenario when you want > to use this? > > And why add the log level part? The context lines can't be readily tagged > with the log level since there can be messages with several different > levels within a different context (and they aren't all known when the line > is produced). And I think it is too much information to stick all into one > line. So I see that we can set it up so that you can get something that > looks like WARN level output when running in TERSE. In addition, running > things with VERBOSE slows runtimes down rather noticeably, so I'm not sure > you would want to do that routinely while only looking at terse messages, > for example. > > On the implementation side, log messages are already scanned for newlines > and indentation prefixes inserted, so adding other prefixes is easy. > > On Jul 3, 2012, at 3:51 PM, Javier Velazquez wrote: > > > > > I have a simple proposal. write the granularity ad the beginning of each > log message. Something like > > > > LOG:TERSE blah blah > > > > Then a couple of "greps" would make going through all the output less > painful, wouldn't it? > > > > _______________________________________________ > > IMP-dev mailing list > > IMP-dev@salilab.org > > https://salilab.org/mailman/listinfo/imp-dev > > > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev >
The way I would use it is to write everything with VERBOSE mode and then start doing greps until I reach the interesting level, also for hopping between same tags. It will avoid me reading lines and lines of non-relevant material because I don't know where the important part is.
On 7/5/12 8:34 AM, Barak Raveh wrote: > Daniel, > What exactly is the context? I guess this is what I really had in mind > personally, but I'm not 100% sure what you mean by it, or how to use > it (couldn't find any ref to it in the man page on logging). Is it > someway of getting to know in which context a log message from a > certain class was called? Is it possible to mute certain contexts in > runtime (e.g., now I don't want to see logging from this class but > only from that class, etc.). > Barak > > On Thu, Jul 5, 2012 at 7:10 AM, Daniel Russel <drussel@gmail.com > mailto:drussel@gmail.com> wrote: > > I'm not sure I see the problem this is supposed to solve. And it > would make often already long log lines even longer and harder to > scan visually since the prefix is no longer meaningful. What is a > scenario when you want to use this? > > And why add the log level part? The context lines can't be readily > tagged with the log level since there can be messages with several > different levels within a different context (and they aren't all > known when the line is produced). And I think it is too much > information to stick all into one line. So I see that we can set > it up so that you can get something that looks like WARN level > output when running in TERSE. In addition, running things with > VERBOSE slows runtimes down rather noticeably, so I'm not sure you > would want to do that routinely while only looking at terse > messages, for example. > > On the implementation side, log messages are already scanned for > newlines and indentation prefixes inserted, so adding other > prefixes is easy. > > On Jul 3, 2012, at 3:51 PM, Javier Velazquez wrote: > > > > > I have a simple proposal. write the granularity ad the beginning > of each log message. Something like > > > > LOG:TERSE blah blah > > > > Then a couple of "greps" would make going through all the output > less painful, wouldn't it? > > > > _______________________________________________ > > IMP-dev mailing list > > IMP-dev@salilab.org mailto:IMP-dev@salilab.org > > https://salilab.org/mailman/listinfo/imp-dev > > > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org mailto:IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev > > > > > -- > Barak > > > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev
When a log message is printed out you get something like Model::evaluate MyRestraint::evaluate Found a fit with orientation X another message end MyRestraint::evaluate end Model::evaluate
As for controlling what gets printed, each thing derived from IMP::base::Object has its own log level. This should be used to control the logging of every method on the object (and methods called by them that don't have something else setting their log level). Doing this requires an IMP_OBJECT_LOG macro invocation at the start of the method which has some cost (both in terms of putting the line in and at runtime), so not all methods have it. I tend to put it in the methods that are more than ~10 lines in the objects I write.
You can also use SetLogState raii objects to locally control the logging produced (eg disable it for some part of your code).
On Jul 5, 2012, at 8:34 AM, Barak Raveh wrote:
> Daniel, > What exactly is the context? I guess this is what I really had in mind personally, but I'm not 100% sure what you mean by it, or how to use it (couldn't find any ref to it in the man page on logging). Is it someway of getting to know in which context a log message from a certain class was called? Is it possible to mute certain contexts in runtime (e.g., now I don't want to see logging from this class but only from that class, etc.). > Barak > > On Thu, Jul 5, 2012 at 7:10 AM, Daniel Russel drussel@gmail.com wrote: > I'm not sure I see the problem this is supposed to solve. And it would make often already long log lines even longer and harder to scan visually since the prefix is no longer meaningful. What is a scenario when you want to use this? > > And why add the log level part? The context lines can't be readily tagged with the log level since there can be messages with several different levels within a different context (and they aren't all known when the line is produced). And I think it is too much information to stick all into one line. So I see that we can set it up so that you can get something that looks like WARN level output when running in TERSE. In addition, running things with VERBOSE slows runtimes down rather noticeably, so I'm not sure you would want to do that routinely while only looking at terse messages, for example. > > On the implementation side, log messages are already scanned for newlines and indentation prefixes inserted, so adding other prefixes is easy. > > On Jul 3, 2012, at 3:51 PM, Javier Velazquez wrote: > > > > > I have a simple proposal. write the granularity ad the beginning of each log message. Something like > > > > LOG:TERSE blah blah > > > > Then a couple of "greps" would make going through all the output less painful, wouldn't it? > > > > _______________________________________________ > > IMP-dev mailing list > > IMP-dev@salilab.org > > https://salilab.org/mailman/listinfo/imp-dev > > > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev > > > > -- > Barak > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev
I can only suggest to make it even longer :) it is helpful to print the time before the log level, something like this:
00:00:07.78| INFO: Clustered transforms size: 785 00:00:07.78| DEBUG: found trans with RMSD: 2.30 -0.18 0.07 -0.19 -1.23 1.71 1.52
it gives you an idea where the time is spent. I know you can easily get it from profiling, but you don't run profiler on every run, so this is very helpful to keep you aware of run times.
also I wouldn't worry about long lines, that's what we have big monitors for :)
On Thu, Jul 5, 2012 at 10:04 AM, Daniel Russel drussel@gmail.com wrote: > When a log message is printed out you get something like > Model::evaluate > MyRestraint::evaluate > Found a fit with orientation X > another message > end MyRestraint::evaluate > end Model::evaluate > > As for controlling what gets printed, each thing derived from > IMP::base::Object has its own log level. This should be used to control the > logging of every method on the object (and methods called by them that don't > have something else setting their log level). Doing this requires an > IMP_OBJECT_LOG macro invocation at the start of the method which has some > cost (both in terms of putting the line in and at runtime), so not all > methods have it. I tend to put it in the methods that are more than ~10 > lines in the objects I write. > > You can also use SetLogState raii objects to locally control the logging > produced (eg disable it for some part of your code). > > On Jul 5, 2012, at 8:34 AM, Barak Raveh wrote: > > Daniel, > What exactly is the context? I guess this is what I really had in mind > personally, but I'm not 100% sure what you mean by it, or how to use it > (couldn't find any ref to it in the man page on logging). Is it someway of > getting to know in which context a log message from a certain class was > called? Is it possible to mute certain contexts in runtime (e.g., now I > don't want to see logging from this class but only from that class, etc.). > Barak > > On Thu, Jul 5, 2012 at 7:10 AM, Daniel Russel drussel@gmail.com wrote: >> >> I'm not sure I see the problem this is supposed to solve. And it would >> make often already long log lines even longer and harder to scan visually >> since the prefix is no longer meaningful. What is a scenario when you want >> to use this? >> >> And why add the log level part? The context lines can't be readily tagged >> with the log level since there can be messages with several different levels >> within a different context (and they aren't all known when the line is >> produced). And I think it is too much information to stick all into one >> line. So I see that we can set it up so that you can get something that >> looks like WARN level output when running in TERSE. In addition, running >> things with VERBOSE slows runtimes down rather noticeably, so I'm not sure >> you would want to do that routinely while only looking at terse messages, >> for example. >> >> On the implementation side, log messages are already scanned for newlines >> and indentation prefixes inserted, so adding other prefixes is easy. >> >> On Jul 3, 2012, at 3:51 PM, Javier Velazquez wrote: >> >> > >> > I have a simple proposal. write the granularity ad the beginning of each >> > log message. Something like >> > >> > LOG:TERSE blah blah >> > >> > Then a couple of "greps" would make going through all the output less >> > painful, wouldn't it? >> > >> > _______________________________________________ >> > IMP-dev mailing list >> > IMP-dev@salilab.org >> > https://salilab.org/mailman/listinfo/imp-dev >> >> >> _______________________________________________ >> IMP-dev mailing list >> IMP-dev@salilab.org >> https://salilab.org/mailman/listinfo/imp-dev > > > > > -- > Barak > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev > > > > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev >
On 7/5/12 10:38 AM, Dina Schneidman wrote: > I can only suggest to make it even longer :) > it is helpful to print the time before the log level
If you want that, just call set_log_timer(true).
Ben
I should :)
On Thu, Jul 5, 2012 at 10:48 AM, Ben Webb ben@salilab.org wrote: > On 7/5/12 10:38 AM, Dina Schneidman wrote: >> >> I can only suggest to make it even longer :) >> it is helpful to print the time before the log level > > > If you want that, just call set_log_timer(true). > > Ben > -- > ben@salilab.org http://salilab.org/~ben/ > "It is a capital mistake to theorize before one has data." > - Sir Arthur Conan Doyle > > _______________________________________________ > IMP-dev mailing list > IMP-dev@salilab.org > https://salilab.org/mailman/listinfo/imp-dev
participants (6)
-
Barak Raveh -
Ben Webb -
Daniel Russel -
Dina Schneidman -
Javier Velazquez -
Javier Velazquez-Muriel