Logging: test multithreaded logging by IanButterworth · Pull Request #57448 · JuliaLang/julia

IanButterworth · 2025-02-17T21:45:08Z

Investigating #57376

With and without the redirect there's no crash locally.
Ideally it'd be good to test logging to the console but I don't think we can do that without noisy logs on the console..

Tests for no crashes due to memory corruption
Tests that no tearing occurs in log prints

vtjnash

You need to make the code actually correct first before adding tests for new uses cases which may be unreliable

IanButterworth · 2025-02-18T16:52:54Z

By "new use cases" do you mean logging from tasks running on other threads?

vtjnash · 2025-02-18T16:54:22Z

Yes, that has never been allowed before

IanButterworth · 2025-02-18T17:05:49Z

Ok then I think we need to do two things:

Elaborate the specific issues on Request for clarification on the thread-safety (or lack thereof) of the Julia logging system #57376 as has been requested by people (like myself) that were surprised to hear that logging from threads has always been forbidden and is highly dangerous (even though these test don't shake the bugs out)
Update the docs because as far as I can tell, it doesn't say anywhere that logging from threads is forbidden.

Hopefully we can avoid 2) by just fixing the stuff in 1) first, but I am unaware of the issues, and I believe from slack that you have a private list of issues @vtjnash so it'd be good to make that public.

I'll happily look into fixing this, I just am unfamiliar with the issue(s).

simsurace · 2025-02-19T21:25:32Z

Yes, that has never been allowed before

Could you confirm that this multi-threaded hello world program is in your opinion a user error:

Threads.@spawn @info "Hello from thread $(Threads.threadid())"

vtjnash · 2025-02-19T21:28:17Z

Yes, only functions that declare themselves thread-safe may be used

simsurace · 2025-02-19T22:04:18Z

Since the point of the logging macros is to abstract away the mechanics of how the logs are processed, doesn't an otherwise thread-safe function becoming unsafe by virtue of some logging statements violate expectations for this abstraction?

IanButterworth · 2025-03-01T03:55:52Z

This has been added to #57591

@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) ```

@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>

IanButterworth added multithreading Base.Threads and related functionality logging The logging framework labels Feb 17, 2025

IanButterworth mentioned this pull request Feb 17, 2025

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

Closed

IanButterworth changed the title ~~Loggin: test multithreaded logging~~ Logging: test multithreaded logging Feb 17, 2025

IanButterworth force-pushed the ib/threaded_logging_tests branch 2 times, most recently from 8eed463 to 2db9213 Compare February 17, 2025 23:18

This comment was marked as resolved.

Sign in to view

IanButterworth force-pushed the ib/threaded_logging_tests branch from 2db9213 to 5a5fe27 Compare February 18, 2025 12:25

test multithreaded logging

349709a

IanButterworth force-pushed the ib/threaded_logging_tests branch from 5a5fe27 to 349709a Compare February 18, 2025 16:23

vtjnash requested changes Feb 18, 2025

View reviewed changes

IanButterworth mentioned this pull request Mar 1, 2025

Logging: Improve threadsafety #57591

Merged

IanButterworth closed this Mar 1, 2025

IanButterworth deleted the ib/threaded_logging_tests branch March 1, 2025 03:55

kpamnany mentioned this pull request Apr 7, 2025

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

Merged

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Logging: test multithreaded logging#57448

Logging: test multithreaded logging#57448
IanButterworth wants to merge 1 commit intoJuliaLang:masterfrom
IanButterworth:ib/threaded_logging_tests

IanButterworth commented Feb 17, 2025 •

edited

Loading

Uh oh!

This comment was marked as resolved.

vtjnash left a comment

Uh oh!

IanButterworth commented Feb 18, 2025

Uh oh!

vtjnash commented Feb 18, 2025

Uh oh!

IanButterworth commented Feb 18, 2025

Uh oh!

simsurace commented Feb 19, 2025

Uh oh!

vtjnash commented Feb 19, 2025

Uh oh!

simsurace commented Feb 19, 2025

Uh oh!

IanButterworth commented Mar 1, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Uh oh!

Conversation

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

Uh oh!

Uh oh!

This comment was marked as resolved.

vtjnash left a comment

Choose a reason for hiding this comment

Uh oh!

IanButterworth commented Feb 18, 2025

Uh oh!

vtjnash commented Feb 18, 2025

Uh oh!

IanButterworth commented Feb 18, 2025

Uh oh!

simsurace commented Feb 19, 2025

Uh oh!

vtjnash commented Feb 19, 2025

Uh oh!

simsurace commented Feb 19, 2025

Uh oh!

IanButterworth commented Mar 1, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

IanButterworth commented Feb 17, 2025 •

edited

Loading