invenia / Memento.jl

A flexible logging library for Julia
https://invenia.github.io/Memento.jl/latest
Other
88 stars 14 forks source link

Replacing base logging #75

Closed rofinn closed 6 years ago

rofinn commented 6 years ago

Initial attempt to get stdlib logging working.

Example)

julia> using Memento; getlogger(@__MODULE__); Memento.config!("info"; recursive=true); Memento.setglobal!()
Logging.ConsoleLogger(Base.TTY(RawFD(0x0000000f) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}(Pair{Any,Int64}((Base.InterpreterIP(CodeInfo(:(begin
      Core.SSAValue(0) = current_module()
      return Core.SSAValue(0)
  end)), 0x0000000000000000), :current_module), 0)))

julia> @info "Foo"
WARNING: importing deprecated binding Base.myid into Memento.
WARNING: Base.myid is deprecated: it has been moved to the standard library package `Distributed`.
Add `using Distributed` to your imports.
  likely near no file:310
WARNING: Base.myid is deprecated: it has been moved to the standard library package `Distributed`.
Add `using Distributed` to your imports.
  likely near no file:310
WARNING: Base.myid is deprecated: it has been moved to the standard library package `Distributed`.
Add `using Distributed` to your imports.
  likely near no file:310
[info | Main]: Foo

I'll note that using Memento has slightly worse performance than base when we're actually writing messages. The bigger issue is that no-op conditions are slower if we route everything to Memento.

# Base: `@info`

julia> @benchmark @info "Foo"
...
BenchmarkTools.Trial: 
  memory estimate:  3.50 KiB
  allocs estimate:  87
  --------------
  minimum time:     37.108 μs (0.00% GC)
  median time:      50.513 μs (0.00% GC)
  mean time:        88.835 μs (2.38% GC)
  maximum time:     22.891 ms (0.00% GC)
  --------------
  samples:          10000
  evals/sample:     1

# Memento: `@info`

julia> @benchmark @info "Foo"
...
BenchmarkTools.Trial: 
  memory estimate:  5.33 KiB
  allocs estimate:  111
  --------------
  minimum time:     61.727 μs (0.00% GC)
  median time:      70.142 μs (0.00% GC)
  mean time:        78.761 μs (9.54% GC)
  maximum time:     58.598 ms (99.65% GC)
  --------------
  samples:          10000
  evals/sample:     1

# Base: `@debug`

julia> @benchmark @debug "Foo"
BenchmarkTools.Trial: 
  memory estimate:  0 bytes
  allocs estimate:  0
  --------------
  minimum time:     122.010 ns (0.00% GC)
  median time:      124.102 ns (0.00% GC)
  mean time:        127.923 ns (0.00% GC)
  maximum time:     179.063 ns (0.00% GC)
  --------------
  samples:          10000
  evals/sample:     903

# Memento: `@debug`

julia> @benchmark @debug "Foo"
BenchmarkTools.Trial: 
  memory estimate:  1.58 KiB
  allocs estimate:  45
  --------------
  minimum time:     17.152 μs (0.00% GC)
  median time:      17.795 μs (0.00% GC)
  mean time:        18.505 μs (0.00% GC)
  maximum time:     87.248 μs (0.00% GC)
  --------------
  samples:          10000
  evals/sample:     1

The slower no-op performance is an accepted compromise with Memento's design (for tracing code Trace.jl would be a better choice). A middle ground may be to not route debug messages to Memento by default.

codecov[bot] commented 6 years ago

Codecov Report

Merging #75 into master will decrease coverage by 0.76%. The diff coverage is 94.11%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master      #75      +/-   ##
==========================================
- Coverage     100%   99.23%   -0.77%     
==========================================
  Files           9       11       +2     
  Lines         251      261      +10     
==========================================
+ Hits          251      259       +8     
- Misses          0        2       +2
Impacted Files Coverage Δ
src/Memento.jl 100% <ø> (ø) :arrow_up:
src/config.jl 100% <100%> (ø)
src/loggers.jl 100% <100%> (ø) :arrow_up:
src/stdlib.jl 75% <75%> (ø)

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update f6f26e7...a0d15b2. Read the comment docs.

rofinn commented 6 years ago

I'm not sure what's up the coverage reporting because all of those lines should be getting hit in order for the tests to pass.

https://codecov.io/gh/invenia/Memento.jl/src/6a7ca7f870687da85281e0f8a36db41679588d2f/src/stdlib.jl

rofinn commented 6 years ago

Looks like the coverage problem was an issue with the optimizer which is fixed on master.

https://github.com/JuliaLang/julia/issues/27209

Unfortunately, travis is still using a nightly build from a few days ago.

ararslan commented 6 years ago

Also note that there are some weird issues with Coverage.jl on master right now (see for example the 0.7 CI logs in https://github.com/JuliaCI/Coverage.jl/pull/162), which appears to include hit detection.