Skip to content

Logging: Improve threadsafety #57591

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 10 commits into from
Apr 4, 2025

Conversation

IanButterworth
Copy link
Member

@IanButterworth IanButterworth commented Mar 1, 2025

Closes #57376
Closes #34037

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

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)

@IanButterworth IanButterworth added multithreading Base.Threads and related functionality logging The logging framework backport 1.10 Change should be backported to the 1.10 release backport 1.11 Change should be backported to release-1.11 backport 1.12 Change should be backported to release-1.12 labels Mar 1, 2025
@IanButterworth IanButterworth changed the title Logging: Improve SimpleLogger and ConsoleLogger threadsafety Logging: Improve threadsafety Mar 1, 2025
@IanButterworth IanButterworth force-pushed the ib/logging_lock branch 3 times, most recently from 110a64c to bbfaffe Compare March 2, 2025 04:12
@IanButterworth IanButterworth requested a review from vtjnash March 2, 2025 12:23
@vtjnash
Copy link
Member

vtjnash commented Mar 10, 2025

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

This was referenced Mar 11, 2025
Copy link
Member

@kpamnany kpamnany left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM.

@IanButterworth
Copy link
Member Author

@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
Copy link
Member

Bump. This seems important.

@IanButterworth
Copy link
Member Author

@vtjnash what do you think?

@KristofferC KristofferC mentioned this pull request Mar 24, 2025
27 tasks
@IanButterworth
Copy link
Member Author

Bump @vtjnash

@KristofferC KristofferC mentioned this pull request Mar 31, 2025
36 tasks
@@ -171,7 +172,7 @@ Alias for [`LogLevel(1_000_001)`](@ref LogLevel).
const AboveMaxLevel = LogLevel( 1000001)

# 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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why make this an int?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@IanButterworth IanButterworth merged commit 9af9650 into JuliaLang:master Apr 4, 2025
9 checks passed
@IanButterworth IanButterworth deleted the ib/logging_lock branch April 4, 2025 13:44
kpamnany pushed a commit to RelationalAI/julia that referenced this pull request Apr 7, 2025
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)
```
KristofferC pushed a commit that referenced this pull request Apr 9, 2025
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)
@KristofferC KristofferC removed the backport 1.12 Change should be backported to release-1.12 label Apr 25, 2025
@KristofferC KristofferC mentioned this pull request Apr 25, 2025
61 tasks
KristofferC pushed a commit that referenced this pull request Jun 4, 2025
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)
KristofferC pushed a commit that referenced this pull request Jun 5, 2025
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)
KristofferC pushed a commit that referenced this pull request Jun 5, 2025
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)
KristofferC pushed a commit that referenced this pull request Jun 5, 2025
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)
KristofferC pushed a commit that referenced this pull request Jun 5, 2025
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)
KristofferC pushed a commit that referenced this pull request Jun 5, 2025
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)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
backport 1.10 Change should be backported to the 1.10 release backport 1.11 Change should be backported to release-1.11 logging The logging framework multithreading Base.Threads and related functionality
Projects
None yet
4 participants