# How to log something slow properly

**URL:** <https://discourse.julialang.org/t/how-to-log-something-slow-properly/61572>\
**Category:** New to Julia\
**Tags:** logging\
**Created:** [May 21, 2021, 10:10am UTC](https://discourse.julialang.org/t/how-to-log-something-slow-properly/61572 "2021-05-21T10:10:28Z")\
**Posts on this page:** 6\
**Page:** 1

<div class="post-metadata">

**Author:** ![ChunXi\_Zhang](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/chunxi_zhang/32/22556_2.png) [@ChunXi\_Zhang](https://discourse.julialang.org/u/ChunXi_Zhang)\
**Post date:** [May 21, 2021, 10:10am UTC](https://discourse.julialang.org/t/how-to-log-something-slow-properly/61572/1 "2021-05-21T10:10:28Z")

</div>

Here is what I want to do:

```julia
using Logging
using Statistics

mutable struct MyLogger <: AbstractLogger
    log
    min_level
end

MyLogLevel= LogLevel(-1)

MyLogger() = MyLogger([], MyLogLevel)

function Logging.handle_message(logger::MyLogger, level, message, _module, group, id, file, line; kargs...)
    push!(logger.log, kargs.data)
end

Logging.shouldlog(logger::MyLogger, level, _module, group, id) = level == MyLogLevel

Logging.min_enabled_level(logger::MyLogger) = MyLogLevel

logger = MyLogger()

function compute()
    data = rand(10000)
    @logmsg MyLogLevel "Compute" mean=mean(data)
end

function no_log_compute()
    data = rand(10000)
end

with_logger(logger) do
    println("With Logger")
    @btime compute()
end

println("No logger")
@btime compute()

println("No log compute")
@btime no_log_compute()

```

Here I have a custom logger, which log something which require computation, and push to my logger.  
I wish that if I don’t have `with_logger(logger)`, it should perform the same as I didn’t write the `@logmsg` in the first place, meaning don’t run anything in the key value pairs.

But in fact, I get:

```julia
With Logger
  8.000 μs (8 allocations: 78.45 KiB)
No logger
  9.000 μs (11 allocations: 78.62 KiB)
No log compute
  6.340 μs (2 allocations: 78.20 KiB)

```

Which means, even the loglevel is above the target, the log is not logged into anything, the key value pairs still get executed anyway.  
And the second version is even slower than the with logger version…

---

<div class="post-metadata">

**Author:** ![fredrikekre](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/fredrikekre/32/1688_2.png) [@fredrikekre](https://discourse.julialang.org/u/fredrikekre)\
**Post date:** [May 21, 2021, 11:09am UTC](https://discourse.julialang.org/t/how-to-log-something-slow-properly/61572/2 "2021-05-21T11:09:43Z")

</div>

> [@ChunXi\_Zhang](#):
>
> key value pairs still get executed anyway

Are you sure about that? I think you are just seeing the overhead of checking if the logger should log or not. Try e.g.

```julia
julia> @debug "hello" error("not called") # no error

julia> @info "hello" error("not called") # error
┌ Error: Exception while generating log record in module Main at REPL[5]:1

```

And here is a measure of the overhead, which seems to align with your measurements:

```julia
julia> using BenchmarkTools, Logging

julia> infologger = SimpleLogger(devnull, Logging.Info);

julia> debuglogger = SimpleLogger(devnull, Logging.Debug);

julia> function f()
           @debug "hello"
       end;

julia> global_logger(infologger);

julia> @btime f()
  65.839 ns (0 allocations: 0 bytes)

julia> global_logger(debuglogger);

julia> @btime f()
  2.247 μs (22 allocations: 1.22 KiB)

```

---

<div class="post-metadata">

**Author:** ![ChunXi\_Zhang](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/chunxi_zhang/32/22556_2.png) [@ChunXi\_Zhang](https://discourse.julialang.org/u/ChunXi_Zhang)\
**Post date:** [May 21, 2021, 12:49pm UTC](https://discourse.julialang.org/t/how-to-log-something-slow-properly/61572/3 "2021-05-21T12:49:15Z")

</div>

It is not a constant overhead, since you can make the `mean(data)` more complicated, to see if the time grows:

```julia
function compute()
    data = ones(10000)
    @logmsg MyLogLevel "Compute" mean=mean(data .* data .* exp.(data) .^ 2)
end

function no_log_compute()
    data = ones(10000)
end

with_logger(logger) do
    println("With Logger")
    @btime compute()
end

println("No logger")
@btime compute()

println("no log compute")
@btime no_log_compute()

```

And it does:

```julia
With Logger
  55.500 μs (10 allocations: 156.66 KiB)
No logger
  57.500 μs (13 allocations: 156.83 KiB)
no log compute
  6.233 μs (2 allocations: 78.20 KiB)

```

---

<div class="post-metadata">

**Author:** ![fredrikekre](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/fredrikekre/32/1688_2.png) [@fredrikekre](https://discourse.julialang.org/u/fredrikekre)\
**Post date:** [May 21, 2021, 2:33pm UTC](https://discourse.julialang.org/t/how-to-log-something-slow-properly/61572/4 "2021-05-21T14:33:28Z")

</div>

```julia
julia> @time with_logger(SimpleLogger(devnull, Logging.Info)) do
           @debug "sleeping..." sleep(5)
       end
  0.069389 seconds (97.56 k allocations: 5.215 MiB, 99.07% compilation time)

julia> @time with_logger(SimpleLogger(devnull, Logging.Debug)) do
           @debug "sleeping..." sleep(5)
       end
  5.053603 seconds (97.60 k allocations: 5.217 MiB, 0.99% compilation time)

```

---

<div class="post-metadata">

**Author:** ![ChunXi\_Zhang](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/chunxi_zhang/32/22556_2.png) [@ChunXi\_Zhang](https://discourse.julialang.org/u/ChunXi_Zhang)\
**Post date:** [May 21, 2021, 3:39pm UTC](https://discourse.julialang.org/t/how-to-log-something-slow-properly/61572/5 "2021-05-21T15:39:52Z")

</div>

Can you explain why my code shows it does grow with the it?  
My real world case is I want to log a CuArray, which means copy it from device to host, it takes around 300us.  
Can you try without modifying global logger or with a logger?

---

<div class="post-metadata">

**Author:** ![ChunXi\_Zhang](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/chunxi_zhang/32/22556_2.png) [@ChunXi\_Zhang](https://discourse.julialang.org/u/ChunXi_Zhang)\
**Post date:** [May 21, 2021, 4:40pm UTC](https://discourse.julialang.org/t/how-to-log-something-slow-properly/61572/6 "2021-05-21T16:40:16Z")

</div>

After some test I found the problem is that the default logger of VSCode is a VSCodeServer.VSCodeLogger(), and it’s min\_enabled\_level is just -1.