Fix the use of time() in measuring performances (replace with time_ns…

…()) (#34181)

time() is a wrapper for gettimeofday, which is affected by by discontinuous
jumps in the system time (e.g., if the system administrator manually changes the
system time), see `man gettimeofday`.  On the other hand, time_ns() is a wrapper
for libuv uv_hrtime that has no drift, whose manual page says "The primary use
is for measuring performance between intervals.".

base/asyncevent.jl

@@ -264,13 +264,14 @@ Returns :ok, :timed_out, or :error
 """
 function timedwait(testcb::Function, secs::Float64; pollint::Float64=0.1)
  pollint > 0 || throw(ArgumentError("cannot set pollint to $pollint seconds"))
- start = time()
+ start = time_ns()
+ nsecs = 1e9 * secs
  done = Channel(1)
  function timercb(aw)
  try
  if testcb()
  put!(done, :ok)
- elseif (time() - start) > secs
+ elseif (time_ns() - start) > nsecs
  put!(done, :timed_out)
  end
  catch e

contrib/generate_precompile.jl

@@ -57,7 +57,7 @@ if Pkg !== nothing
 end
 
 function generate_precompile_statements()
- start_time = time()
+ start_time = time_ns()
  debug_output = devnull # or stdout
 
  # Precompile a package
@@ -179,9 +179,9 @@ function generate_precompile_statements()
  end
 
  print(" $(length(statements)) generated in ")
- tot_time = time() - start_time
- Base.time_print(tot_time * 10^9)
- print(" (overhead "); Base.time_print((tot_time - include_time) * 10^9); println(")")
+ tot_time = time_ns() - start_time
+ Base.time_print(tot_time)
+ print(" (overhead "); Base.time_print(tot_time - (include_time * 1e9)); println(")")
  end
 
  return

doc/src/manual/metaprogramming.md

@@ -771,10 +771,10 @@ final value. The macro might look like this:
 ```julia
 macro time(ex)
  return quote
- local t0 = time()
+ local t0 = time_ns()
  local val = $ex
- local t1 = time()
- println("elapsed time: ", t1-t0, " seconds")
+ local t1 = time_ns()
+ println("elapsed time: ", (t1-t0)/1e9, " seconds")
  val
  end
 end
@@ -857,10 +857,10 @@ macro time(expr)
  return :(timeit(() -> $(esc(expr))))
 end
 function timeit(f)
- t0 = time()
+ t0 = time_ns()
  val = f()
- t1 = time()
- println("elapsed time: ", t1-t0, " seconds")
+ t1 = time_ns()
+ println("elapsed time: ", (t1-t0)/1e9, " seconds")
  return val
 end
 ```

stdlib/Distributed/src/cluster.jl

@@ -293,12 +293,11 @@ Base.showerror(io::IO, e::LaunchWorkerError) = print(io, e.msg)
 # The master process uses this to connect to the worker and subsequently
 # setup a all-to-all network.
 function read_worker_host_port(io::IO)
- t0 = time()
+ t0 = time_ns()
 
  # Wait at most for JULIA_WORKER_TIMEOUT seconds to read host:port
  # info from the worker
- timeout = worker_timeout()
-
+ timeout = worker_timeout() * 1e9
  # We expect the first line to contain the host:port string. However, as
  # the worker may be launched via ssh or a cluster manager like SLURM,
  # ignore any informational / warning lines printed by the launch command.
@@ -311,7 +310,7 @@ function read_worker_host_port(io::IO)
  while ntries > 0
  readtask = @async readline(io)
  yield()
- while !istaskdone(readtask) && ((time() - t0) < timeout)
+ while !istaskdone(readtask) && ((time_ns() - t0) < timeout)
  sleep(0.05)
  end
  !istaskdone(readtask) && break
@@ -707,20 +706,20 @@ function redirect_output_from_additional_worker(pid, port)
 end
 
 function check_master_connect()
- timeout = worker_timeout()
+ timeout = worker_timeout() * 1e9
  # If we do not have at least process 1 connect to us within timeout
  # we log an error and exit, unless we're running on valgrind
  if ccall(:jl_running_on_valgrind,Cint,()) != 0
  return
  end
  @async begin
- start = time()
- while !haskey(map_pid_wrkr, 1) && (time() - start) < timeout
+ start = time_ns()
+ while !haskey(map_pid_wrkr, 1) && (time_ns() - start) < timeout
  sleep(1.0)
  end
 
  if !haskey(map_pid_wrkr, 1)
- print(stderr, "Master process (id 1) could not connect within $timeout seconds.\nexiting.\n")
+ print(stderr, "Master process (id 1) could not connect within $(timeout/1e9) seconds.\nexiting.\n")
  exit(1)
  end
  end
@@ -1035,10 +1034,10 @@ function _rmprocs(pids, waitfor)
  end
  end
 
- start = time()
- while (time() - start) < waitfor
+ start = time_ns()
+ while (time_ns() - start) < waitfor*1e9
  all(w -> w.state == W_TERMINATED, rmprocset) && break
- sleep(min(0.1, waitfor - (time() - start)))
+ sleep(min(0.1, waitfor - (time_ns() - start)/1e9))
  end
 
  unremoved = [wrkr.id for wrkr in filter(w -> w.state != W_TERMINATED, rmprocset)]

stdlib/Profile/test/runtests.jl

@@ -17,8 +17,8 @@ end
  init_data = Profile.len_data()
  while iter < n_tries && Profile.len_data() == init_data
  iter += 1
- tend = time() + t
- while time() < tend end
+ tend = time_ns() + 1e9 * t
+ while time_ns() < tend end
  end
 end
 

stdlib/Sockets/test/runtests.jl

@@ -379,11 +379,11 @@ end
  end
 
  function wait_with_timeout(recvs)
- TIMEOUT_VAL = 3 # seconds
- t0 = time()
+ TIMEOUT_VAL = 3*1e9 # nanoseconds
+ t0 = time_ns()
  recvs_check = copy(recvs)
  while ((length(filter!(t->!istaskdone(t), recvs_check)) > 0)
- && (time() - t0 < TIMEOUT_VAL))
+ && (time_ns() - t0 < TIMEOUT_VAL))
  sleep(0.05)
  end
  length(recvs_check) > 0 && error("timeout")

test/bitarray.jl

@@ -32,12 +32,12 @@ macro check_bit_operation(ex)
  Expr(:call, :check_bitop_call, nothing, map(esc, ex.args)...)
 end
 
-let t0 = time()
+let t0 = time_ns()
  global timesofar
  function timesofar(str)
  return # no-op, comment to see timings
- t1 = time()
- println(str, ": ", t1-t0, " seconds")
+ t1 = time_ns()
+ println(str, ": ", (t1-t0)/1e9, " seconds")
  t0 = t1
  end
 end

test/file.jl

@@ -3,7 +3,7 @@
 #############################################
 # Create some temporary files & directories #
 #############################################
-starttime = time()
+starttime = time_ns() / 1e9
 pwd_ = pwd()
 dir = mktempdir()
 file = joinpath(dir, "afile.txt")
@@ -394,12 +394,14 @@ if Sys.iswindows()
 else
  @test filesize(dir) > 0
 end
-nowtime = time()
+# We need both: one to check passed time, one to comapare file's mtime()
+nowtime = time_ns() / 1e9
+nowwall = time()
 # Allow 10s skew in addition to the time it took us to actually execute this code
 let skew = 10 + (nowtime - starttime)
  mfile = mtime(file)
  mdir = mtime(dir)
- @test abs(nowtime - mfile) <= skew && abs(nowtime - mdir) <= skew && abs(mfile - mdir) <= skew
+ @test abs(nowwall - mfile) <= skew && abs(nowwall - mdir) <= skew && abs(mfile - mdir) <= skew
 end
 #@test Int(time()) >= Int(mtime(file)) >= Int(mtime(dir)) >= 0 # 1 second accuracy should be sufficient