Bug#954197: gegl: FTBFS (most often on arm64, armhf): gegl:simple / backend-file times out

Wed Mar 18 09:31:46 GMT 2020

On Wed, 18 Mar 2020 at 08:29:06 +0000, Simon McVittie wrote:
> https://gitlab.gnome.org/GNOME/gegl/issues/226 appears to be the same thing
> on x86_64. I suspect it might be a race condition or otherwise
> intermittent: in the past this test also timed out on armel, but my recent
> upload worked fine on armel. Perhaps there is something about the ARM
> family of architectures that makes this more likely to happen there.

I reproduced this on the arm64 porterbox 'amdahl' by running that test
1000 times in a loop. After a while, output stopped.

>From the backtrace below it appears that there is a deadlock between
threads 1 and 6, which are both waiting for the same mutex. This might
be a GLib bug.

    smcv

Thread 6 (Thread 0xffff95366ce0 (LWP 1856)):
#0  syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1  0x0000ffff97f6f588 in g_mutex_lock_slowpath (mutex=0xffff97cee280 <g.inotify_lock_lock>) at ../../../glib/gthread-posix.c:1457
#2  0x0000ffff97f700b8 in g_mutex_lock (mutex=<optimized out>) at ../../../glib/gthread-posix.c:1482
#3  0x0000ffff97c4c00c in _ih_sub_cancel (sub=0xaaaac48fad60) at ../../../gio/inotify/inotify-helper.c:121
#4  0x0000ffff97c4c2a8 in g_inotify_file_monitor_cancel (monitor=<optimized out>) at ../../../gio/inotify/ginotifyfilemonitor.c:75
#5  0x0000ffff97b6b474 in g_file_monitor_cancel (monitor=0xaaaac48fd410 [GInotifyFileMonitor]) at ../../../gio/gfilemonitor.c:241
#6  g_file_monitor_cancel (monitor=0xaaaac48fd410 [GInotifyFileMonitor]) at ../../../gio/gfilemonitor.c:235
#7  0x0000ffff97b6b51c in g_file_monitor_dispose (object=0xaaaac48fd410 [GInotifyFileMonitor]) at ../../../gio/gfilemonitor.c:123
#8  0x0000ffff97c409d4 in g_local_file_monitor_dispose (object=0xaaaac48fd410 [GInotifyFileMonitor]) at ../../../gio/glocalfilemonitor.c:814
#9  0x0000ffff97e784f8 in g_object_unref (_object=<optimized out>) at ../../../gobject/gobject.c:3461
#10 g_object_unref (_object=0xaaaac48fd410) at ../../../gobject/gobject.c:3391
#11 0x0000ffff97c40358 in g_file_monitor_source_handle_event (fms=0xaaaac48faa50, event_type=event_type at entry=G_FILE_MONITOR_EVENT_CHANGES_DONE_HINT, child=0xffff84001470 "buf_a.gegl", rename_to=rename_to at entry=0x0, other=other at entry=0x0, event_time=<optimized out>) at ../../../gio/glocalfilemonitor.c:455
#12 0x0000ffff97c4bbe4 in ih_event_callback (event=0xffff84001430, sub=0xaaaac48fad60, file_event=<optimized out>) at ../../../gio/inotify/inotify-helper.c:206
#13 0x0000ffff97c4b13c in ip_event_dispatch (dir_list=dir_list at entry=0xaaaac48f7d80 = {...}, file_list=0x0, event=event at entry=0xffff84001430) at ../../../gio/inotify/inotify-path.c:492
#14 0x0000ffff97c4b2f4 in ip_event_dispatch (event=0xffff84001430, file_list=<optimized out>, dir_list=0xaaaac48f7d80 = {...}) at ../../../gio/inotify/inotify-path.c:547
#15 ip_event_callback (event=0xffff84001430) at ../../../gio/inotify/inotify-path.c:547
#16 ip_event_callback (event=0xffff84001430) at ../../../gio/inotify/inotify-path.c:529
#17 0x0000ffff97c4a4f8 in ik_source_dispatch (source=0xaaaac48fa5f0, func=0xffff97c4b210 <ip_event_callback>, user_data=<optimized out>) at ../../../gio/inotify/inotify-kernel.c:327
#18 0x0000ffff97f2235c in g_main_dispatch (context=0xaaaac48fa6b0) at ../../../glib/gmain.c:3309
#19 g_main_context_dispatch (context=context at entry=0xaaaac48fa6b0) at ../../../glib/gmain.c:3974
#20 0x0000ffff97f22708 in g_main_context_iterate (context=context at entry=0xaaaac48fa6b0, block=block at entry=1, dispatch=dispatch at entry=1, self=<optimized out>) at ../../../glib/gmain.c:4047
#21 0x0000ffff97f227ac in g_main_context_iteration (context=0xaaaac48fa6b0, may_block=may_block at entry=1) at ../../../glib/gmain.c:4108
#22 0x0000ffff97f227fc in glib_worker_main (data=<optimized out>) at ../../../glib/gmain.c:5996
#23 0x0000ffff97f4bcec in g_thread_proxy (data=0xaaaac48fbd20) at ../../../glib/gthread.c:807
#24 0x0000ffff97a0b998 in start_thread (arg=0xfffffc63b24f) at pthread_create.c:479
#25 0x0000ffff97dc16ac in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:78

Thread 5 (Thread 0xffff95b67ce0 (LWP 1855)):
#0  syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1  0x0000ffff97f701dc in g_cond_wait (cond=cond at entry=0xffff981bf9d0 <queue_cond>, mutex=mutex at entry=0xffff981bf998 <mutex>) at ../../../glib/gthread-posix.c:1540
#2  0x0000ffff98149d70 in gegl_tile_backend_file_writer_thread (ignored=<optimized out>) at ../gegl/buffer/gegl-tile-backend-file-async.c:257
#3  0x0000ffff97f4bcec in g_thread_proxy (data=0xaaaac4865120) at ../../../glib/gthread.c:807
#4  0x0000ffff97a0b998 in start_thread (arg=0xfffffc63b5ff) at pthread_create.c:479
#5  0x0000ffff97dc16ac in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:78

Thread 4 (Thread 0xffff96368ce0 (LWP 1854)):
#0  syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1  0x0000ffff97f701dc in g_cond_wait (cond=cond at entry=0xffff981bd228 <gegl_parallel_distribute_threads+128>, mutex=mutex at entry=0xffff981bd220 <gegl_parallel_distribute_threads+120>) at ../../../glib/gthread-posix.c:1540
#2  0x0000ffff9811d4e0 in gegl_parallel_distribute_thread_func (thread=0xffff981bd218 <gegl_parallel_distribute_threads+112>) at ../gegl/gegl-parallel.c:508
#3  0x0000ffff97f4bcec in g_thread_proxy (data=0xaaaac4864b60) at ../../../glib/gthread.c:807
#4  0x0000ffff97a0b998 in start_thread (arg=0xfffffc63bccf) at pthread_create.c:479
#5  0x0000ffff97dc16ac in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:78

Thread 3 (Thread 0xffff96b69ce0 (LWP 1853)):
#0  syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1  0x0000ffff97f701dc in g_cond_wait (cond=cond at entry=0xffff981bd1f0 <gegl_parallel_distribute_threads+72>, mutex=mutex at entry=0xffff981bd1e8 <gegl_parallel_distribute_threads+64>) at ../../../glib/gthread-posix.c:1540
#2  0x0000ffff9811d4e0 in gegl_parallel_distribute_thread_func (thread=0xffff981bd1e0 <gegl_parallel_distribute_threads+56>) at ../gegl/gegl-parallel.c:508
#3  0x0000ffff97f4bcec in g_thread_proxy (data=0xaaaac4864b00) at ../../../glib/gthread.c:807
#4  0x0000ffff97a0b998 in start_thread (arg=0xfffffc63bccf) at pthread_create.c:479
#5  0x0000ffff97dc16ac in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:78

Thread 2 (Thread 0xffff9736ace0 (LWP 1852)):
#0  syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1  0x0000ffff97f701dc in g_cond_wait (cond=cond at entry=0xffff981bd1b8 <gegl_parallel_distribute_threads+16>, mutex=mutex at entry=0xffff981bd1b0 <gegl_parallel_distribute_threads+8>) at ../../../glib/gthread-posix.c:1540
#2  0x0000ffff9811d4e0 in gegl_parallel_distribute_thread_func (thread=0xffff981bd1a8 <gegl_parallel_distribute_threads>) at ../gegl/gegl-parallel.c:508
#3  0x0000ffff97f4bcec in g_thread_proxy (data=0xaaaac4864aa0) at ../../../glib/gthread.c:807
#4  0x0000ffff97a0b998 in start_thread (arg=0xfffffc63bccf) at pthread_create.c:479
#5  0x0000ffff97dc16ac in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:78

Thread 1 (Thread 0xffff976efbe0 (LWP 1851)):
#0  syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1  0x0000ffff97f6f588 in g_mutex_lock_slowpath (mutex=mutex at entry=0xffff97cee280 <g.inotify_lock_lock>) at ../../../glib/gthread-posix.c:1457
#2  0x0000ffff97f700b8 in g_mutex_lock (mutex=mutex at entry=0xffff97cee280 <g.inotify_lock_lock>) at ../../../glib/gthread-posix.c:1482
#3  0x0000ffff97c4bf14 in _ih_startup () at ../../../gio/inotify/inotify-helper.c:74
#4  0x0000ffff97c4c308 in g_inotify_file_monitor_start (local_monitor=<optimized out>, dirname=0xaaaac48f62c0 "/tmp/test-backend-file-PI3NH0", basename=0xaaaac48fe550 "buf_a.gegl", filename=0x0, source=0xaaaac48fe700) at ../../../gio/inotify/ginotifyfilemonitor.c:61
#5  0x0000ffff97c40e5c in g_local_file_monitor_new_for_path (pathname=0xaaaac48b3bb0 "/tmp/test-backend-file-PI3NH0/buf_a.gegl", is_directory=0, flags=G_FILE_MONITOR_NONE, error=<optimized out>) at ../../../gio/glocalfilemonitor.c:886
#6  0x0000ffff97b5e6dc in g_file_monitor_file (file=0xaaaac48f80c0, flags=flags at entry=G_FILE_MONITOR_NONE, cancellable=cancellable at entry=0x0, error=error at entry=0x0) at ../../../gio/gfile.c:5447
#7  0x0000ffff9814abec in gegl_tile_backend_file_constructed (object=0xaaaac48f00a0 [GeglTileBackendFile]) at ../gegl/buffer/gegl-tile-backend-file-async.c:1170
#8  0x0000ffff97e78d88 in g_object_new_internal (class=0xaaaac48ee750, class at entry=0xaaaac48b5140, params=params at entry=0xfffffc63b928, n_params=n_params at entry=4) at ../../../gobject/gobject.c:1977
#9  0x0000ffff97e7ab8c in g_object_new_valist (object_type=0xaaaac48ee5a0 [GeglTileBackendFile/GeglTileBackend/GeglTileSource], first_property_name=first_property_name at entry=0xffff98177638 "tile-width", var_args=...) at ../../../gobject/gobject.c:2262
#10 0x0000ffff97e7ae14 in g_object_new (object_type=<optimized out>, first_property_name=first_property_name at entry=0xffff98177638 "tile-width") at ../../../gobject/gobject.c:1780
#11 0x0000ffff9813c9e0 in gegl_buffer_constructor (type=<optimized out>, n_params=<optimized out>, params=<optimized out>) at ../gegl/buffer/gegl-buffer.c:549
#12 0x0000ffff97e78b40 in g_object_new_with_custom_constructor (n_params=2, params=0xfffffc63be18, class=0xaaaac48b4400) at ../../../gobject/gobject.c:1855
#13 g_object_new_internal (class=0xaaaac48b4400, class at entry=0xaaaac48724d0, params=params at entry=0xfffffc63be18, n_params=n_params at entry=2) at ../../../gobject/gobject.c:1935
#14 0x0000ffff97e7ab8c in g_object_new_valist (object_type=0xaaaac48b4160 [GeglBuffer/GeglTileHandler/GeglTileSource], first_property_name=<optimized out>, var_args=...) at ../../../gobject/gobject.c:2262
#15 0x0000ffff97e7ae14 in g_object_new (object_type=<optimized out>, first_property_name=<optimized out>) at ../../../gobject/gobject.c:1780
#16 0x0000aaaac3179808 in test_buffer_open () at ../tests/simple/test-backend-file.c:306
#17 main (argc=<optimized out>, argv=<optimized out>) at ../tests/simple/test-backend-file.c:443