View Ticket
Not logged in
Bounty program for improvements to Tcl and certain Tcl packages.
2018-02-20 14:23 Closed ticket [93ebedfa4a]: Replace log package by logger package plus 2 other changes artifact: c7f94a1d2f user: oehhar
2018-02-20 14:20
Reduce non logging log impact by only building log message when logging. Requires tcllib log package 1.4 or included emulation. Ticket [93ebedfa] check-in: 150950db68 user: oehhar tags: trunk
2017-11-14 21:05 Ticket [93ebedfa4a] Replace log package by logger package status still New with 1 other change artifact: 2727351980 user: oehhar
2017-11-14 16:49 New ticket [93ebedfa4a]. artifact: bf1e82624d user: oehhar
2017-11-14 13:42 New ticket [93ebedfa4a]. artifact: dd66adc336 user: oehhar

Ticket UUID: 93ebedfa4a96b86471bdcf19fd023e768b3e09bb
Title: Replace log package by logger package
Status: Closed Type: Feature_Request
Severity: Minor Priority: Immediate
Subsystem: Client_Side Resolution: Fixed
Assigned to: unassigned
Last Modified: 2018-02-20 14:23:37
Version Found In: trunk
Description & Comments:

Issue: slow due to logging, even if switched off

TCLWS uses the tcllib log package to do logging.

IMHO, this introduces performence penalties, specially when not logging.

Example 1: Large XML message logged

::log::log debug "Parsing WSDL {$wsdlXML}"

Example 2: Procedure call with large xml message as parameter logged

::log::log debug [list ::WS::Client::DoCall $serviceName $operationName $argList]
::WS::Client::DoCall $serviceName $operationName $argList

Big string with often whole xml messages are formatted for the log message and thrown away, if no logging activated.

The formatting of the list may not be avoided. In addition, the ::log::log call is IMHO quite exensive, if the log level is not set. I looked into the source...

Possible solutions

Check for debug on entry of procedures and if the log commands

set fDebug [::log::lvIsSuppressed debug]
if {!$fDebug} {::log::log debug [list ::WS::Client::DoCall $serviceName}

Use the logger package instead of log

  • Logger has a much smaller footprint when log messages are not called.
  • The eventually expensive argument buildings are still necessary.
  • All log entries to trace procedure arguments may be logged using the internal trace methods.

New command which evaluates and invokes only if log level is set

IMHO an optimal log package only gets a log command verbatim and only evaluates it if the log level is set. To get to the upper example:

logCmdDebug {[list ::WS::Client::DoCall $serviceName $operationName $argList]}
::WS::Client::DoCall $serviceName $operationName $argList
and logCmd will be defined depending on the log level as:
if {[::log::lvIsSuppressed debug]} {
    proc logCmdDebug {cmd} {}
} else {
    proc logCmdDebug {cmd} {
        log::log debug [uplevel 1 $cmd]
    }
}

Is this reasonable ?

Thank you for any thoughts, Harald


oehhar added on 2017-11-14 16:49:12 UTC:
Gerald wrote by private E-Mail:

  • the cost of physical copying in the non-log case may be avoided by using [list ...] as argument. So, example 1 may be transformed in a less expensive version by [list "WSDL =" $wsdl].
  • changing to logger package would be a good thing

Thank you for you thoughts, Harald


oehhar added on 2017-11-14 21:05:45 UTC:
I have tried to find out, if the string representation is really not generated, if logging is switched off:

% proc l {} {
> set l [list a b [string repeat A 100000]]
> puts [tcl::unsupported::representation $l]
> log::log debug $l
> puts [tcl::unsupported::representation $l]
> }
% l
value is a list with a refcount of 2, object pointer at 0x7bbee80, internal representation 0x77485f0:0x0, no string representation
value is a list with a refcount of 2, object pointer at 0x7bbee80, internal representation 0x77485f0:0x0, no string representation

So apparently, it works. Thank you, Gerald !


oehhar added on 2018-02-20 14:23:37 UTC:
The log package was extended by a command log::logeval, which only builds the log message when the log level is set.

This is now introduced into tclws starting with commit [150950db68].

I am so far satisfied with this so closing the ticket.

Thank you all, Harald