Skip to content

Cosmetic bug in @time stdout printing when msg is not nothing #50646

@algunion

Description

@algunion

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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions