-
-
Notifications
You must be signed in to change notification settings - Fork 5.6k
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.