linux Profile double-counting number of snapshots

[vtjnash]

julia> using Profile

julia> @profile sleep(1)

julia> Profile.print()
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
    ╎1023 @Base/task.jl:358; (::REPL.var"#26#27"{REPL.REPLBackend})()
    ╎ 1023 @REPL/src/REPL.jl:118; macro expansion
    ╎  1023 @REPL/src/REPL.jl:86; eval_user_input(::Any, ::REPL.REPLBackend)
  21╎   1023 @Base/boot.jl:331; eval(::Module, ::Any)
    ╎    1001 @Base/asyncevent.jl:213; sleep(::Int64)
    ╎     1001 @Base/asyncevent.jl:128; wait
    ╎    ╎ 1001 @Base/asyncevent.jl:110; _trywait(::Timer)
    ╎    ╎  1001 @Base/condition.jl:106; wait(::Base.GenericCondition{Base.Threads.SpinLock})
    ╎    ╎   1001 @Base/task.jl:709; wait()
1001╎    ╎    1001 @Base/task.jl:702; poptaskref(::Base.InvasiveLinkedListSynchronized{Task})
Total snapshots: 2049

Since the stackwalk contains an actual NULL (terminating it), plus we separate them will NULL, we end up with the wrong count here.

[IanButterworth]

The total on MacOS is 4x the expected, while actual recorded samples is far fewer.
Edit: On reflection, perhaps the compilation and run of the first @profile call is actually taking close to 4 seconds

Also, sampling only seems to be working when compilation occurs

               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.7.0-DEV.185 (2020-12-29)
 _/ |\__'_|_|_|\__'_|  |  Commit 770e228c61 (9 days old master)
|__/                   |

julia> using Profile

julia> Profile.init()
(10000000, 0.001)

julia> sleep(1)

julia> @profile sleep(1)

julia> Profile.print()
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
    ╎3    @Base/client.jl:492; _start()
    ╎ 3    @Base/client.jl:309; exec_options(opts::Base.JLOpti...
    ╎  3    @Base/client.jl:379; run_main_repl(interactive::Boo...
    ╎   3    @Base/essentials.jl:708; invokelatest
    ╎    3    @Base/essentials.jl:710; #invokelatest#2
    ╎     3    @Base/client.jl:394; (::Base.var"#888#890"{Bool, ...
    ╎    ╎ 3    .../REPL/src/REPL.jl:305; run_repl(repl::REPL.Abstrac...
    ╎    ╎  3    .../REPL/src/REPL.jl:317; run_repl(repl::REPL.Abstrac...
    ╎    ╎   3    ...REPL/src/REPL.jl:185; start_repl_backend(backend...
    ╎    ╎    3    ...REPL/src/REPL.jl:200; repl_backend_loop(backend...
    ╎    ╎     3    ...EPL/src/REPL.jl:139; eval_user_input(ast::Any,...
   3╎    ╎    ╎ 3    @Base/boot.jl:369; eval(m::Module, e::Any)
Total snapshots: 4512

julia> @profile sleep(1)

julia> Profile.print()
┌ Warning: There were no samples collected. Run your program longer (perhaps by
│ running it multiple times), or adjust the delay between samples with
│ `Profile.init()`.
└ @ Profile /Users/julia/buildbot/worker/package_macos64/build/usr/share/julia/stdlib/v1.7/Profile/src/Profile.jl:863

julia> @profile sleep(1)

julia> Profile.print()
┌ Warning: There were no samples collected. Run your program longer (perhaps by
│ running it multiple times), or adjust the delay between samples with
│ `Profile.init()`.
└ @ Profile /Users/julia/buildbot/worker/package_macos64/build/usr/share/julia/stdlib/v1.7/Profile/src/Profile.jl:863

The same is true on the LLVM Libunwind PR #39127

julia> using Profile

julia> Profile.init()
(10000000, 0.001)

julia> sleep(1)

julia> @profile sleep(1)

julia> Profile.print()
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
    ╎3    @Base/client.jl:492; _start()
    ╎ 3    @Base/client.jl:309; exec_options(opts::Base.JLOptions)
    ╎  3    @Base/client.jl:379; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
    ╎   3    @Base/essentials.jl:708; invokelatest
    ╎    3    @Base/essentials.jl:710; #invokelatest#2
    ╎     3    @Base/client.jl:394; (::Base.var"#890#892"{Bool, Bool, Bool})(REPL::Module)
    ╎    ╎ 3    @REPL/src/REPL.jl:305; run_repl(repl::REPL.AbstractREPL, consumer::Any)
    ╎    ╎  3    @REPL/src/REPL.jl:317; run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool)
    ╎    ╎   3    @REPL/src/REPL.jl:185; start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
    ╎    ╎    3    @REPL/src/REPL.jl:200; repl_backend_loop(backend::REPL.REPLBackend)
    ╎    ╎     3    @REPL/src/REPL.jl:139; eval_user_input(ast::Any, backend::REPL.REPLBackend)
   2╎    ╎    ╎ 3    @Base/boot.jl:369; eval(m::Module, e::Any)
    ╎    ╎    ╎  1    @Base/compiler/typeinfer.jl:874; typeinf_ext_toplevel(mi::Core.MethodInstance, world::UInt64)
    ╎    ╎    ╎   1    @Base/compiler/typeinfer.jl:878; typeinf_ext_toplevel(interp::Core.Compiler.NativeInterpreter, linfo::Core.MethodInstance)
    ╎    ╎    ╎    1    @Base/compiler/typeinfer.jl:843; typeinf_ext(interp::Core.Compiler.NativeInterpreter, mi::Core.MethodInstance)
    ╎    ╎    ╎     1    @Base/compiler/types.jl:33; InferenceResult
    ╎    ╎    ╎    ╎ 1    @Base/compiler/types.jl:33; InferenceResult
   1╎    ╎    ╎    ╎  1    @Base/compiler/inferenceresult.jl:50; matching_cache_argtypes(linfo::Core.MethodInstance, #unused#::Nothing)
Total snapshots: 4368

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
┌ Warning: There were no samples collected. Run your program longer (perhaps by
│ running it multiple times), or adjust the delay between samples with
│ `Profile.init()`.
└ @ Profile ~/Documents/GitHub/julia/usr/share/julia/stdlib/v1.7/Profile/src/Profile.jl:863

julia> @profile sleep(1)

julia> Profile.print()
┌ Warning: There were no samples collected. Run your program longer (perhaps by
│ running it multiple times), or adjust the delay between samples with
│ `Profile.init()`.
└ @ Profile ~/Documents/GitHub/julia/usr/share/julia/stdlib/v1.7/Profile/src/Profile.jl:863

Related issue #38350