Subject: [FFC-dev] Add output method to ufl.log.begin?

From: Johan Hake <[email-masked]>
Date: Mon, 17 Aug 2009 12:57:47 +0200

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

---

From: Anders Logg <[email-masked]>
Date: Mon, 17 Aug 2009 13:23:16 +0200

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.

--
Anders

On Mon, Aug 17, 2009 at 12:57:47PM +0200, Johan Hake wrote:
> _______________________________________________
> FFC-dev mailing list
> [email-masked]
> http://www.fenics.org/mailman/listinfo/ffc-dev

---

From: Johan Hake <[email-masked]>
Date: Mon, 17 Aug 2009 13:46:21 +0200

> push_level(WARNING) before calling the code generation, then

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

> > or if this is too verbose, provide a set_begin_level, which the begin
> > function could use. With alternative 1 we have:
> >

---

From: Anders Logg <[email-masked]>
Date: Mon, 17 Aug 2009 14:09:50 +0200

> I have done some work in this direction already. I can hand a patch if this is

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.

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.

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

--
Anders

---

From: Johan Hake <[email-masked]>
Date: Mon, 17 Aug 2009 14:27:35 +0200

On Monday 17 August 2009 14:09:50 Anders Logg wrote:
> > 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
>

Ok, I didn't anticipate this

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

>   push_level(min(WARNING, options["log_level"] + 10))

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 ;) )

Johan

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

---

From: Anders Logg <[email-masked]>
Date: Mon, 17 Aug 2009 14:39:49 +0200

> the function and let that be a constant that is set differently using jit and

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

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

--
Anders

---

From: Johan Hake <[email-masked]>
Date: Mon, 17 Aug 2009 15:07:31 +0200

On Monday 17 August 2009 14:39:49 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.
> > > >
> > > > 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.
> > > >
> > > > I have done some work in this direction already. I can hand a patch
> > > > if this is what we want.
> > > >
> > > > Johan
> > >
> > 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.
>

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)

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.

> > 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 ;) )
>

Yes, I see this.

Johan

> > > > > > end() statements in ffc.analyze_form. As it is now begin just
> > > > > > uses info when it present the information.
> > > > > >
> > > > > > 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 2: Computing form
> > > > > > representation(s)") debug("Jada")
> > > > > >   debug("Bada")
> > > > > >   end()
> > > > > >
> > > > > >   ...
> > > > > >

---

From: Anders Logg <[email-masked]>
Date: Mon, 17 Aug 2009 16:08:22 +0200

>   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

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

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.

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.

--
Anders

---

From: Johan Hake <[email-masked]>
Date: Mon, 17 Aug 2009 16:27:11 +0200

On Monday 17 August 2009 16:08:22 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.
> > > > > >
> > > > > > 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.
> > > >
> > > > > 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.
> > >
> > when we want to make the level of the messages configurable within a
> > library. These function just call:
> >

Hmm, I was afraid this was the case.

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

I do not get this. Should these two lines only differ in the last two words? 

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

> 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

> > > > 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 ;) )
> > >
> > > > > > > > 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.
> > > > > > > >
> > > > > > > > or if this is too verbose, provide a set_begin_level, which
> > > > > > > > the begin function could use. With alternative 1 we have:
> > > > > > > >

---

From: Anders Logg <[email-masked]>
Date: Mon, 17 Aug 2009 17:16:14 +0200

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

> +++ b/ufl/log.py        Mon Aug 17 16:24:41 2009 +0200

Thanks. I'll add it.

> set_log_level(options['log_level']) in jit_form somwhere.

Great. I'll try to get this working.

--
Anders