Profile.init time units

General Usage Performance
1

The documentation says the time units for the delay in Profile.init are in seconds, but the results I’m getting seem more consistent with 100th of a second. What’s going on? Julia 1.2.

Profile.init(10000000, 0.3)
Profile.clear()
@profile b = MyFirst.mysolve(f1, nhsub, nhsub.wtfast16yr)
Profile.print(;format=:flat, mincount=1000)

The highest count in the resulting profile in my code is 44169. If each tick is 0.3s that would be about 13,250s total. That’s over 3.5 hours, way more than the code took. Run time without profiling is more like 120 seconds, so 132 would be a plausible time.That’s what I’d get if the 0.3 delay in the init call above were multiplied by 1/100 seconds.

I don’t think this is double-counting from recursion. For example, the line that calls the optimizer, which is called only once, has a count of 38566.

2

judging from this line it looks like it is in seconds

https://github.com/JuliaLang/julia/blob/8c34ad352542c05b6f06d33dd67e2ecea593f828/stdlib/Profile/src/Profile.jl#L60

I might be wrong

3

It is in seconds. However, in Julia 1.2 format=:flat just aggregates entries in each backtrace. If your code is recursive, that means you can get more than one count per sampled backtrace. Fixed in https://github.com/JuliaLang/julia/pull/33190 (with more work in https://github.com/JuliaLang/julia/pull/33373) and discussed in the blog post.

1 Like
4

As I said, I don’t think recursion is the problem:

  1. The count I referred to is for
    myll(β) = -myllike(β, xp)
    in my top-level function. myllike is called repeatedly by the optimizer, invoked a few lines later, but is not itself recursive.
    Presumably the high count reflects the calls to the function rather than the literal execution of that line, which happens exactly once. The literal report was
    44169 ...n\Documents\KBD2\MyFirst\src\MyFirst.jl 157 (::getfield(MyFirst, Symbol("#myll#19")){MyFirst.MultipleWor...
  2. The top entry in tree view is
    50915 .\task.jl:268; (::getfield(Atom, Symbol("##19#21")){Array{Any,1}})()
    Since this is tree view, it shouldn’t be affected by the issue you mentioned. And, though I don’t really know what the code from the REPL above my code is doing, I presume the top of the tree is not recursive.
5

Do you get the same results if you profile from the plain REPL (i.e., from the unix/windows prompt) rather than inside Juno?

6

The counts are a little lower, but the same order of magnitude.
43.5k for top of the tree; 37.8k for top line in my code.
I profiled before doing any initial runs, so I assume there is some setup in there.
Wall clock was just over 2 minutes.

7

A little later in Profile.jl is interesting:

# init with default values
# Use a max size of 1M profile samples, and fire timer every 1ms
if Sys.iswindows()
    __init__() = init(1_000_000, 0.01)
else
    __init__() = init(1_000_000, 0.001)
end

The comment says the delay is 1ms and makes no OS distinctions.
So this means delay of 0.01 = 1ms on windows but
delay of 0.001 = 1ms elsewhere
So delay is in units of seconds when not on Windows. But …
If delay of 0.01 is 1e-3 seconds on MS-Windows then delay is in units of .1 seconds on Windows.
Then delay of 0.3, the argument I used, is 0.03 seconds. This would imply 4k samples in 130 seconds, which is still a factor of 10 less than what I actually got.

The documentation at Profiling · The Julia Language , like the comments in the code, says the argument delay is in seconds. It also says

The default setting is delay = 0.001 .

which matches the code comment that the timer fires every 1 ms, though it does not match the actual arguments in the init calls in the code shown above.

8

It’s quite possible that the comment is out of date, perhaps when it became realized that Windows has a hard time with short latency events.

Because the previous discussion involved code that I couldn’t run, let’s try to transition this to something we can all try. This is what I get on Linux:

julia> using Profile

julia> Profile.init(delay=0.001)

julia> @profile sleep(1)

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
1001 ./task.jl:333; (::REPL.var"#26#27"{REPL.REPLBacke...
 1001 ...v1.3/REPL/src/REPL.jl:118; macro expansion
  1001 ...v1.3/REPL/src/REPL.jl:86; eval_user_input(::Any, ::REPL.REP...
   1001 ./boot.jl:330; eval(::Module, ::Any)
    1001 ./asyncevent.jl:213; sleep(::Int64)
     1001 ./asyncevent.jl:128; wait
      1001 ./asyncevent.jl:110; _trywait(::Timer)
       1001 ./condition.jl:106; wait(::Base.GenericCondition{B...
        1001 ./task.jl:667; wait()
         1001 ./task.jl:660; poptaskref(::Base.InvasiveLi...

julia> Profile.init(delay=0.1)

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
10 ./task.jl:333; (::REPL.var"#26#27"{REPL.REPLBacken...
 10 .../v1.3/REPL/src/REPL.jl:118; macro expansion
  10 .../v1.3/REPL/src/REPL.jl:86; eval_user_input(::Any, ::REPL.REPL...
   10 ./boot.jl:330; eval(::Module, ::Any)
    10 ./asyncevent.jl:213; sleep(::Int64)
     10 ./asyncevent.jl:128; wait
      10 ./asyncevent.jl:110; _trywait(::Timer)
       10 ./condition.jl:106; wait(::Base.GenericCondition{Ba...
        10 ./task.jl:667; wait()
         10 ./task.jl:660; poptaskref(::Base.InvasiveLink...

As you can see, the results are entirely consistent with units of seconds. What platform are you on, and what do you get?

1 Like
9

I’m on Windows 10 Enterprise Build 16299, 64 bit.
Julia 1.2.0
MS Visual Studio 2017 and 2019 are also installed.
Running from the command prompt (no Juno). I seem to get about the same results regardless of the argument to init.

julia> Profile.init(delay=0.001)

julia> @profile sleep(1)

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
354 ....julia\packages\Gtk\mVhmL\src\events.jl:1; gtk_main()
 354 ...ackages\Gtk\mVhmL\src\GLib\signals.jl:167; g_sigatom(::Any)
  354 ...julia\packages\Gtk\mVhmL\src\events.jl:2; (::getfield(Gtk, Symbol("##237#238")))()
   1 ...ackages\Gtk\mVhmL\src\GLib\signals.jl:324; uv_dispatch(::Ptr{Nothing}, ::Ptr{Nothing}, ::Int64)

julia>  Profile.init(delay=0.1)

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
# this is weird.  Are there 2 top level calls here?
# if you look down you'll see a count of 357
1   .\client.jl:464; _start()
 1 .\client.jl:312; exec_options(::Base.JLOptions)
  1 .\client.jl:374; run_main_repl(::Bool, ::Bool, ::Bool, ::Bool, ::Bool)
   1 .\essentials.jl:789; invokelatest
    1 .\essentials.jl:790; #invokelatest#1
     1 .\client.jl:390; (::getfield(Base, Symbol("##737#739")){Bool,Bool,Bool,Boo...
      1 ...e\julia\stdlib\v1.2\REPL\src\REPL.jl:201; run_repl(::REPL.AbstractREPL, ::Any)
       1 ...\julia\stdlib\v1.2\REPL\src\REPL.jl:1038; run_frontend(::REPL.LineEditREPL, ::REPL.REPLBackendRef)
        1 ...ia\stdlib\v1.2\REPL\src\LineEdit.jl:2306; run_interface(::REPL.Terminals.TextTerminal, ::REPL.Li...
         1 .\essentials.jl:789; invokelatest
          1 .\essentials.jl:790; #invokelatest#1
           1 ...julia\stdlib\v1.2\REPL\src\REPL.jl:722; (::getfield(REPL, Symbol("#do_respond#38")){Bool,getf...
            1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:2246; transition
             1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:2242; transition(::Function, ::REPL.LineEdit.MIState, ::Any)
              1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:2210; activate(::REPL.LineEdit.TextInterface, ::REPL.Line...
               1 ...stdlib\v1.2\REPL\src\LineEdit.jl:1227; refresh_line(::Any, ::Any)
                1 ...stdlib\v1.2\REPL\src\LineEdit.jl:375; refresh_multi_line(::REPL.Terminals.TerminalBuffer...
                 1 ...stdlib\v1.2\REPL\src\LineEdit.jl:375; #refresh_multi_line#14(::Any, ::typeof(REPL.LineE...
                  1 ...tdlib\v1.2\REPL\src\LineEdit.jl:1663; refresh_multi_line(::REPL.Terminals.TerminalBuff...
                   1 ...tdlib\v1.2\REPL\src\LineEdit.jl:1664; #refresh_multi_line#37(::Any, ::typeof(REPL.Line...
                    1 .\none:0; (::getfield(REPL.LineEdit, Symbol("#kw##refresh_m...
                     1 ...dlib\v1.2\REPL\src\LineEdit.jl:382; #refresh_multi_line#16(::Any, ::Any, ::typeof(R...
                      1 ...lib\v1.2\REPL\src\Terminals.jl:79; width(::REPL.Terminals.TTYTerminal)
                       1 ...ib\v1.2\REPL\src\Terminals.jl:153; displaysize(::REPL.Terminals.TTYTerminal)
                        1 .\stream.jl:492; displaysize(::Base.TTY)
357 ...julia\packages\Gtk\mVhmL\src\events.jl:1; gtk_main()
 357 ...ackages\Gtk\mVhmL\src\GLib\signals.jl:167; g_sigatom(::Any)
  357 ...julia\packages\Gtk\mVhmL\src\events.jl:2; (::getfield(Gtk, Symbol("##237#238")))()

julia> Profile.init(delay=0.1)

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
1   .\client.jl:464; _start()
 1 .\client.jl:312; exec_options(::Base.JLOptions)
  1 .\client.jl:374; run_main_repl(::Bool, ::Bool, ::Bool, ::Bool, ::Bool)
   1 .\essentials.jl:789; invokelatest
    1 .\essentials.jl:790; #invokelatest#1
     1 .\client.jl:390; (::getfield(Base, Symbol("##737#739")){Bool,Bool,Bool,Boo...
      1 ...e\julia\stdlib\v1.2\REPL\src\REPL.jl:201; run_repl(::REPL.AbstractREPL, ::Any)
       1 ...\julia\stdlib\v1.2\REPL\src\REPL.jl:1038; run_frontend(::REPL.LineEditREPL, ::REPL.REPLBackendRef)
        1 ...ia\stdlib\v1.2\REPL\src\LineEdit.jl:2301; run_interface(::REPL.Terminals.TextTerminal, ::REPL.Li...
         1 ...ia\stdlib\v1.2\REPL\src\LineEdit.jl:2386; prompt!(::REPL.Terminals.TextTerminal, ::REPL.LineEdit...
          1 ...a\stdlib\v1.2\REPL\src\LineEdit.jl:2219; activate(::REPL.LineEdit.ModalInterface, ::REPL.LineE...
           1 ...a\stdlib\v1.2\REPL\src\LineEdit.jl:2216; activate(::REPL.LineEdit.TextInterface, ::REPL.LineE...
            1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:2210; activate(::REPL.LineEdit.TextInterface, ::REPL.LineE...
             1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:1227; refresh_line(::Any, ::Any)
              1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:466; refresh_multi_line(::REPL.Terminals.UnixTerminal, :...
               1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:468; #refresh_multi_line#17(::Any, ::typeof(REPL.LineEdi...
                1 ...stdlib\v1.2\REPL\src\LineEdit.jl:1663; refresh_multi_line(::REPL.Terminals.TerminalBuffe...
                 1 ...tdlib\v1.2\REPL\src\LineEdit.jl:1664; #refresh_multi_line#37(::Any, ::typeof(REPL.LineE...
                  1 .\none:0; (::getfield(REPL.LineEdit, Symbol("#kw##refresh_mu...
                   1 ...tdlib\v1.2\REPL\src\LineEdit.jl:382; #refresh_multi_line#16(::Any, ::Any, ::typeof(RE...
                    1 ...dlib\v1.2\REPL\src\Terminals.jl:79; width(::REPL.Terminals.TTYTerminal)
                     1 ...lib\v1.2\REPL\src\Terminals.jl:153; displaysize(::REPL.Terminals.TTYTerminal)
                      1 .\stream.jl:474; displaysize(::Base.TTY)
                       1 .\stream.jl:469; displaysize
                        1 .\env.jl:80; get
                         1 .\env.jl:11; access_env(::getfield(Base, Symbol("##459#460...
                          1 .\c.jl:250; cwstring(::String)
                           1 .\c.jl:299; transcode(::Type{UInt16}, ::Base.CodeUnits{...
                            1 .\array.jl:1021; sizehint!
359 ...julia\packages\Gtk\mVhmL\src\events.jl:1; gtk_main()
 359 ...ackages\Gtk\mVhmL\src\GLib\signals.jl:167; g_sigatom(::Any)
  359 ...julia\packages\Gtk\mVhmL\src\events.jl:2; (::getfield(Gtk, Symbol("##237#238")))()
   1 ...ackages\Gtk\mVhmL\src\GLib\signals.jl:324; uv_dispatch(::Ptr{Nothing}, ::Ptr{Nothing}, ::Int64)
    1 ...ackages\Gtk\mVhmL\src\GLib\signals.jl:228; g_yield(::UInt64)
     1 ...ackages\Gtk\mVhmL\src\GLib\signals.jl:207; g_siginterruptible(::typeof(yield), ::Function)
      1 .\task.jl:479; yield
       1 .\task.jl:591; wait()
        1 .\task.jl:586; poptaskref(::Base.InvasiveLinkedListSynchronized{Task})

julia> Profile.init(; delay=0.1)  # I thought maybe positional arguments were misinterpreted

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
346 ....julia\packages\Gtk\mVhmL\src\events.jl:1; gtk_main()
 346 ...ackages\Gtk\mVhmL\src\GLib\signals.jl:167; g_sigatom(::Any)
  346 ...julia\packages\Gtk\mVhmL\src\events.jl:2; (::getfield(Gtk, Symbol("##237#238")))()
10

What’s causing Gtk to load? Try it without that package. You can check

for (id, m) in Base.loaded_modules
    println(m)
end

to be sure it’s not present.

11

I was running in the environment I use for development. I started a clean session in a terminal. This got rid of gtk, but didn’t change the insensitivity of the counts to changes in delay. It also didn’t change an apparent top-level count of 1.

julia> for (id, m) in Base.loaded_modules; println(m); end
Markdown
Dates
Random
Sockets
Printf
Logging
REPL
SHA
Base
Future
UUIDs
FileWatching
Serialization
Mmap
Statistics
Core
Pkg
Unicode
Main
LibGit2
__PackagePrecompilationStatementModule
SharedArrays
InteractiveUtils
Test
CRC32c
Base64
Profile
DelimitedFiles
SuiteSparse
Libdl
SparseArrays
LinearAlgebra
Distributed

julia> using Profile

julia> Profile.init(delay=0.001)

julia> @profile sleep(1)

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
1   .\client.jl:464; _start()
 1 .\client.jl:312; exec_options(::Base.JLOptions)
  1 .\client.jl:374; run_main_repl(::Bool, ::Bool, ::Bool, ::Bool, ::Bool)
   1 .\essentials.jl:789; invokelatest
    1 .\essentials.jl:790; #invokelatest#1
     1 .\client.jl:390; (::getfield(Base, Symbol("##737#739")){Bool,Bool,Bool,Boo...
      1 ...e\julia\stdlib\v1.2\REPL\src\REPL.jl:201; run_repl(::REPL.AbstractREPL, ::Any)
       1 ...\julia\stdlib\v1.2\REPL\src\REPL.jl:1038; run_frontend(::REPL.LineEditREPL, ::REPL.REPLBackendRef)
        1 ...ia\stdlib\v1.2\REPL\src\LineEdit.jl:2306; run_interface(::REPL.Terminals.TextTerminal, ::REPL.Li...
         1 .\essentials.jl:789; invokelatest
          1 .\essentials.jl:790; #invokelatest#1
           1 ...julia\stdlib\v1.2\REPL\src\REPL.jl:722; (::getfield(REPL, Symbol("#do_respond#38")){Bool,getf...
            1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:2246; transition
             1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:2243; transition(::Function, ::REPL.LineEdit.MIState, ::Any)
              1 ...\stdlib\v1.2\REPL\src\LineEdit.jl:2222; commit_changes(::REPL.Terminals.UnixTerminal, ::Any)
               1 .\io.jl:545; write(::REPL.Terminals.TTYTerminal, ::Array{UInt8,1})
                1 .\io.jl:522; macro expansion
                 1 .\io.jl:238; unsafe_write(::REPL.Terminals.TTYTerminal, ::Ptr{...
                  1 .\stream.jl:931; unsafe_write(::Base.TTY, ::Ptr{UInt8}, ::UInt64)
                   1 .\stream.jl:877; uv_write(::Base.TTY, ::Ptr{UInt8}, ::UInt64)
                    1 .\stream.jl:907; uv_write_async(::Base.TTY, ::Ptr{UInt8}, ::UInt6...
337 .\task.jl:268; (::getfield(REPL, Symbol("##26#27")){REPL.REPLBackend})()
 337 ...re\julia\stdlib\v1.2\REPL\src\REPL.jl:118; macro expansion
  337 ...re\julia\stdlib\v1.2\REPL\src\REPL.jl:86; eval_user_input(::Any, ::REPL.REPLBackend)
   337 .\boot.jl:330; eval(::Module, ::Any)
    337 .\asyncevent.jl:188; sleep(::Int64)
     337 .\asyncevent.jl:116; wait(::Timer)
      337 .\stream.jl:47; stream_wait(::Timer, ::Base.GenericCondition{Base.Threa...
       337 .\condition.jl:104; wait(::Base.GenericCondition{Base.Threads.SpinLock})
        337 .\task.jl:591; wait()
         337 .\task.jl:564; poptaskref(::Base.InvasiveLinkedListSynchronized{Task})

julia> Profile.init(delay=0.1)

julia> Profile.clear()

julia> @profile sleep(1)

julia> Profile.print()
1   .\client.jl:464; _start()
 1 .\client.jl:312; exec_options(::Base.JLOptions)
  1 .\client.jl:374; run_main_repl(::Bool, ::Bool, ::Bool, ::Bool, ::Bool)
   1 .\essentials.jl:789; invokelatest
    1 .\essentials.jl:790; #invokelatest#1
     1 .\client.jl:390; (::getfield(Base, Symbol("##737#739")){Bool,Bool,Bool,Boo...
      1 ...e\julia\stdlib\v1.2\REPL\src\REPL.jl:201; run_repl(::REPL.AbstractREPL, ::Any)
       1 ...\julia\stdlib\v1.2\REPL\src\REPL.jl:1038; run_frontend(::REPL.LineEditREPL, ::REPL.REPLBackendRef)
        1 ...ia\stdlib\v1.2\REPL\src\LineEdit.jl:2301; run_interface(::REPL.Terminals.TextTerminal, ::REPL.Li...
         1 ...ia\stdlib\v1.2\REPL\src\LineEdit.jl:2390; prompt!(::REPL.Terminals.TextTerminal, ::REPL.LineEdit...
          1 ...a\stdlib\v1.2\REPL\src\LineEdit.jl:1342; match_input(::Dict, ::Any)
           1 ...a\stdlib\v1.2\REPL\src\LineEdit.jl:1342; match_input(::Dict, ::Any, ::Any, ::Any, ::Any)
            1 .\io.jl:290; eof(::REPL.Terminals.TTYTerminal)
             1 .\stream.jl:61; eof(::Base.TTY)
              1 .\stream.jl:376; wait_readnb(::Base.TTY, ::Int64)
               1 .\condition.jl:104; wait(::Base.GenericCondition{Base.Threads.SpinLock})
                1 .\task.jl:591; wait()
                 1 .\task.jl:564; poptaskref(::Base.InvasiveLinkedListSynchronized{...
337 .\task.jl:268; (::getfield(REPL, Symbol("##26#27")){REPL.REPLBackend})()
 337 ...re\julia\stdlib\v1.2\REPL\src\REPL.jl:118; macro expansion
  337 ...re\julia\stdlib\v1.2\REPL\src\REPL.jl:86; eval_user_input(::Any, ::REPL.REPLBackend)
   337 .\boot.jl:330; eval(::Module, ::Any)
    337 .\asyncevent.jl:188; sleep(::Int64)
     337 .\asyncevent.jl:116; wait(::Timer)
      337 .\stream.jl:47; stream_wait(::Timer, ::Base.GenericCondition{Base.Threa...
       337 .\condition.jl:104; wait(::Base.GenericCondition{Base.Threads.SpinLock})
        337 .\task.jl:591; wait()
         337 .\task.jl:564; poptaskref(::Base.InvasiveLinkedListSynchronized{Task})

By the way, 337 counts a second seems about right for the profiles that prompted my initial post, with a count of around 44k in ~130 seconds.

12

OK, I tried this on Windows in a VM. I get the same thing you do. Care to file an issue?

13

@tim.holy , if I try your example with sleep on Mac, I don’t get any counts (on some recent julia master)

julia> using Profile

julia> Profile.init(delay=0.001)

julia> @profile sleep(1)

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 /usr/local/julia/usr/share/julia/stdlib/v1.4/Profile/src/Profile.jl:849

Is that expected?

1 Like
14

Definitely not. Is Linux the only platform where the profiler is working?

It is also worth considering whether there’s a difference between source-builds and binary downloads. https://github.com/JuliaLang/julia/issues/28648 is closed now, but it indicates that this has been relevant in the past. My Linux source build works as expected, as does a Linux binary I tested; my Windows binary does not.

15

Opened https://github.com/JuliaLang/julia/issues/33834.
I hope that was the right place.

@juthohaegeman I included a shout-out to the problem on a Mac, but the bug report focuses on Windows.

On windows it’s acting as if the delay is just hard-coded.

1 Like