[racket] avoiding unnecessary work when using `log-debug` et al

I see that you're right about `log-debug`, but here's the example that led
me to make an incorrect generalization. It seems that the (expensive)
function in `log-test-error` always runs, even if the level is 'none or
'fatal. I don't understand why.

#lang racket

(define-logger test)

(define current-level (make-parameter #f))

(define (activate-test-logger)
  (define receiver (make-log-receiver test-logger (current-level)))
  (void (thread
         (λ ()
           (let loop ()
             (match (sync receiver)
               [(vector event-level event-message event-value name)
                (eprintf (format "[~a] ~a\n" event-level event-message))
                (loop)]))))))

(define (expensive from)
  (displayln (format "expensive op requested from log-test-~a at level ~v"
from (current-level)))
  (apply + (range 5000000)))

(parameterize ([current-level 'none])
  (activate-test-logger)
  (log-test-fatal (format "fatal at level ~v" (current-level)))
  (log-test-error "error at level ~v = ~a" (current-level) (expensive
"error"))
  (log-test-debug "debug at level ~v = ~a" (current-level) (expensive
"debug")))

On Fri, Dec 12, 2014 at 1:49 PM, Vincent St-Amour <stamourv at ccs.neu.edu>
wrote:
>
> I may be missing something, but `log-debug` and friends already do that.
>
>     stamourv at westmount:2014-12-12 16:45:plt$ racket
>     Welcome to Racket v6.1.1.6.
>     -> (log-debug (begin (displayln "hello!") "log"))
>     ->
>     stamourv at westmount:2014-12-12 16:45:plt$ racket -W debug
>     Welcome to Racket v6.1.1.6.
>     GC: 0:min @ 1,356K(+307K)[+160K]; free 932K(-5,028K) 4ms @ 12
>     GC: 0:min @ 1,813K(+3,946K)[+232K]; free 755K(-2,051K) 4ms @ 20
>     GC: 0:min @ 4,040K(+4,087K)[+232K]; free 1,448K(-1,448K) 4ms @ 28
>     GC: 0:min @ 5,015K(+3,112K)[+240K]; free 1,425K(-6,817K) 4ms @ 40
>     GC: 0:min @ 7,459K(+6,060K)[+272K]; free 2,162K(-3,458K) 0ms @ 56
>     GC: 0:min @ 9,356K(+6,211K)[+280K]; free 1,628K(-2,924K) 4ms @ 72
>     GC: 0:min @ 13,230K(+4,353K)[+296K]; free 2,558K(-16,142K) 12ms @ 96
>     GC: 0:min @ 17,224K(+13,943K)[+392K]; free 3,900K(-6,492K) 12ms @ 136
>     GC: 0:min @ 21,878K(+12,457K)[+400K]; free 4,741K(-6,037K) 12ms @ 172
>     GC: 0:min @ 27,016K(+9,255K)[+988K]; free 6,168K(-8,760K) 16ms @ 232
>     GC: 0:min @ 32,548K(+6,315K)[+1,276K]; free 7,665K(-26,641K) 36ms @ 312
>     -> (log-debug (begin (displayln "hello!") "log"))
>     hello!
>     log
>     ->
>
> `log-message`, however, does not.
>
> The problem may be that, when you switch to the lower logging level,
> your old listener for the higher level is still around to receive the
> messages.
>
> Vincent
>
>
>
> At Fri, 12 Dec 2014 13:32:41 -0800,
> Matthew Butterick wrote:
> >
> > Is there a reason not to redefine `log-debug` et al as macros that
> evaluate their arguments lazily?
> >
> > Sort of like this;
> >
> > (if ((current-logging-level) . is-equal-or-above? . 'debug)
> >   (log-debug arg ...)
> >   (void))
> >
> > Because I find that my use of these functions often looks like this:
> >
> > (log-debug "Value = ~a" (expensive-operation-for-logging-purposes))
> >
> > The problem is that when I change to a lower logging level, the
> (expensive-operation) is still evaluated.
> >
> > I asked a similar question about hash-ref! not long ago. The answer was
> that you can get lazy evaluation by wrapping the default argument in a
> lambda, like so:
> >
> > (hash-ref! hashtable key (λ () (expression-that-produces-value)))
> >
> > But it seems there's no equivalent idiom for `log-debug` et al.
> > ____________________
> >   Racket Users list:
> >   http://lists.racket-lang.org/users
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.racket-lang.org/users/archive/attachments/20141212/94aa6e59/attachment.html>