Logging: Improve threadsafety by IanButterworth · Pull Request #57591 · JuliaLang/julia

IanButterworth · 2025-03-01T03:25:32Z

Adds a lock in SimpleLogger and ConsoleLogger for use on maxlog tracking and stream writes to improve threadsafety.
Closely similar to Make TestLogger thread-safe (introduce a lock) #54497 by @NHDaly
Turns the internal _min_enabled_level into a Threads.Atomic. There are some direct interactions to this internal in the ecosystem, but they should still work

julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1
LogLevel(1)

Brings tests over from Logging: test multithreaded logging #57448

Performance seems highly similar:

Master

julia> @time for i in 1:10000
          @info "foo" maxlog=10000000
       end
[ Info: foo
...
  0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time)

This PR

  0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time)

base/logging/logging.jl

vtjnash · 2025-03-10T11:38:27Z

This may need some comments and it needs documentation, since adding a lock can interact poorly with other existing locks, so users need to be aware of the risk, to be able to structure their code safely

kpamnany

LGTM.

IanButterworth · 2025-03-14T03:00:52Z

@vtjnash I added some explanation to the docs and a comment, and went as far as stating thread-safety.
In writing that explanation I thought it made more sense to split this out to two separate locks.

Do you think the doc additions are sufficient detail to allow users to understand risks or should it be more explicit?

kpamnany · 2025-03-20T23:35:25Z

Bump. This seems important.

IanButterworth · 2025-03-22T02:11:36Z

@vtjnash what do you think?

IanButterworth · 2025-03-28T21:38:35Z

Bump @vtjnash

base/logging/logging.jl

vtjnash · 2025-03-10T11:36:06Z

base/logging/logging.jl


 # Global log limiting mechanism for super fast but inflexible global log limiting.
-const _min_enabled_level = Ref{LogLevel}(Debug)
+const _min_enabled_level = Threads.Atomic{Int32}(Debug)


Why make this an int?

Just adding the discussion from the multithreading call that Threads.Atomic can only take certain types.

and use for maxlog and stream writes

@time

Closes JuliaLang#57376 Closes JuliaLang#34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to JuliaLang#54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from JuliaLang#57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ```

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ### Master ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ### This PR ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ### Master ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ### This PR ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes #57376 Closes #34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to #54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from #57448 Performance seems highly similar: ### Master ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ### This PR ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` (cherry picked from commit 9af9650)

@time

Closes JuliaLang#57376 Closes JuliaLang#34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to JuliaLang#54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from JuliaLang#57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ```

@time

Closes JuliaLang#57376 Closes JuliaLang#34037 - Adds a lock in `SimpleLogger` and `ConsoleLogger` for use on maxlog tracking and stream writes to improve threadsafety. Closely similar to JuliaLang#54497 - Turns the internal `_min_enabled_level` into a `Threads.Atomic`. There are [some direct interactions](https://juliahub.com/ui/Search?type=code&q=_min_enabled_level&w=true) to this internal in the ecosystem, but they should still work ``` julia> Base.CoreLogging._min_enabled_level[] = Logging.Info+1 LogLevel(1) ``` - Brings tests over from JuliaLang#57448 Performance seems highly similar: ``` julia> @time for i in 1:10000 @info "foo" maxlog=10000000 end [ Info: foo ... 0.481446 seconds (1.33 M allocations: 89.226 MiB, 0.49% gc time) ``` ``` 0.477235 seconds (1.31 M allocations: 79.002 MiB, 1.77% gc time) ``` Co-authored-by: Tomáš Drvoštěp <tomas.drvostep@gmail.com>

The current enable_finalizers call before issuing a warning on a thread is leading to segmentation faults. I suspect it is no longer needed, since work has gone into making logging threadsafe as in issue: JuliaLang/julia#57591

IanButterworth changed the title ~~Logging: Improve SimpleLogger and ConsoleLogger threadsafety~~ Logging: Improve threadsafety Mar 1, 2025

IanButterworth mentioned this pull request Mar 1, 2025

Logging: test multithreaded logging #57448

Closed

IanButterworth force-pushed the ib/logging_lock branch from 6462f96 to a40e867 Compare March 1, 2025 04:00

IanButterworth mentioned this pull request Mar 1, 2025

Request for clarification on the thread-safety (or lack thereof) of the Julia logging system #57376

Closed

IanButterworth force-pushed the ib/logging_lock branch from a40e867 to 8e5a2e1 Compare March 1, 2025 16:57

IanButterworth commented Mar 1, 2025

View reviewed changes

base/logging/logging.jl Outdated Show resolved Hide resolved

IanButterworth force-pushed the ib/logging_lock branch 3 times, most recently from 110a64c to bbfaffe Compare March 2, 2025 04:12

IanButterworth requested a review from vtjnash March 2, 2025 12:23

KristofferC mentioned this pull request Mar 3, 2025

Backports release 1.12 #57536

Merged

This was referenced Mar 11, 2025

Backports release 1.11 #57714

Merged

Backports for 1.10.10 #57715

Merged

kpamnany approved these changes Mar 13, 2025

View reviewed changes

IanButterworth force-pushed the ib/logging_lock branch from bbfaffe to a0b7b27 Compare March 14, 2025 02:58

KristofferC mentioned this pull request Mar 24, 2025

Backports release 1.12 #57871

Merged

27 tasks

KristofferC mentioned this pull request Mar 31, 2025

Backports release 1.12 #57955

Merged

36 tasks

vtjnash reviewed Apr 3, 2025

View reviewed changes

IanButterworth added 2 commits April 3, 2025 13:48

add a lock to SimpleLogger and ConsoleLogger

7a46e9c

and use for maxlog and stream writes

make _min_enabled_level Threads.Atomic

d70393b

IanButterworth mentioned this pull request Apr 3, 2025

Logging.disable_logging() either broken or docs not clear on usage #34037

Closed

IanButterworth requested a review from vtjnash April 4, 2025 02:22

KristofferC mentioned this pull request Apr 4, 2025

Backports for 1.12.0-beta2 #58009

Merged

51 tasks

vtjnash approved these changes Apr 4, 2025

View reviewed changes

IanButterworth merged commit 9af9650 into JuliaLang:master Apr 4, 2025
9 checks passed

IanButterworth deleted the ib/logging_lock branch April 4, 2025 13:44

kpamnany mentioned this pull request Apr 7, 2025

Logging: Improve threadsafety (#57591) RelationalAI/julia#229

Merged

3 tasks

KristofferC removed the backport 1.12 Change should be backported to release-1.12 label Apr 25, 2025

KristofferC mentioned this pull request Apr 25, 2025

Backports for julia 1.11.6 #58224

Merged

71 tasks

KristofferC removed the backport 1.11 Change should be backported to release-1.11 label Aug 19, 2025

DilumAluthge mentioned this pull request Sep 13, 2025

Backports for Julia 1.10.11 #58889

Merged

71 tasks

KristofferC mentioned this pull request Nov 20, 2025

set VERSION to 1.12.2 #60182

Merged

EdsterG mentioned this pull request Dec 4, 2025

Regression, use of _min_enabled_level broken in logging ecosystem. #60317

Closed

KristofferC mentioned this pull request Dec 12, 2025

release-1.12: Revert "build: More msys2 fixes (#59028)" #60374

Merged

KristofferC mentioned this pull request Jan 3, 2026

set VERSION to 1.12.4 #60539

Merged

github-actions bot removed the backport 1.10 Change should be backported to the 1.10 release label Jan 18, 2026

zygmuntszpak mentioned this pull request Feb 9, 2026

Removes enable_finalizers call when giving warning for a thread zygmuntszpak/Actors.jl#1

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Logging: Improve threadsafety#57591

Logging: Improve threadsafety#57591
IanButterworth merged 10 commits intoJuliaLang:masterfrom
IanButterworth:ib/logging_lock

IanButterworth commented Mar 1, 2025 •

edited

Loading

Uh oh!

Uh oh!

vtjnash commented Mar 10, 2025

Uh oh!

kpamnany left a comment

Uh oh!

IanButterworth commented Mar 14, 2025

Uh oh!

kpamnany commented Mar 20, 2025

Uh oh!

IanButterworth commented Mar 22, 2025

Uh oh!

IanButterworth commented Mar 28, 2025

Uh oh!

Uh oh!

Uh oh!

vtjnash Mar 10, 2025

Uh oh!

IanButterworth Apr 3, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Uh oh!

Conversation

IanButterworth commented Mar 1, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Master

This PR

Uh oh!

Uh oh!

vtjnash commented Mar 10, 2025

Uh oh!

kpamnany left a comment

Choose a reason for hiding this comment

Uh oh!

IanButterworth commented Mar 14, 2025

Uh oh!

kpamnany commented Mar 20, 2025

Uh oh!

IanButterworth commented Mar 22, 2025

Uh oh!

IanButterworth commented Mar 28, 2025

Uh oh!

Uh oh!

Uh oh!

vtjnash Mar 10, 2025

Choose a reason for hiding this comment

Uh oh!

IanButterworth Apr 3, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

IanButterworth commented Mar 1, 2025 •

edited

Loading