Profile: `@profile` hanging on MacOS 12

[IanButterworth]

On master and 1.6.4, on MacOS (other platforms not tested yet)

               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.8.0-DEV.1183 (2021-12-28)
 _/ |\__'_|_|_|\__'_|  |  Commit 693b4471fa (0 days old master)
|__/                   |

julia> versioninfo()
Julia Version 1.8.0-DEV.1183
Commit 693b4471fa (2021-12-28 10:36 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin19.5.0)
  CPU: Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-12.0.1 (ORCJIT, skylake)
Environment:
  JULIA_NUM_THREADS = 6

(jl_ePM8ng) pkg> add FFMPEG
...
Precompiling project...
  44 dependencies successfully precompiled in 10 seconds. 3 already precompiled.

julia> using Profile

julia> @profile using FFMPEG
# hangs with no CPU usage

[DilumAluthge]

If you Ctrl-C out of it, is the stacktrace helpful?

[IanButterworth]

I forgot to add, ctrl-c does nothing. Neither does ctrl-z. All ctrl-t on MacOS does is

load: 12.52  cmd: julia 4042 waiting 6.10u 9.46s

no stack trace.

It seems like the signal handler has silently stopped.

Also, this doesn't happen on ubuntu

[IanButterworth]

Maybe this is a clue.. The following also hangs

julia> using Profile

julia> using Pkg

julia> @profile Pkg.update()

But one time it didn't immediately and I got:

julia> @profile Pkg.update()
    Updating registry at `~/.julia/registries/General`
   Installed LoweredCodeUtils ─ v2.2.0
   Installed JuliaInterpreter ─ v0.9.0
   Installed Revise ─────────── v3.3.0
    Updating ERROR: Exception handler triggered on unmanaged thread.
`~/.julia/environments/v1.6/Project.toml`
  [6e4b80f9] ↑ BenchmarkTools v1.2.0 ⇒ v1.2.2
  [9b87118b] ↑ PackageCompiler v2.0.2 ⇒ v2.0.4
  [295af30f] ↑ Revise v3.1.20 ⇒ v3.3.0
    Updating `~/.julia/environments/v1.6/Manifest.toml`
  [6e4b80f9] ↑ BenchmarkTools v1.2.0 ⇒ v1.2.2
  [34da2185] ↑ Compat v3.40.0 ⇒ v3.41.0
  [c8e1da08] ↑ IterTools v1.3.0 ⇒ v1.4.0
  [aa1ae85d] ↑ JuliaInterpreter v0.8.21 ⇒ v0.9.0
  [6f1432cf] ↑ LoweredCodeUtils v2.1.2 ⇒ v2.2.0
  [9b87118b] ↑ PackageCompiler v2.0.2 ⇒ v2.0.4
  [69de0a69] ↑ Parsers v2.1.2 ⇒ v2.1.3
  [21216c6a] ↑ Preferences v1.2.2 ⇒ v1.2.3
  [ae029012] ↑ Requires v1.1.3 ⇒ v1.2.0
  [295af30f] ↑ Revise v3.1.20 ⇒ v3.3.0
ERROR: Exception handler triggered on unmanaged thread.

then it hung.

Seems the thread is unknown
https://github.com/JuliaLang/julia/blob/master/src/signals-mach.c#L254-L268

[IanButterworth]

This doesn't happen on MacOS 10 on 1.6 or 1.7
Three MacOS 12 machines are now confirmed to hang.

MacOS internals have changed quite a lot between 10 and 12.

With @staticfloat's help, the paused MacOS 12 x86 machine was probed with lldb

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007ff802ab295a libsystem_pthread.dylib`os_unfair_lock_unlock
    frame #1: 0x00007ff80d81c77d libSystem.B.dylib`libSystem_atfork_parent + 13
    frame #2: 0x00007ff8029a46c4 libsystem_c.dylib`fork + 84
    frame #3: 0x000000010dc219df libjulia-internal.1.7.dylib`uv_spawn + 847
    frame #4: 0x000000010db4d975 libjulia-internal.1.7.dylib`jl_spawn + 165
    frame #5: 0x0000000126d0a07c sys.dylib`julia__spawn_primitive_21403.clone_1.clone_2 at process.jl:88
    frame #6: 0x0000000126d33bc9 sys.dylib`julia_setup_stdios_37254.clone_1.clone_2 at process.jl:113
    frame #7: 0x0000000126a58c10 sys.dylib`julia_YY.openYY.699_26034.clone_1.clone_2 at process.jl:112
    frame #8: 0x000000012640a141 sys.dylib`julia_YY.openYY.700_23607.clone_1 at process.jl:362
    frame #9: 0x000000012641652c sys.dylib`japi1_uncompress_registry_55677.clone_1 at process.jl:393
    frame #10: 0x00000001269edb0c sys.dylib`julia_RegistryInstance_16082.clone_1.clone_2 at registry_instance.jl:266
    frame #11: 0x00000001269ff3bd sys.dylib`japi1_YY.reachable_registriesYY.17_55530.clone_1.clone_2 at registry_instance.jl:373
    frame #12: 0x0000000126aa9898 sys.dylib`julia_YY.download_default_registriesYY.28_55732.clone_1.clone_2 at registry_instance.jl:345
    frame #13: 0x00000001101b7c3c
    frame #14: 0x00000001101b7f02
    frame #15: 0x00000001101b75af
    frame #16: 0x00000001101b762e
    frame #17: 0x00000001101b7308
    frame #18: 0x00000001101b73d2
    frame #19: 0x000000010db31800 libjulia-internal.1.7.dylib`do_call + 208
    frame #20: 0x000000010db2fa6a libjulia-internal.1.7.dylib`eval_body + 714
    frame #21: 0x000000010db2ff8b libjulia-internal.1.7.dylib`eval_body + 2027
    frame #22: 0x000000010db3033d libjulia-internal.1.7.dylib`jl_interpret_toplevel_thunk + 269
    frame #23: 0x000000010db4b490 libjulia-internal.1.7.dylib`jl_toplevel_eval_flex + 4848
    frame #24: 0x000000010db4b233 libjulia-internal.1.7.dylib`jl_toplevel_eval_flex + 4243
    frame #25: 0x000000010db4c506 libjulia-internal.1.7.dylib`jl_toplevel_eval_in + 150
    frame #26: 0x0000000126bd3ab3 sys.dylib`japi1_eval_user_input_48528.clone_1.clone_2 at boot.jl:373
    frame #27: 0x0000000126bd4431 sys.dylib`japi1_repl_backend_loop_48455.clone_1.clone_2 at REPL.jl:244
    frame #28: 0x00000001265fbf11 sys.dylib`japi1_start_repl_backend_46588.clone_1 at REPL.jl:229
    frame #29: 0x0000000126627a3b sys.dylib`julia_YY.run_replYY.47_47613.clone_1 at REPL.jl:362
    frame #30: 0x0000000126627b5c sys.dylib`japi1_run_repl_47031.clone_1 at REPL.jl:349
    frame #31: 0x000000010db183c1 libjulia-internal.1.7.dylib`jl_apply_generic + 1937
    frame #32: 0x0000000126425887 sys.dylib`julia_YY.930_45169.clone_1 at client.jl:394
    frame #33: 0x000000012642591c sys.dylib`jfptr_YY.930_45170.clone_1 + 12
    frame #34: 0x000000010db183c1 libjulia-internal.1.7.dylib`jl_apply_generic + 1937
    frame #35: 0x000000010db251ab libjulia-internal.1.7.dylib`jl_f__call_latest + 75
    frame #36: 0x0000000126a8a53e sys.dylib`julia_run_main_repl_44990.clone_1.clone_2 at essentials.jl:716
    frame #37: 0x0000000126a98fb6 sys.dylib`julia_exec_options_38230.clone_1.clone_2 at client.jl:309
    frame #38: 0x00000001262e06c0 sys.dylib`julia__start_28059.clone_1 at client.jl:495
    frame #39: 0x00000001262e0829 sys.dylib`jfptr__start_28060.clone_1 + 9
    frame #40: 0x000000010db183c1 libjulia-internal.1.7.dylib`jl_apply_generic + 1937
    frame #41: 0x000000010db6ed23 libjulia-internal.1.7.dylib`true_main + 179
    frame #42: 0x000000010db6ec14 libjulia-internal.1.7.dylib`jl_repl_entrypoint + 164
    frame #43: 0x000000010d3c2f79 julia`main + 9
    frame #44: 0x000000011b8954fe dyld`start + 462

(lldb) thread select 2
(lldb) bt
* thread #2
  * frame #0: 0x00007ff802a7420a libsystem_kernel.dylib`__ulock_wait + 10
    frame #1: 0x00007ff802ac32c5 libsystem_platform.dylib`_os_unfair_lock_lock_slow + 162
    frame #2: 0x000000011b89a642 dyld`dyld4::RuntimeState::withLoadersReadLock(void () block_pointer) + 34
    frame #3: 0x000000011b8b2c38 dyld`dyld4::APIs::findImageMappedAt(void const*, dyld3::MachOLoaded const**, bool*, char const**, void const**, unsigned long long*, unsigned char*) + 782
    frame #4: 0x000000011b8b5662 dyld`dyld4::APIs::_dyld_find_unwind_sections(void*, dyld_unwind_sections*) + 88
    frame #5: 0x000000010d534e73 libunwind.1.0.dylib`libunwind::UnwindCursor<libunwind::LocalAddressSpace, libunwind::Registers_x86_64>::setInfoBasedOnIPRegister(bool) + 65
    frame #6: 0x000000010d534d20 libunwind.1.0.dylib`libunwind::UnwindCursor<libunwind::LocalAddressSpace, libunwind::Registers_x86_64>::step() + 52
    frame #7: 0x000000010db5d75e libjulia-internal.1.7.dylib`jl_unw_stepn + 382
    frame #8: 0x000000010db5d5cc libjulia-internal.1.7.dylib`rec_backtrace_ctx + 92
    frame #9: 0x000000010db6f728 libjulia-internal.1.7.dylib`jl_throw_in_thread + 168
    frame #10: 0x000000010db70752 libjulia-internal.1.7.dylib`signal_listener + 1714
    frame #11: 0x00007ff802aaf4f4 libsystem_pthread.dylib`_pthread_start + 125
    frame #12: 0x00007ff802aab00f libsystem_pthread.dylib`thread_start + 15

(lldb) bt
* thread #4
  * frame #0: 0x00007ff802a7420a libsystem_kernel.dylib`__ulock_wait + 10
    frame #1: 0x00007ff802ac32c5 libsystem_platform.dylib`_os_unfair_lock_lock_slow + 162
    frame #2: 0x000000011b89a642 dyld`dyld4::RuntimeState::withLoadersReadLock(void () block_pointer) + 34
    frame #3: 0x000000011b8b2c38 dyld`dyld4::APIs::findImageMappedAt(void const*, dyld3::MachOLoaded const**, bool*, char const**, void const**, unsigned long long*, unsigned char*) + 782
    frame #4: 0x000000011b8b5662 dyld`dyld4::APIs::_dyld_find_unwind_sections(void*, dyld_unwind_sections*) + 88
    frame #5: 0x000000010d534e73 libunwind.1.0.dylib`libunwind::UnwindCursor<libunwind::LocalAddressSpace, libunwind::Registers_x86_64>::setInfoBasedOnIPRegister(bool) + 65
    frame #6: 0x000000010d534d20 libunwind.1.0.dylib`libunwind::UnwindCursor<libunwind::LocalAddressSpace, libunwind::Registers_x86_64>::step() + 52
    frame #7: 0x000000010db5d75e libjulia-internal.1.7.dylib`jl_unw_stepn + 382
    frame #8: 0x000000010db5d5cc libjulia-internal.1.7.dylib`rec_backtrace_ctx + 92
    frame #9: 0x000000010db6fc60 libjulia-internal.1.7.dylib`mach_profile_listener + 608
    frame #10: 0x00007ff802aaf4f4 libsystem_pthread.dylib`_pthread_start + 125
    frame #11: 0x00007ff802aab00f libsystem_pthread.dylib`thread_start + 15

A theory is that perhaps when libunwind calls _dyld_find_unwind_sections(), we may lock something that causes a deadlock.

But it seems odd that two threads are calling rec_backtrace_ctx() at the same time.

@vtjnash does anything jump out to you here?

Starting with one thread doesn't fix it

[staticfloat]

Could it be that we need to wrap jl_spawn() in jl_profile_atomic()?

[IanButterworth]

I tried to give that a go but couldn't see how to do that given jl_profile_atomic is currently only used in c++ but jl_spawn is in c

[IanButterworth]

So yeah, this is a mwe

julia> using Profile

julia> @profile while true
       run(`pwd`)
       end
/Users/ian
/Users/ian
# hang

[IanButterworth]

This isn't enough.
In https://github.com/JuliaLang/julia/blob/master/base/process.jl

@@ -86,6 +86,7 @@ const SpawnIOs = Vector{Any} # convenience name for readability
         handle = Libc.malloc(_sizeof_uv_process)
         disassociate_julia_struct(handle) # ensure that data field is set to C_NULL
         (; exec, flags, env, dir) = cmd
+        ccall(:jl_lock_profile, Cvoid, ())
         err = ccall(:jl_spawn, Int32,
                   (Cstring, Ptr{Cstring}, Ptr{Cvoid}, Ptr{Cvoid},
                    Ptr{Tuple{Cint, UInt}}, Int,
@@ -96,6 +97,7 @@ const SpawnIOs = Vector{Any} # convenience name for readability
             env === nothing ? C_NULL : env,
             isempty(dir) ? C_NULL : dir,
             @cfunction(uv_return_spawn, Cvoid, (Ptr{Cvoid}, Int64, Int32)))
+        ccall(:jl_unlock_profile, Cvoid, ())
     end
     if err != 0
         ccall(:jl_forceclose_uv, Cvoid, (Ptr{Cvoid},), handle) # will call free on handle eventually

So perhaps the issue exists for the duration of the spawned process not just while it's being spawned.. which would seem to indicate this is a macos bug?

[IanButterworth]

Could it be that we need to wrap jl_spawn() in jl_profile_atomic()?

Seems to work #43629