-
-
Notifications
You must be signed in to change notification settings - Fork 5.7k
Description
When the @time macro is called using @time "message" ex, it can mess up the stdout print.
Consider the following:
function withtime(msg)
@time msg sleep(1)
end
@info "@time x ..."
t1 = Threads.@spawn withtime("time 1")
t2 = Threads.@spawn withtime("time 2")
wait(t1)
wait(t2)
@info "@time noghing ... / e.g., @time ..."
t3 = Threads.@spawn withtime(nothing)
t4 = Threads.@spawn withtime(nothing)
wait(t3)
wait(t4)
readline()Most of the times for the msg with non-nothing value we get a messed up printing to the stdout (and if you are lucky and get a nice print at first execution, just try again):
[ Info: @time x ...
time 1: time 2: 1.001953 seconds (768 allocations: 46.614 KiB, 1.42% compilation time)
1.001784 seconds (263 allocations: 12.469 KiB, 0.95% compilation time)
[ Info: @time noghing ... / e.g., @time ...
1.001953 seconds (15.60 k allocations: 1.031 MiB)
1.001822 seconds (89 allocations: 5.180 KiB, 0.69% compilation time)
The time 1: time 2: 1.001953 seconds (768 alloc... mess is caused by the following:
has_msg && print(_msg, ": ")
time_print(stdout, elapsedtime, diff.allo...Between the print(_msg, ": ") and the time_print issuing the print statement, there is a significant time gap (enough for other tasks to be able to litter the space with whatever they want - any task that will issue a print can print between the msg: and the rest of @time content.
The solution consists in either moving the msg printing inside the time_print function or returning a string from time_print and issuing a single print statement inside the @time macro body.