[PATCH] Avoid string interpolation in logging calls

[Alex Willmer <al.willmer@…>]

When using Python's stdlib logging it's better to delegate string formatting to the loggging package - rather than use %-interpolation directly. This saves a few CPU cycles when the configured log level would discard that log message. Instead of

self.log.debug("Sendmail command line: %s" % cmdline)

use

self.log.debug("Sendmail command line: %s", cmdline)

Attached is a patch to fix this in 0.12.x. If theres interest I can update for 1.0.x and trunk.

[Christian Boos]

Thanks for the patch! Looks like a no-brainer.

I see that there's a log.isEnabledFor which I was not familiar with, but this seems to be supported in Python 2.4, so no big deal either.

[Ryan J Ollos]

I was hoping to use PyLint's ​Logging checker (W1201: logging-not-lazy) to detect these cases of string interpolation in the codebase. It's easy to miss them by manual inspection. For instance, here is one that is not captured in the patch: branches/0.12-stable/trac/wiki/model.py@12597:93#L84​

I've had no luck getting the Logging checker to work, see ​SO:26609732. Alternatively we can probably come up with some regexes for checking the code base.

[Ryan J Ollos]

Given the maintenance status of 0.12-stable, this change representing a minor optimization and the difficulties of merging large changesets (I think a few of these issues have been fixed on 1.0-stable), it seems better to target the patch to 1.0-stable. Would anyone be troubled if we targeted this change to 1.0.3 rather than 0.12.7?

[Christian Boos]

No problem for 1.0.x on this one. Until we decide if there's a 0.12.7 at all (other than for security fixes reasons), I think it makes sense to move all the minor/normal issues to 1.0.x.

[Ryan J Ollos]

Replying to cboos:

Thanks for the patch! Looks like a no-brainer.

I see that there's a log.isEnabledFor which I was not familiar with, but this seems to be supported in Python 2.4, so no big deal either.

The line:

self.env.log.debug("SQL: " + sql % tuple([repr(a) for a in args]))

was commented out on 1.0-stable in [10185].

With the change:

if self.env.log.isEnabledFor(logging.DEBUG):
    self.env.log.debug("Query SQL: %s",
                       sql % tuple(repr(a) for a in args))

I guess we are trying to avoid the ​overhead of string interpolation?

How does this look as an alternative?

self.env.log.debug("SQL: " + sql, *tuple([repr(a) for a in args]))

The only overhead should be a string concatenation, which even for a long query string the overhead for memory allocation and copy to create a new immutable string must be relatively small.

Maybe the reason it was commented out though is because the SQL can be obtained with [trac] debug_sql = enabled. The log.debug line generates:

07:33:13 PM Trac[query] DEBUG: SQL: SELECT t.id AS id,t.summary AS summary,t.status AS status,t.owner AS owner,t.type AS type,t.priority AS priority,t.milestone AS milestone,t.time AS time,t.changetime AS changetime,priority.value AS priority_value
FROM ticket AS t
  LEFT OUTER JOIN enum AS priority ON (priority.type='priority' AND priority.name=priority)
WHERE (COALESCE(t.status,'') IN (u'accepted',u'assigned',u'new',u'reopened'))
ORDER BY COALESCE(priority.value,'')='',CAST(priority.value AS integer),t.id

The debug_sql = enabled generates:

07:33:13 PM Trac[util] DEBUG: SQL: SELECT t.id AS id,t.summary AS summary,t.status AS status,t.owner AS owner,t.type AS type,t.priority AS priority,t.milestone AS milestone,t.time AS time,t.changetime AS changetime,priority.value AS priority_value
FROM ticket AS t
  LEFT OUTER JOIN enum AS priority ON (priority.type='priority' AND priority.name=priority)
WHERE (COALESCE(t.status,'') IN (%s,%s,%s,%s))
ORDER BY COALESCE(priority.value,'')='',CAST(priority.value AS integer),t.id
07:33:13 PM Trac[util] DEBUG: args: [u'accepted', u'assigned', u'new', u'reopened']

[Ryan J Ollos]

I deleted the logging line discussed in comment:6.

Committed to 1.0-stable in [13230], merged to trunk in [13232].

Thank you for the patch Alex!

[Ryan J Ollos]

Another instance of string interpolation fixed on trunk in [13543].

[Ryan J Ollos]

Replying to rjollos:

I've had no luck getting the Logging checker to work, see ​SO:26609732.

No replies from the StackOverflow post, so I created ​issue 459.

[Ryan J Ollos]

Regression in [13232#file8] fixed in [14267] (see comment:6:ticket:11677).