How to handle functions which run slowly the first few thousand times and fast on subsequent runs? #98

nsajko · 2024-04-28T06:17:58Z

In a fresh REPL session:

foo(::Type{<:Array}) = nothing
T = Vector{Int};
g() = foo(T)
using Chairmarks
@b g  # timing always larger than below
@b g  # timing always smaller than above

Example:

julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g
333.609 ns

julia> @b g
317.712 ns

julia> @b g
310.692 ns

julia> @b g
314.212 ns

(@v1.12) pkg> st Chairmarks
Status `~/.julia/environments/v1.12/Project.toml`
  [0ca39b1e] Chairmarks v1.2.1

LilithHafner · 2024-04-28T23:07:38Z

Thanks. I'm able to reproduce this on some machines but not others.

Successful reproduction:

[lilith@fedora ~]$ julia +nightly --startup-file=no --banner=short
  o  | Version 1.12.0-DEV.427 (2024-04-28)
 o o | Commit 6023ad67185 (0 days old master)
julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g  # timing always larger than below
977.185 ns

julia> @b g  # timing always smaller than above
617.767 ns

julia> 
[lilith@fedora ~]$ julia +nightly --startup-file=no --banner=short
  o  | Version 1.12.0-DEV.427 (2024-04-28)
 o o | Commit 6023ad67185 (0 days old master)
julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g  # timing always larger than below
976.857 ns

julia> @b g  # timing always smaller than above
974.700 ns

julia> 
[lilith@fedora ~]$ julia +nightly --startup-file=no --banner=short
  o  | Version 1.12.0-DEV.427 (2024-04-28)
 o o | Commit 6023ad67185 (0 days old master)
julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g  # timing always larger than below
992.577 ns

julia> @b g  # timing always smaller than above
975.552 ns

julia> 
[lilith@fedora ~]$ julia +nightly --startup-file=no --banner=short
  o  | Version 1.12.0-DEV.427 (2024-04-28)
 o o | Commit 6023ad67185 (0 days old master)
julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g  # timing always larger than below
991.172 ns

julia> @b g  # timing always smaller than above
974.533 ns

julia> 
[lilith@fedora ~]$ julia +nightly --startup-file=no --banner=short
  o  | Version 1.12.0-DEV.427 (2024-04-28)
 o o | Commit 6023ad67185 (0 days old master)
julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g  # timing always larger than below
976.069 ns

julia> @b g  # timing always smaller than above
975.700 ns

(@v1.12) pkg> st
Status `~/.julia/environments/v1.12/Project.toml`
  [0ca39b1e] Chairmarks v1.2.1

julia> versioninfo()
Julia Version 1.12.0-DEV.427
Commit 6023ad67185 (2024-04-28 07:31 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 16 × Intel(R) Xeon(R) CPU           E5520  @ 2.27GHz
  WORD_SIZE: 64
  LLVM: libLLVM-16.0.6 (ORCJIT, nehalem)
Threads: 1 default, 0 interactive, 1 GC (on 16 virtual cores)

Failed to reproduction:

x@fedora:~/.julia/dev/CompileTimeDicts$ julia +nightly --startup-file=no
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.12.0-DEV.427 (2024-04-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 6023ad67185 (0 days old master)
|__/                   |

julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g  # timing always larger than below
179.739 ns

julia> @b g  # timing always smaller than above
181.818 ns

julia> 
x@fedora:~/.julia/dev/CompileTimeDicts$ julia +nightly --startup-file=no
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.12.0-DEV.427 (2024-04-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 6023ad67185 (0 days old master)
|__/                   |

julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g  # timing always larger than below
181.588 ns

julia> @b g  # timing always smaller than above
181.452 ns

julia> 
x@fedora:~/.julia/dev/CompileTimeDicts$ julia +nightly --startup-file=no
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.12.0-DEV.427 (2024-04-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 6023ad67185 (0 days old master)
|__/                   |

julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> @b g  # timing always larger than below
181.113 ns

julia> @b g  # timing always smaller than above
180.830 ns

(@v1.12) pkg> st
Status `~/.julia/environments/v1.12/Project.toml`
  [6e4b80f9] BenchmarkTools v1.5.0
  [0ca39b1e] Chairmarks v1.2.1
  [295af30f] Revise v3.5.14
  [2913bbd2] StatsBase v0.34.3

julia> versioninfo()
Julia Version 1.12.0-DEV.427
Commit 6023ad67185 (2024-04-28 07:31 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: Linux (aarch64-linux-gnu)
  CPU: 8 × unknown
  WORD_SIZE: 64
  LLVM: libLLVM-16.0.6 (ORCJIT, apple-m2)
Threads: 1 default, 0 interactive, 1 GC (on 8 virtual cores)

LilithHafner · 2024-04-28T23:29:43Z

This is a classic "the first n (4511, in this case) times this function runs are slower than subsequent runs". ~~I'm going to open a~~ this will be a central issue to point this kind of report to. AFAICT, there is no solution besides knowing the magic number on each computer and setting runtime/evals high enough to exceed it.

foo(::Type{<:Array}) = nothing
T = Vector{Int};
g() = foo(T)
using Chairmarks
x = @be g seconds=.3  # timing always larger than below

using UnicodePlots
UnicodePlots.scatterplot([s.time for s in x.samples])

using Statistics
target = (minimum([s.time for s in x.samples]) + Statistics.median([s.time for s in x.samples]))/2
findfirst(x.time < target for x in x.samples)

[lilith@fedora ~]$ julia +nightly --startup-file=no --banner=short
  o  | Version 1.12.0-DEV.427 (2024-04-28)
 o o | Commit 6023ad67185 (0 days old master)
julia> foo(::Type{<:Array}) = nothing
foo (generic function with 1 method)

julia> T = Vector{Int};

julia> g() = foo(T)
g (generic function with 1 method)

julia> using Chairmarks

julia> x = @be g seconds=.3  # timing always larger than below
Benchmark: 8937 samples with 30 evaluations
min    615.433 ns
median 974.200 ns
mean   824.201 ns
max    7.513 μs

julia> using UnicodePlots

julia> UnicodePlots.scatterplot([s.time for s in x.samples])
        ┌────────────────────────────────────────┐ 
   8e⁻⁶ │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠂⠀⠀⠀⠀⠀⠀⠀⠀⠀⢀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⡤⢤⠮⣤⢄⣤⣠⣤⣤⢽⠼⡦⣤⠤⠷⠤⠤⣥⢤⣦⠀⢀⠀⢀⢸⡀⠀⠀⠠⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        │⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⠉⣥⣬⣴⣮⣼⣾⣾⣦⣬⣴⣴⣤⣤⣤⣤⣬⣾⣤⣶⣤│ 
      0 │⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀│ 
        └────────────────────────────────────────┘ 
        ⠀0⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀9 000⠀ 

julia> findfirst(x.time < 7e-7 for x in x.samples)
4512

julia> target = [minimum(x).time + Chairmarks.median(x).time]/2
1-element Vector{Float64}:
 7.948166666666667e-7

julia> target = (minimum(x).time + Chairmarks.median(x).time)/2
7.948166666666667e-7

julia> findfirst(x.time < target for x in x.samples)
4512

LilithHafner · 2024-04-28T23:32:27Z

See also: https://discourse.julialang.org/t/difference-in-microbenchmark-result-chairmarks-jl-vs-benchmarktools-jl/111656/7?u=lilith, which is another example of a function with this weird drop after a bunch of runs

LilithHafner added the timing results label Apr 28, 2024

LilithHafner changed the title ~~first run produces larger measurement~~ How to handle functions which run slowly the first few thousand times and fast on subsequent runs? Apr 28, 2024

LilithHafner added the help wanted Extra attention is needed label Apr 28, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

How to handle functions which run slowly the first few thousand times and fast on subsequent runs? #98

How to handle functions which run slowly the first few thousand times and fast on subsequent runs? #98

nsajko commented Apr 28, 2024

LilithHafner commented Apr 28, 2024

LilithHafner commented Apr 28, 2024 •

edited

Loading

LilithHafner commented Apr 28, 2024

How to handle functions which run slowly the first few thousand times and fast on subsequent runs? #98

How to handle functions which run slowly the first few thousand times and fast on subsequent runs? #98

Comments

nsajko commented Apr 28, 2024

LilithHafner commented Apr 28, 2024

LilithHafner commented Apr 28, 2024 • edited Loading

LilithHafner commented Apr 28, 2024

LilithHafner commented Apr 28, 2024 •

edited

Loading