Skip to content

Commit 9c892c6

Browse files
IanButterworthKristofferC
authored andcommitted
Logging: Improve threadsafety (#57591)
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)
1 parent 1998364 commit 9c892c6

File tree

1 file changed

+43
-0
lines changed

1 file changed

+43
-0
lines changed

stdlib/Logging/test/runtests.jl

Lines changed: 43 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -335,4 +335,47 @@ end
335335
end
336336
end
337337

338+
@testset "Logging when multithreaded" begin
339+
n = 10000
340+
cmd = `$(Base.julia_cmd()) -t4 --color=no $(joinpath(@__DIR__, "threads_exec.jl")) $n`
341+
fname = tempname()
342+
@testset "Thread safety" begin
343+
f = open(fname, "w")
344+
@test success(run(pipeline(cmd, stderr=f)))
345+
close(f)
346+
end
347+
348+
@testset "No tearing in log printing" begin
349+
# Check for print tearing by verifying that each log entry starts and ends correctly
350+
f = open(fname, "r")
351+
entry_start = r"┌ (Info|Warning|Error): iteration"
352+
entry_end = r""
353+
354+
open_entries = 0
355+
total_entries = 0
356+
for line in eachline(fname)
357+
starts = count(entry_start, line)
358+
starts > 1 && error("Interleaved logs: Multiple log entries started on one line")
359+
if starts == 1
360+
startswith(line, entry_start) || error("Interleaved logs: Log entry started in the middle of a line")
361+
open_entries += 1
362+
total_entries += 1
363+
end
364+
365+
ends = count(entry_end, line)
366+
starts == 1 && ends == 1 && error("Interleaved logs: Log entry started and and another ended on one line")
367+
ends > 1 && error("Interleaved logs: Multiple log entries ended on one line")
368+
if ends == 1
369+
startswith(line, entry_end) || error("Interleaved logs: Log entry ended in the middle of a line")
370+
open_entries -= 1
371+
end
372+
# Ensure no mismatched log entries
373+
open_entries >= 0 || error("Interleaved logs")
374+
end
375+
376+
@test open_entries == 0 # Ensure all entries closed properly
377+
@test total_entries == n * 3 # Ensure all logs were printed (3 because @debug is hidden)
378+
end
379+
end
380+
338381
end

0 commit comments

Comments
 (0)