ffc team mailing list archive

[Johan Hake <hake@xxxxxxxxx>]

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? 

> 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."

> 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.

Johan

> --
> Anders
>
> > > > > 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