ffc team mailing list archive

[Anders Logg <logg@xxxxxxxxx>]

On Mon, Aug 17, 2009 at 04:27:11PM +0200, Johan Hake wrote:
> On Monday 17 August 2009 16:08:22 Anders Logg wrote:
> > On Mon, Aug 17, 2009 at 03:07:31PM +0200, Johan Hake wrote:
> > > On Monday 17 August 2009 14:39:49 Anders Logg wrote:
> > > > On Mon, Aug 17, 2009 at 02:27:35PM +0200, Johan Hake wrote:
> > > > > On Monday 17 August 2009 14:09:50 Anders Logg wrote:
> > > > > > On Mon, Aug 17, 2009 at 01:46:21PM +0200, Johan Hake wrote:
> > > > > > > On Monday 17 August 2009 13:23:16 Anders Logg wrote:
> > > > > > > > Fixed. I've set the log level to INFO in the JIT compiler, and
> > > > > > > > then do push_level(WARNING) before calling the code generation,
> > > > > > > > then pop_level.
> > > > > > >
> > > > > > > Nice, but I wonder if this is a hack more than a fix ;)
> > > > > > >
> > > > > > > It circumvent the whole log system, by forcing the log level to
> > > > > > > be at a certain level, without possibility for the user to
> > > > > > > control it. Now I cannot get rid of the message by altering the
> > > > > > > log level. We should at least use option["log_level"] when the
> > > > > > > setting the log level for jit_form.
> > > > > > >
> > > > > > > My fix lets the begin message be level conscious, and then we
> > > > > > > have to change all info("") call in the sub routines of
> > > > > > > analyze_form to debug("").
> > > > > > >
> > > > > > > I have done some work in this direction already. I can hand a
> > > > > > > patch if this is what we want.
> > > > > > >
> > > > > > > Johan
> > > > > >
> > > > > > I guess the problem is that what is considered as normal output
> > > > > > when running from the command-line is verbose when running in JIT
> > > > > > mode.
> > > > >
> > > > > Ok, I didn't anticipate this
> > > > >
> > > > > > So what is normally printed on the INFO level should be moved to
> > > > > > the DEBUG level, but only when running in JIT mode. I don't know
> > > > > > how to do this, but changing the log level has much the same
> > > > > > effect.
> > > > >
> > > > > We could add a log function to ufl.log, which do the same as
> > > > > logging.log. It takes a level argument as first argument. We could
> > > > > also skip the argument to the function and let that be a constant
> > > > > that is set differently using jit and from the command line.
> > > >
> > > > How would this help? The problem as I see it is that the user (of the
> > > > JIT function through DOLFIN) wants to print INFO messages, but
> > > > disagrees with FFC about what constitutes INFO messages and thinks
> > > > that FFC INFO messages should really be DEBUG messages.
> > > >
> > > > So the user would need something like
> > > >
> > > >   set_offset(10)
> > > >
> > > > which would move all messages up one level (in particular from INFO to
> > > > DEBUG) so that INFO messages are not printed when the INFO level is
> > > > set...
> > >
> > > That's the point of using logging.log instead of
> > >
> > >   logging.debug("Foo"), logging.info("Bar")
> > >
> > > when we want to make the level of the messages configurable within a
> > > library. These function just call:
> > >
> > >   loggin.log(DEBUG,"Foo"), logging.log(INFO,"Bar")
> > >
> > > anyway.
> > >
> > > The DEBUG and INFO levels here could be set within the library using a
> > > constant that is different for jit and from command line. For example:
> > >
> > >   set_internal_log_level(INFO/DEBUG)
> >
> > The problem here is that FFC itself wants to print messages which are
> > sometimes INFO and sometimes DEBUG.
> >
> > Then we would need something like
> >
> >   set_internal_info_log_level(WARNING/INFO/DEBUG)
> >   set_internal_debug_log_level(WARNING/INFO/DEBUG)
> >   etc
>
> Hmm, I was afraid this was the case.
>
> > > for comandline and jit use respectively. We could also add
> > > {push,pop}_internal_log_level too?
> > >
> > > Then the user can control which level a handler should be set to. The
> > > handler is the one that take care of the message.
> > >
> > > A general rule could be:
> > > We use debug, and info in the library when the "library knows" what level
> > > the message should be presented with, but log, when the level should be
> > > controlled by a by the internal_log_level.
> >
> > What the library knows is that some messages are more important than
> > others and thus uses INFO for some and DEBUG for some. It never really
> > knows the level it should be, just that some are more important than
> > others. Then it's the responsibility of the user to set which level
> > should be printed.
> >
> > So perhaps the following is a good solution:
> >
> >   The FFC compile command prints messages at level INFO  (=20)
> >   The FFC compile command prints messages at level DEBUG (=10)
>
> I do not get this. Should these two lines only differ in the last two words?

Yes. I meant that FFC does both things (printing INFO and DEBUG
messages). But it was a confusing way to say it.

> > When the compile command is called from jit, the compile command wants
> > to print messages which are even more important than the stuff the
> > compile command prints. So perhaps the best solution would be for the
> > jit command to print things at an even higher level, something like
> > level 25. A user calling the jit command with level INFO would then
> > see both the internal INFO stuff (level 20) and the more important
> > level 25 stuff. To see only the very important stuff ("Calling FFC JIT
> > compiler..."), the level would need to be raised to 25.
>
> Sounds good. This should be possible if we add the ufl.log function and use
> this to print the "Calling FFC JIT compiler..." stuff. The diff for this
> stuff:
>
> --- a/ufl/log.py        Fri Jun 19 13:31:22 2009 +0200
> +++ b/ufl/log.py        Mon Aug 17 16:24:41 2009 +0200
> @@ -74,6 +74,10 @@
>
>      def get_logfile_handler(self, filename):
>          return self._logfiles[filename]
> +
> +    def log(self, level, *message):
> +        "Write a log message with provided level"
> +        self._log.log(level, self._format(*message))
>
>      def debug(self, *message):
>          "Write debug message."

Thanks. I'll add it.

> > This way, we don't mess with the level and FFC prints messages at the
> > same level as it does on the command-line. Only DOLFIN would need to
> > raise the debug level to 25 since DOLFIN is not really interested in
> > seeing all the text FFC spits out.
>
> Sounds good. This should be doable by PyDOLFIN setting option["log_level"] =
> 25, in dolfin/jit.py, before it calls jit, and then add
> set_log_level(options['log_level']) in jit_form somwhere.

Great. I'll try to get this working.

--
Anders


> Johan
>
> >
> > > > > > How about this:
> > > > > >
> > > > > >   set_level(options["log_level"])
> > > > > >
> > > > > >   info("Calling FFC JIT compiler...")
> > > > > >
> > > > > >   push_level(min(WARNING, options["log_level"] + 10))
> > > > > >
> > > > > >   compile()
> > > > > >
> > > > > >   pop_level()
> > > > > >
> > > > > >   info("Done")
> > > > >
> > > > > Even if I see the features of {push,pop}_level, I think it is
> > > > > somewhat abusive to use them in a library as they prevent the user to
> > > > > control the level. (I want be a zealous about it ;) )
> > > >
> > > > It doesn't prevent the user from setting the level. It just makes the
> > > > best of the situation. The user just gives one input for log level,
> > > > which is used (or should be used) when printing
> > > >
> > > >   "Calling FFC JIT compiler..."
> > > >
> > > > Then another level is needed for the other stuff that goes on inside
> > > > this call and the JIT compiler then makes a guess that the user is not
> > > > really interested and so treats these as DEBUG messages (or sets the
> > > > level to WARNING so that INFO is ignored).
> > >
> > > Yes, I see this.
> > >
> > > Johan
> > >
> > > > > Johan
> > > > >
> > > > > > > > On Mon, Aug 17, 2009 at 12:57:47PM +0200, Johan Hake wrote:
> > > > > > > > > Hello!
> > > > > > > > >
> > > > > > > > > I want to get back the nice
> > > > > > > > >
> > > > > > > > >   "Calling FFC just-in-time (JIT) compiler, this may take
> > > > > > > > > some time..."
> > > > > > > > >
> > > > > > > > > message when jit compiling a form. I see that when I add a
> > > > > > > > >
> > > > > > > > >   set_log_level(INFO)
> > > > > > > > >
> > > > > > > > > in jit_form I get a bunch of uninteresting information:
> > > > > > > > >
> > > > > > > > > Compiler stage 1: Analyzing form
> > > > > > > > > --------------------------------
> > > > > > > > >
> > > > > > > > > Compiler stage 2: Computing form representation(s)
> > > > > > > > > --------------------------------------------------
> > > > > > > > >   Computing quadrature representation.
> > > > > > > > >
> > > > > > > > > ...
> > > > > > > > >
> > > > > > > > > After some research I found out that this comes from the
> > > > > > > > > begin(), end() statements in ffc.analyze_form. As it is now
> > > > > > > > > begin just uses info when it present the information.
> > > > > > > > >
> > > > > > > > > Could we let begin take a level, like:
> > > > > > > > >
> > > > > > > > >   begin(DEBUG,"Compiler stage 1: Analyzing form")
> > > > > > > > >
> > > > > > > > > or if this is too verbose, provide a set_begin_level, which
> > > > > > > > > the begin function could use. With alternative 1 we have:
> > > > > > > > >
> > > > > > > > >   begin(DEBUG,"Compiler stage 1: Analyzing form")
> > > > > > > > >   debug("Jada")
> > > > > > > > >   debug("Bada")
> > > > > > > > >   end()
> > > > > > > > >
> > > > > > > > >   begin(DEBUG,"Compiler stage 2: Computing form
> > > > > > > > > representation(s)") debug("Jada")
> > > > > > > > >   debug("Bada")
> > > > > > > > >   end()
> > > > > > > > >
> > > > > > > > >   ...
> > > > > > > > >
> > > > > > > > > and with alternative 2 we have:
> > > > > > > > >
> > > > > > > > >   set_begin_level(DEBUG)
> > > > > > > > >   begin("Compiler stage 1: Analyzing form")
> > > > > > > > >   debug("Jada")
> > > > > > > > >   debug("Bada")
> > > > > > > > >   end()
> > > > > > > > >
> > > > > > > > >   begin("Compiler stage 2: Computing form representation(s)")
> > > > > > > > >   debug("Jada")
> > > > > > > > >   debug("Bada")
> > > > > > > > >   end()
> > > > > > > > >
> > > > > > > > >
> > > > > > > > > I go for alternative 1.
> > > > > > > > >
> > > > > > > > > Johan
> > > > > > > > > _______________________________________________
> > > > > > > > > FFC-dev mailing list
> > > > > > > > > FFC-dev@xxxxxxxxxx
> > > > > > > > > http://www.fenics.org/mailman/listinfo/ffc-dev

Attachment: signature.asc
Description: Digital signature