Profile: `@profile` hanging on MacOS 12 #43578

IanButterworth · 2021-12-28T16:31:22Z

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

The text was updated successfully, but these errors were encountered:

DilumAluthge · 2021-12-28T20:22:08Z

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

IanButterworth · 2021-12-28T21:02:53Z

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 · 2021-12-28T21:19:04Z

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 · 2021-12-28T21:56:10Z

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 · 2021-12-29T00:42:27Z

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

IanButterworth · 2021-12-29T04:29:39Z

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 · 2021-12-31T05:48:51Z

So yeah, this is a mwe

julia> using Profile

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

IanButterworth · 2022-01-02T01:05:21Z

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

Seems to work #43629

vtjnash · 2022-01-07T07:33:59Z

It is a macOS bug introduced into dyld3 (specifically dyld-732.8 on Jan 31 2020). This however appears to be dyld4 now, but Apple has failed so far to provide source code for it https://github.com/apple-oss-distributions/dyld/. It is sad that there was a warning comment here in dyld2, but that failed to get copied into dyld3.

vtjnash · 2022-01-07T07:36:14Z

We can work-around this in the same way that we used to work-around the buggy keymgr stuff, which Apple eventually deleted because of this exact problem. The only challenge will be making this still link on older systems (so we cannot uses the symbols directly as I did here, but need to make them weak imports).

diff --git a/src/signals-mach.c b/src/signals-mach.c
index 57dcc96906..be6a8b67c4 100644
--- a/src/signals-mach.c
+++ b/src/signals-mach.c
@@ -31,6 +31,11 @@ extern void *_keymgr_get_and_lock_processwide_ptr(unsigned int key);
 extern int _keymgr_get_and_lock_processwide_ptr_2(unsigned int key, void **result);
 extern int _keymgr_set_lockmode_processwide_ptr(unsigned int key, unsigned int mode);
 
+// private dyld3/dyld4 stuff
+extern void _dyld_atfork_prepare(void);
+extern void _dyld_atfork_parent(void);
+//extern void _dyld_fork_child(void);
+
 static void attach_exception_port(thread_port_t thread, int segv_only);
 
 // low 16 bits are the thread id, the next 8 bits are the original gc_state
@@ -540,6 +545,7 @@ void *mach_profile_listener(void *arg)
         jl_lock_profile();
         void *unused = NULL;
         int keymgr_locked = _keymgr_get_and_lock_processwide_ptr_2(KEYMGR_GCC3_DW2_OBJ_LIST, &unused) == 0;
+        _dyld_atfork_prepare();
         jl_shuffle_int_array_inplace(profile_round_robin_thread_order, jl_n_threads, &profile_cong_rng_seed);
         for (int idx = jl_n_threads; idx-- > 0; ) {
             // Stop the threads in the random round-robin order.
@@ -609,6 +615,7 @@ void *mach_profile_listener(void *arg)
             // We're done! Resume the thread.
             jl_thread_resume(i, 0);
         }
+        _dyld_atfork_parent();
         if (keymgr_locked)
             _keymgr_unlock_processwide_ptr(KEYMGR_GCC3_DW2_OBJ_LIST);
         jl_unlock_profile();

IanButterworth · 2022-01-07T14:06:27Z

Thanks @vtjnash is this something apple is aware of? How did you identify it?

Apple reintroduced the old bug that we previously worked around in fad04d3 with a similar patch to this. Fixes #43578

vtjnash · 2022-01-07T17:28:43Z

I don't think they are aware of it. I identified it because it is not the first time they have had this bug.

Apple reintroduced the old bug that we previously worked around in fad04d3 with a similar patch to this. This is needed anywhere that we may attempt to stop threads. Fixes #43578

Apple reintroduced the old bug that we previously worked around in fad04d3 with a similar patch to this. This is needed anywhere that we may attempt to stop threads. Fixes JuliaLang#43578

Apple reintroduced the old bug that we previously worked around in fad04d3 with a similar patch to this. This is needed anywhere that we may attempt to stop threads. Fixes #43578 (cherry picked from commit 2939272)

Apple reintroduced the old bug that we previously worked around in fad04d3 with a similar patch to this. This is needed anywhere that we may attempt to stop threads. Fixes JuliaLang#43578

Apple reintroduced the old bug that we previously worked around in fad04d3 with a similar patch to this. This is needed anywhere that we may attempt to stop threads. Fixes #43578 (cherry picked from commit 2939272)

Extend the fix for #43578 (2939272) to cover the deadlock bug present internally in dyld4 inside the function we use to avoid the previous deadlock issue. Fix #49733

Extend the fix for JuliaLang#43578 (2939272) to cover the deadlock bug present internally in dyld4 inside the function we use to avoid the previous deadlock issue. Fix JuliaLang#49733

IanButterworth added kind:bug Indicates an unexpected problem or unintended behavior profiler labels Dec 28, 2021

IanButterworth added the system:mac Affects only macOS label Dec 28, 2021

IanButterworth changed the title ~~Profile: @profile using Foo hangs for non-sysimaged package~~ Profile: @profile using Foo hangs for non-sysimaged package on MacOS Dec 28, 2021

IanButterworth changed the title ~~Profile: @profile using Foo hangs for non-sysimaged package on MacOS~~ Profile: @profile hanging on MacOS 12 Dec 28, 2021

This comment has been minimized.

Sign in to view

IanButterworth mentioned this issue Jan 2, 2022

jl_profile_atomic lock around jl_spawn to prevent macos profiling deadlock #43629

Closed

IanButterworth mentioned this issue Jan 2, 2022

@profview hanging timholy/ProfileView.jl#185

Closed

vtjnash added a commit that referenced this issue Jan 7, 2022

macOS: workaround a dyld/libunwind deadlock issue since 12.1

a51e2d8

Apple reintroduced the old bug that we previously worked around in fad04d3 with a similar patch to this. Fixes #43578

vtjnash mentioned this issue Jan 7, 2022

macOS: workaround a dyld/libunwind deadlock issue since 12.1 #43701

Merged

vtjnash closed this as completed in #43701 Jan 13, 2022

mkitti mentioned this issue Aug 3, 2022

try 1.8.0.rc4 conda-forge/julia-feedstock#212

Merged

5 tasks

vtjnash added a commit that referenced this issue May 10, 2023

macOS: avoid deadlock inside dyld4 deadlock workaround

2adebab

Extend the fix for #43578 (2939272) to cover the deadlock bug present internally in dyld4 inside the function we use to avoid the previous deadlock issue. Fix #49733

vtjnash mentioned this issue May 10, 2023

macOS: avoid deadlock inside dyld4 deadlock workaround #49740

Merged

vtjnash added a commit that referenced this issue May 10, 2023

macOS: avoid deadlock inside dyld4 deadlock workaround

540f283

Extend the fix for #43578 (2939272) to cover the deadlock bug present internally in dyld4 inside the function we use to avoid the previous deadlock issue. Fix #49733

benz0li mentioned this issue May 28, 2023

Alternative to copying part of a recent Xcode libSystem.tbd to src/mach_dyld_atfork.tbd #49976

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Profile: `@profile` hanging on MacOS 12 #43578

Profile: `@profile` hanging on MacOS 12 #43578

IanButterworth commented Dec 28, 2021

DilumAluthge commented Dec 28, 2021

IanButterworth commented Dec 28, 2021 •

edited

Loading

IanButterworth commented Dec 28, 2021

IanButterworth commented Dec 28, 2021 •

edited

Loading

staticfloat commented Dec 29, 2021

IanButterworth commented Dec 29, 2021 •

edited

Loading

IanButterworth commented Dec 31, 2021

This comment has been minimized.

IanButterworth commented Jan 2, 2022

vtjnash commented Jan 7, 2022

vtjnash commented Jan 7, 2022

IanButterworth commented Jan 7, 2022

vtjnash commented Jan 7, 2022

Profile: @profile hanging on MacOS 12 #43578

Profile: @profile hanging on MacOS 12 #43578

Comments

IanButterworth commented Dec 28, 2021

DilumAluthge commented Dec 28, 2021

IanButterworth commented Dec 28, 2021 • edited Loading

IanButterworth commented Dec 28, 2021

IanButterworth commented Dec 28, 2021 • edited Loading

staticfloat commented Dec 29, 2021

IanButterworth commented Dec 29, 2021 • edited Loading

IanButterworth commented Dec 31, 2021

This comment has been minimized.

IanButterworth commented Jan 2, 2022

vtjnash commented Jan 7, 2022

vtjnash commented Jan 7, 2022

IanButterworth commented Jan 7, 2022

vtjnash commented Jan 7, 2022

Profile: `@profile` hanging on MacOS 12 #43578

Profile: `@profile` hanging on MacOS 12 #43578

IanButterworth commented Dec 28, 2021 •

edited

Loading

IanButterworth commented Dec 28, 2021 •

edited

Loading

IanButterworth commented Dec 29, 2021 •

edited

Loading