We have been using OpenMP with Imagick for as long as I can remember (several years), but after our system was recently updated system to FreeBSD 13.2 (RELEASE-p9) we have started experiencing random instances of processes getting locked at 100% CPU usage with truss revealing that sched_yield(); is being infinitely called on the locked processes. The locked processes never finish, and the only solution is to manually kill them.
When googling this issue, I was only able to find two mentions of this, and both seemed to point to this being a potential issue with compiling Imagick with OpenMP enabled on FreeBSD 13.2.
Has anyone else experienced this? If this is the case, is there a solution in the works? Disabling threads isn't a workable solution for us, since doing this significantly increases the amount of time it takes to process each image (5x or more), and we process a fairly large number of images on a daily basis.
For reference: FreeBSD 13.2-RELEASE-p9, PHP 8.1.27 (cli), ImageMagick 7.1.1-26.
The couple of similar mentions that I've seen of this can be found here:
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=274135
https://forums.freebsd.org/threads/issue-with-ule-scheduler.85307/
Here is an example debug log showing the process locking with sched_yield(), and then never releasing.
(gdb) thread apply all bt
Thread 1 (LWP 101575 of process 33247):
#0 sched_yield () at sched_yield.S:4
#1 0x00000008456d0491 in __kmp_wait_4_ptr (spinner=0x84573151c <__kmp_initz_lock+28>, checker=1, pred=0x8456eab50 <__kmp_bakery_check(void*, unsigned int)>, obj=0x845731500 <__kmp_initz_lock>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_dispatch.cpp:2695
#2 0x00000008456e97c8 in __kmp_acquire_ticket_lock_timed_template (lck=0x0, gtid=<optimized out>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.cpp:640
#3 __kmp_acquire_ticket_lock (lck=0x0, gtid=<optimized out>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.cpp:645
#4 0x00000008456ef564 in __kmp_acquire_bootstrap_lock (lck=0x84573151c <__kmp_initz_lock+28>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.h:524
#5 __kmp_get_global_thread_id_reg () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:253
#6 0x00000008456af91e in __kmp_entry_thread () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp.h:3401
#7 kmpc_malloc (size=35524908316) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_alloc.cpp:1098
#8 0x000000084572a1b7 in __kmp_is_address_mapped (addr=0x847bad5c8) at /usr/src/contrib/llvm-project/openmp/runtime/src/z_Linux_util.cpp:2067
#9 0x00000008456f9925 in __kmp_register_library_startup () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:6774
#10 0x00000008456ef5c4 in __kmp_do_serial_initialize () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:6966
#11 0x00000008456ef578 in __kmp_get_global_thread_id_reg () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:255
#12 0x00000008456da0b2 in __kmp_api_omp_init_lock (user_lock=0x84573151c <__kmp_initz_lock+28>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_ftn_entry.h:1083
#13 0x0000000845bb773c in MagickCoreGenesis () from /usr/local/lib/libMagickCore-7.so.10
#14 0x00000008451f4d8e in zm_startup_imagick () from /usr/local/lib/php/20230831-debug/imagick.so
#15 0x000000000083b010 in zend_startup_module_ex ()
#16 0x000000000083bb10 in ?? ()
#17 0x0000000000853131 in zend_hash_apply ()
#18 0x000000000083b90c in zend_startup_modules ()
#19 0x0000000000766b0f in php_module_startup ()
#20 0x00000000009f51e9 in ?? ()
#21 0x00000000009f37a4 in ?? ()
#22 0x0000000000423720 in _start ()
(gdb)
And here is a second process that locked at the same time (pid 33248 vs 33247):
(gdb) thread apply all bt
Thread 1 (LWP 100499 of process 33248):
#0 sched_yield () at sched_yield.S:4
#1 0x00000008495aa491 in __kmp_wait_4_ptr (spinner=0x84960b51c <__kmp_initz_lock+28>, checker=1, pred=0x8495c4b50 <__kmp_bakery_check(void*, unsigned int)>, obj=0x84960b500 <__kmp_initz_lock>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_dispatch.cpp:2695
#2 0x00000008495c37c8 in __kmp_acquire_ticket_lock_timed_template (lck=0x0, gtid=<optimized out>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.cpp:640
#3 __kmp_acquire_ticket_lock (lck=0x0, gtid=<optimized out>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.cpp:645
#4 0x00000008495c9564 in __kmp_acquire_bootstrap_lock (lck=0x84960b51c <__kmp_initz_lock+28>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.h:524
#5 __kmp_get_global_thread_id_reg () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:253
#6 0x000000084958991e in __kmp_entry_thread () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp.h:3401
#7 kmpc_malloc (size=35590812956) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_alloc.cpp:1098
#8 0x00000008496041b7 in __kmp_is_address_mapped (addr=0x847bad5c8) at /usr/src/contrib/llvm-project/openmp/runtime/src/z_Linux_util.cpp:2067
#9 0x00000008495d3925 in __kmp_register_library_startup () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:6774
#10 0x00000008495c95c4 in __kmp_do_serial_initialize () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:6966
#11 0x00000008495c9578 in __kmp_get_global_thread_id_reg () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:255
#12 0x00000008495b40b2 in __kmp_api_omp_init_lock (user_lock=0x84960b51c <__kmp_initz_lock+28>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_ftn_entry.h:1083
#13 0x000000084b24773c in MagickCoreGenesis () from /usr/local/lib/libMagickCore-7.so.10
#14 0x000000084a26bd8e in zm_startup_imagick () from /usr/local/lib/php/20230831-debug/imagick.so
#15 0x000000000083b010 in zend_startup_module_ex ()
#16 0x000000000083bb10 in ?? ()
#17 0x0000000000853131 in zend_hash_apply ()
#18 0x000000000083b90c in zend_startup_modules ()
#19 0x0000000000766b0f in php_module_startup ()
#20 0x00000000009f51e9 in ?? ()
#21 0x00000000009f37a4 in ?? ()
#22 0x0000000000423720 in _start ()
(gdb)
We have also tried updating to PHP 8.3.4, and the problem still remains.
Update: I have taken Imagick out of the equation and have recreated the same bug with just ImageMagick using the command-line convert operation. To recreate the bug outside of PHP, I created two processes, with each process repeatedly adding a watermark to another image, and then I just waited for something to lock up.
I am adding watermarks to the top-left corner of another image using the following: convert 'originalfile.jpg' 'watermarkfile.png' -set colorspace sRGB -gravity NorthWest -geometry +3+3 -define compose:args=20,100 -compose dissolve -composite 'resultingfile.jpg'
The trace information for the resulting locked processes from just using convert are as follows:
(gdb) thread apply all bt
Thread 1 (LWP 101740 of process 79048):
#0 sched_yield () at sched_yield.S:4
#1 0x0000000824f60491 in __kmp_wait_4_ptr (spinner=0x824fc151c <__kmp_initz_lock+28>, checker=1, pred=0x824f7ab50 <__kmp_bakery_check(void*, unsigned int)>, obj=0x824fc1500 <__kmp_initz_lock>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_dispatch.cpp:2695
#2 0x0000000824f797c8 in __kmp_acquire_ticket_lock_timed_template (lck=0x0, gtid=<optimized out>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.cpp:640
#3 __kmp_acquire_ticket_lock (lck=0x0, gtid=<optimized out>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.cpp:645
#4 0x0000000824f7f564 in __kmp_acquire_bootstrap_lock (lck=0x824fc151c <__kmp_initz_lock+28>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.h:524
#5 __kmp_get_global_thread_id_reg () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:253
#6 0x0000000824f3f91e in __kmp_entry_thread () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp.h:3401
#7 kmpc_malloc (size=34980238620) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_alloc.cpp:1098
#8 0x0000000824fba1b7 in __kmp_is_address_mapped (addr=0x8242955c8) at /usr/src/contrib/llvm-project/openmp/runtime/src/z_Linux_util.cpp:2067
#9 0x0000000824f89925 in __kmp_register_library_startup () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:6774
#10 0x0000000824f7f5c4 in __kmp_do_serial_initialize () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:6966
#11 0x0000000824f7f578 in __kmp_get_global_thread_id_reg () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:255
#12 0x0000000824f6a0b2 in __kmp_api_omp_init_lock (user_lock=0x824fc151c <__kmp_initz_lock+28>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_ftn_entry.h:1083
#13 0x0000000821df77ac in MagickCoreGenesis () from /usr/local/lib/libMagickCore-7.so.10
#14 0x0000000000202512 in ?? ()
#15 0x00000000002022f0 in ?? ()
#16 0x00000000002021f0 in ?? ()
#17 0x0000000000000000 in ?? ()
And
(gdb) thread apply all bt
Thread 1 (LWP 153345 of process 79049):
#0 sched_yield () at sched_yield.S:4
#1 0x0000000825da5491 in __kmp_wait_4_ptr (spinner=0x825e0651c <__kmp_initz_lock+28>, checker=1, pred=0x825dbfb50 <__kmp_bakery_check(void*, unsigned int)>, obj=0x825e06500 <__kmp_initz_lock>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_dispatch.cpp:2695
#2 0x0000000825dbe7c8 in __kmp_acquire_ticket_lock_timed_template (lck=0x0, gtid=<optimized out>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.cpp:640
#3 __kmp_acquire_ticket_lock (lck=0x0, gtid=<optimized out>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.cpp:645
#4 0x0000000825dc4564 in __kmp_acquire_bootstrap_lock (lck=0x825e0651c <__kmp_initz_lock+28>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_lock.h:524
#5 __kmp_get_global_thread_id_reg () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:253
#6 0x0000000825d8491e in __kmp_entry_thread () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp.h:3401
#7 kmpc_malloc (size=34995201308) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_alloc.cpp:1098
#8 0x0000000825dff1b7 in __kmp_is_address_mapped (addr=0x8246965c8) at /usr/src/contrib/llvm-project/openmp/runtime/src/z_Linux_util.cpp:2067
#9 0x0000000825dce925 in __kmp_register_library_startup () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:6774
#10 0x0000000825dc45c4 in __kmp_do_serial_initialize () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:6966
#11 0x0000000825dc4578 in __kmp_get_global_thread_id_reg () at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_runtime.cpp:255
#12 0x0000000825daf0b2 in __kmp_api_omp_init_lock (user_lock=0x825e0651c <__kmp_initz_lock+28>) at /usr/src/contrib/llvm-project/openmp/runtime/src/kmp_ftn_entry.h:1083
#13 0x00000008226c37ac in MagickCoreGenesis () from /usr/local/lib/libMagickCore-7.so.10
#14 0x0000000000202512 in ?? ()
#15 0x00000000002022f0 in ?? ()
#16 0x00000000002021f0 in ?? ()
#17 0x0000000000000000 in ?? ()
This really is an issue in the LLVM OpenMP runtime (I created an issue for this: https://github.com/llvm/llvm-project/issues/86684).
I'm not sure why you didn't see this issue before. It might be the case that FreeBSD moved from gcc compiled ImageMagick to clang compiled ImageMagick.
Unfortunately, I have no idea how to mitigate the issue until it is fixed.