Edgewall Software
Modify

Opened 6 years ago

Closed 6 years ago

Last modified 5 years ago

#11765 closed defect (fixed)

[PATCH] Avoid string interpolation in logging calls

Reported by: Alex Willmer <al.willmer@…> Owned by: Alex Willmer <al.willmer@…>
Priority: low Milestone: 1.0.3
Component: general Version:
Severity: minor Keywords:
Cc: Branch:
Release Notes:

Replaced string interpolation in logging calls with function parameter format.

API Changes:
Internal Changes:

Description

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.

Attachments (1)

0.12.x_logging_formats.patch (19.4 KB ) - added by Alex Willmer <al.willmer@…> 6 years ago.

Download all attachments as: .zip

Change History (12)

by Alex Willmer <al.willmer@…>, 6 years ago

comment:1 by Christian Boos, 6 years ago

Milestone: 0.12.7

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.

comment:2 by Ryan J Ollos, 6 years ago

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.

comment:3 by Ryan J Ollos, 6 years ago

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?

comment:4 by Ryan J Ollos, 6 years ago

Owner: set to Ryan J Ollos
Status: newassigned

comment:5 by Christian Boos, 6 years ago

Milestone: 0.12.71.0.3

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.

in reply to:  1 comment:6 by Ryan J Ollos, 6 years ago

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']

comment:7 by Ryan J Ollos, 6 years ago

Release Notes: modified (diff)
Resolution: fixed
Status: assignedclosed

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!

comment:8 by Ryan J Ollos, 6 years ago

Owner: changed from Ryan J Ollos to Alex Willmer <al.willmer@…>

comment:9 by Ryan J Ollos, 6 years ago

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

in reply to:  2 comment:10 by Ryan J Ollos, 6 years ago

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.

comment:11 by Ryan J Ollos, 5 years ago

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

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Alex Willmer <al.willmer@…>.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Alex Willmer <al.willmer@…> to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.