[sip-comm-dev] Activities to modify usage of logger.{debug,info,trace} messages


#1

Dear all,

in my last post to the list I've discussed that unguarded use of logger
method leads to quite some waste of resources. While this may not be a
problem for big desktops/laptop computer this may be an issue for smaller
computers.

I attach two per scripts that help to fix this issue. The checkLogger.pl
script locates all java files in a directory and checks for unguarded
and guarded logger calls. Th script looks for the following patterns:

Found as unguarded logger call (.info, .trace):

  logger.debug(...)

Found as guarded logger call:

  if (logger.isDebugDenabled())
      logger.debug(...)

Sometimes the code contains a pattern like this:

  if (logger.isDebugDenabled())
  {
      logger.debug(...)
  }

This is counted a unguarded (the script checks only one previous line).

The script shows the results:
...
WhiteboardSessionPacketExtension.java: info: 0/0, debug: 4/0, trace: 0/0
Global: info: 0/0, debug: 32/0, trace: 0/0
checkLogger found unprotected logger calls

A per-file summary, a global summary and an additional info line.
For example:

- in the java file the script found 4 unguarded logger.debug calls,
  0 guarded logger.debug call.

- All java file in the directory contained 32 unguarded logger.debug calls
  and 0 guarded logger.debug call.

The logger.pl script works the same way and fixed unguarded calls.
For example:

  logger.debug(...) becomes

  if (logger.isDebugEnabled())
      logger.debug(...)

Caveat: because of the limited parsing feature the construct

  if (logger.isDebugDenabled())
  {
      logger.debug(...)
  }

becomes

  if (logger.isDebugDenabled())
  {
      if (logger.isDebugEnabled())
          logger.debug(...)
  }

This does not do any harm. Most often the compiler eliminates (optimizes)
the second if. To find these constructs you may use the following command:

grep -B 3 'logger\.[dit][enr]' *.java

which displays the logger calls plus 3 lines before the matching line.
However, these constructs are not very often according to my experiences
so far.

I'm using these two scripts already to fix the java files in the
impl/protocol and its sub-directories (step by step of course :wink: ).

Have fun.

Regards,
Werner

checkLogger.pl (1.67 KB)

logger.pl (2 KB)


#2

Hey Werner,

Thanks for the update. I just have one question:

···

On Sun, May 30, 2010 at 2:52 PM, Werner Dittmann <Werner.Dittmann@t-online.de> wrote:

Caveat: because of the limited parsing feature the construct

if (logger.isDebugDenabled())
{
logger.debug(...)
}

becomes

if (logger.isDebugDenabled())
{
if (logger.isDebugEnabled())
logger.debug(...)
}

This does not do any harm. Most often the compiler eliminates (optimizes)
the second if. To find these constructs you may use the following command:

grep -B 3 'logger\.[dit][enr]' *.java

which displays the logger calls plus 3 lines before the matching line.
However, these constructs are not very often according to my experiences
so far.

Still, you are planning on removing them before committing, right? I
am asking because it would be a lot easier to do so now, before you
add all the if-s you are planning to, which would make it harder to
grep them.

Emil


#3

Emil,

Hey Werner,

Thanks for the update. I just have one question:

Caveat: because of the limited parsing feature the construct

if (logger.isDebugDenabled())
{
     logger.debug(...)
}

becomes

if (logger.isDebugDenabled())
{
     if (logger.isDebugEnabled())
         logger.debug(...)
}

This does not do any harm. Most often the compiler eliminates (optimizes)
the second if. To find these constructs you may use the following command:

grep -B 3 'logger\.[dit][enr]' *.java

which displays the logger calls plus 3 lines before the matching line.
However, these constructs are not very often according to my experiences
so far.

Still, you are planning on removing them before committing, right? I
am asking because it would be a lot easier to do so now, before you
add all the if-s you are planning to, which would make it harder to
grep them.

You mean if I plan to remove this constructs? Usually yes, maybe that some
will "slip thru" but I will remove most of them. This also gives a sort
of standard pattern for "logger.*" usage. That pattern may be use afterwards
to even locate logger.* usage cleanup the source from unwanted/not needed
logger calls (if this will become necessary).

I'm just working on some enhancements of my scripts to better detect more
patterns.

Also the scripts were meant to be used by others as well :wink: - not only by
me - to clean up. Best would be if the developer that knows his/her code uses
the scripts. They are meant as a sort of support, not as a silver bullet :slight_smile: .

Werner

···

Am 30.05.2010 16:28, schrieb Emil Ivov:

On Sun, May 30, 2010 at 2:52 PM, Werner Dittmann > <Werner.Dittmann@t-online.de> wrote:

Emil

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#4

Emil,

I've enhanced the logger usage check and fix scripts.

They now detect (and fix if necessary) different logger usage
scenarios. The scenario

  if (logger.isDebugDenabled())
  {
      logger.debug(...)
  }

is now detected and _not_ fixed because it is a guarded logger usage
already. The scripts also works if there are blank lines between '{'
and the logger.*(...) call.

I used some modified version of the checking script to get an idea about
how many logger calls (not counting logger.warn and logger.error) are in
use in SC. The result:

Global: info: 185/70, debug: 459/292, trace: 195/177

This line translates into:
           unguarded guarded
logger.info: 185 70
logger.debug: 459 292
logger.trace: 195 177

···

----------------------------
Grand total: 839 539

Many of the guarded logger calls are located in the files that were
fixed during the last activities.

During the next days (Thursday to Saturday) I plan to fix this step by
step if nobody objects (presentations anyone? :wink: )

Regards,
Werner

Am 30.05.2010 17:05, schrieb Werner Dittmann:

Emil,

Still, you are planning on removing them before committing, right? I
am asking because it would be a lot easier to do so now, before you
add all the if-s you are planning to, which would make it harder to
grep them.

You mean if I plan to remove this constructs? Usually yes, maybe that some
will "slip thru" but I will remove most of them. This also gives a sort
of standard pattern for "logger.*" usage. That pattern may be use afterwards
to even locate logger.* usage cleanup the source from unwanted/not needed
logger calls (if this will become necessary).

I'm just working on some enhancements of my scripts to better detect more
patterns.

Also the scripts were meant to be used by others as well :wink: - not only by
me - to clean up. Best would be if the developer that knows his/her code uses
the scripts. They are meant as a sort of support, not as a silver bullet :slight_smile: .

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#5

Dear all,

I've just committed the last bunch of changes of enhance usage of
the logger class. Now all usage of logger.{info,debug,trace} is
guarded and are called only if the logger level is set accordingly.

To get most out of these modification we shall adjust SC's
logging.properties file. Currently the setting is inconsistent
with respect to the logging level.

The default setting is ".FINEST". This level triggers full logging.
The setting of the outputs is ".INFO" and ".SEVERE". Thus the
debug and trace messages are not written to any output albeit much
of the overhead was already spent. My profiles show that debug and
trace calls outnumber info calls by a large degree.

My proposal: the standard logging level should be in sync with
the lowest output level, in our case this would be '.INFO'. For
a production release I would set both to ".WARN".

I'll check-in a modified logging.properties file that implements
the proposal.

Regards,
Werner

···

Am 01.06.2010 19:20, schrieb Werner Dittmann:

Emil,

I've enhanced the logger usage check and fix scripts.

They now detect (and fix if necessary) different logger usage
scenarios. The scenario

  if (logger.isDebugDenabled())
  {
      logger.debug(...)
  }

is now detected and _not_ fixed because it is a guarded logger usage
already. The scripts also works if there are blank lines between '{'
and the logger.*(...) call.

I used some modified version of the checking script to get an idea about
how many logger calls (not counting logger.warn and logger.error) are in
use in SC. The result:

Global: info: 185/70, debug: 459/292, trace: 195/177

This line translates into:
           unguarded guarded
logger.info: 185 70
logger.debug: 459 292
logger.trace: 195 177
----------------------------
Grand total: 839 539

Many of the guarded logger calls are located in the files that were
fixed during the last activities.

During the next days (Thursday to Saturday) I plan to fix this step by
step if nobody objects (presentations anyone? :wink: )

Regards,
Werner

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net