ltfs icon indicating copy to clipboard operation
ltfs copied to clipboard

Published 20 hours ago • verified publisher icon LinearTapeFileSystem

Deadlock when unmounting LTFS after writing multiple small files

Open greengreengreengit opened this issue 2 years ago • 6 comments

Deadlock when unmounting LTFS after writing multiple small files

LTFS 2.4.5.0 (or older versions) macFUSE 4.4.1 (or older versions) macOS 12.5.1

On Apple Silicon Macs ltfs runs in Rosetta, this works well. However we have discovered a deadlock situation when unmounting a tape. It's intermittent, but happens very often when the files written are small in size.

mount tape write some small files to tape, here the SRC folder has 5 x 7MB files. unmount

ltfs /Volumes/LTFS1 -o devname=0
cp -r /Volumes/SOURCE/SRC /Volumes/LTFS1/TEST
umount /Volumes/LTFS1

About 30% of the time this will lockup and then after 20 minutes the process will timeout. The same script will run repeatedly using an Intel Mac.

Writing a larger file (here a 1GB file) after the small ones prevents the deadlock

ltfs /Volumes/LTFS1 -o devname=0
cp -r /Volumes/SOURCE/SRC /Volumes/LTFS1/TEST
cp /Volumes/SOURCE/1G.bin /Volumes/LTFS$1/TEST/
umount /Volumes/LTFS1

Here is a sample of the deadlocked processes...

2576 Thread_17870 DispatchQueue_1: com.apple.main-thread (serial) + 2576 start (in ltfs) + 52 [0x100000eb4] + 2576 main (in ltfs) + 5713 [0x100004011] + 2576 single_drive_main (in ltfs) + 5707 [0x1000059fb] + 2576 fuse_main_real (in libfuse.2.dylib) + 12 [0x1088b259c] + 2576 ??? (in libfuse.2.dylib) load address 0x10889e000 + 0x145f1 [0x1088b25f1] + 2576 fuse_loop (in libfuse.2.dylib) + 48 [0x1088a3610] + 2576 fuse_session_loop (in libfuse.2.dylib) + 153 [0x1088ab599] + 2576 fuse_session_process_buf (in libfuse.2.dylib) + 25 [0x1088b09b9] + 2576 ??? (in libfuse.2.dylib) load address 0x10889e000 + 0xfc75 [0x1088adc75] + 2576 ??? (in libfuse.2.dylib) load address 0x10889e000 + 0x10989 [0x1088ae989] + 2576 ??? (in libfuse.2.dylib) load address 0x10889e000 + 0x882a [0x1088a682a] + 2576 ??? (in libfuse.2.dylib) load address 0x10889e000 + 0xc1ef [0x1088aa1ef] + 2576 fuse_fs_release (in libfuse.2.dylib) + 123 [0x1088a169b] + 2576 ??? (in libfuse.2.dylib) load address 0x10889e000 + 0x36c3 [0x1088a16c3] + 2576 ??? (in libfuse.2.dylib) load address 0x10889e000 + 0x1a1ce [0x1088b81ce] + 2576 fuse_fs_release (in libfuse.2.dylib) + 123 [0x1088a169b] + 2576 ??? (in libfuse.2.dylib) load address 0x10889e000 + 0x36c3 [0x1088a16c3] + 2576 ltfs_fuse_release (in ltfs) + 462 [0x10000850e] + 2576 ltfs_fsops_close (in libltfs.2.4.4.dylib) + 517 [0x10873c915] + 2576 iosched_close (in libltfs.2.4.4.dylib) + 615 [0x108728657] + 2576 unified_close (in libiosched-unified.2.4.4.dylib) + 320 [0x1086e6e40] + 2576 _unified_flush_unlocked (in libiosched-unified.2.4.4.dylib) + 646 [0x1086e71d6] + 2576 ltfs_fsraw_write (in libltfs.2.4.4.dylib) + 531 [0x1087479a3] + 2576 _ltfs_fsraw_write_data_unlocked (in libltfs.2.4.4.dylib) + 859 [0x1087462db] + 2576 writetoread_mrsw (in libltfs.2.4.4.dylib) + 33 [0x1087466b1] + 2576 _pthread_rwlock_lock_slow (in libsystem_pthread.dylib) + 565 [0x7ff81464e514] + 2576 _pthread_rwlock_lock_wait (in libsystem_pthread.dylib) + 56 [0x7ff81464fefd] + 2576 __psynch_rw_rdlock (in libsystem_kernel.dylib) + 10 [0x7ff814618a12] + 2576 ??? (in ) [0x7ff8a4ae6940] 2576 Thread_17874 2576 thread_start (in libsystem_pthread.dylib) + 15 [0x7ff81464cf6b] 2576 _pthread_start (in libsystem_pthread.dylib) + 125 [0x7ff8146514e1] 2576 _unified_writer_thread (in libiosched-unified.2.4.4.dylib) + 557 [0x1086e669d] 2576 _unified_process_queue (in libiosched-unified.2.4.4.dylib) + 144 [0x1086eb2c0] 2576 _unified_process_data_queue (in libiosched-unified.2.4.4.dylib) + 1542 [0x1086ebc96] 2576 ltfs_fsraw_write (in libltfs.2.4.4.dylib) + 531 [0x1087479a3] 2576 _ltfs_fsraw_write_data_unlocked (in libltfs.2.4.4.dylib) + 413 [0x10874611d] 2576 tape_device_lock (in libltfs.2.4.4.dylib) + 127 [0x10875797f] 2576 ltfs_mutex_lock (in libltfs.2.4.4.dylib) + 21 [0x1087569b5] 2576 _pthread_mutex_firstfit_lock_slow (in libsystem_pthread.dylib) + 205 [0x7ff81464ccbb] 2576 _pthread_mutex_firstfit_lock_wait (in libsystem_pthread.dylib) + 76 [0x7ff81464ee7e] 2576 __psynch_mutexwait (in libsystem_kernel.dylib) + 10 [0x7ff814616bd2] 2576 ??? (in ) [0x7ff8a4ae6940]

greengreengreengit avatar Sep 13 '22 15:09 greengreengreengit

I tried adding each of the the following commands after the write and before the unmount.

  • flush
  • sleep 5
  • LTFS sync

None of these made any difference. The only solution seems to be writing a large file before un-mounting.

greengreengreengit avatar Sep 14 '22 10:09 greengreengreengit

I'm not sure a deadlock really happens. Because we don't have a deadlock in this a few years at all.

You need to attach the debugger to the process and check the lock chain, which lock blocks other locks.

I can't say anything from the logs in the comments.

piste-jp avatar Sep 14 '22 12:09 piste-jp

The two threads' stack traces indicate they're waiting for different resources. The top-most thread is blocked while trying to downgrade the multi-reader, single writer vol->lock to reader mode. The bottom-most thread is blocked while trying to obtain a lock on the device backend's dev->backend_mutex. @greengreengreengit, you mentioned that you've pasted a sample of the stack traces; we may need the full stack traces to check which locks the other threads are trying to obtain.

Now, there's something to note here. We have two implementations of multi-reader, single writer locks. The original one uses a logic based on try-locks, whereas the second one (which IIRC came as a NetBSD-related PR) uses a cleaner implementation based on pthread_rwlock_t. @piste-jp-ibm, I am unaware of how the macOS builds are currently being distributed (or if users are expected to build their own package from the source code). Would you know which implementation is used by default on macOS? configure.ac only enables the pthread_rwlock_t implementation when building for NetBSD, although --enable-new-locking is provided for those wanting to use it.

lucasvr avatar Sep 17 '22 05:09 lucasvr

The issue only happens on Apple Silicon where there is a third thread. I cut it from the sample, because it did not seem to be involved. However it might be the clue, as when running on Intel we never see this lock issue AND this third thread does not exist. Note that the current IBM releases builds are for x86_64, so LTFS runs using Rosetta. Rosetta hasn't seemed to be an issue up until now. (Note that when mounting the tape we set sync_type=unmount to disable syncing, so that is why there is no 4th thread for a timer. Also note that issue occurs both with and without sync enabled)

Here is the full stack trace...

Call graph:
    2574 Thread_272800   DispatchQueue_1: com.apple.main-thread  (serial)
    + 2574 start  (in ltfs) + 52  [0x100000eb4]
    +   2574 main  (in ltfs) + 5713  [0x100004011]
    +     2574 single_drive_main  (in ltfs) + 5707  [0x1000059fb]
    +       2574 fuse_main_real  (in libfuse.2.dylib) + 12  [0x1088b356c]
    +         2574 ???  (in libfuse.2.dylib)  load address 0x10889f000 + 0x145c1  [0x1088b35c1]
    +           2574 fuse_loop  (in libfuse.2.dylib) + 48  [0x1088a45e0]
    +             2574 fuse_session_loop  (in libfuse.2.dylib) + 153  [0x1088ac599]
    +               2574 fuse_session_process_buf  (in libfuse.2.dylib) + 25  [0x1088b1979]
    +                 2574 ???  (in libfuse.2.dylib)  load address 0x10889f000 + 0xfc7c  [0x1088aec7c]
    +                   2574 ???  (in libfuse.2.dylib)  load address 0x10889f000 + 0x10979  [0x1088af979]
    +                     2574 ???  (in libfuse.2.dylib)  load address 0x10889f000 + 0x880a  [0x1088a780a]
    +                       2574 ???  (in libfuse.2.dylib)  load address 0x10889f000 + 0xc1ef  [0x1088ab1ef]
    +                         2574 fuse_fs_release  (in libfuse.2.dylib) + 123  [0x1088a267b]
    +                           2574 ???  (in libfuse.2.dylib)  load address 0x10889f000 + 0x36a3  [0x1088a26a3]
    +                             2574 ???  (in libfuse.2.dylib)  load address 0x10889f000 + 0x1a1ae  [0x1088b91ae]
    +                               2574 fuse_fs_release  (in libfuse.2.dylib) + 123  [0x1088a267b]
    +                                 2574 ???  (in libfuse.2.dylib)  load address 0x10889f000 + 0x36a3  [0x1088a26a3]
    +                                   2574 ltfs_fuse_release  (in ltfs) + 462  [0x10000850e]
    +                                     2574 ltfs_fsops_close  (in libltfs.2.4.5.dylib) + 517  [0x10873c595]
    +                                       2574 iosched_close  (in libltfs.2.4.5.dylib) + 615  [0x108728207]
    +                                         2574 unified_close  (in libiosched-unified.2.4.5.dylib) + 320  [0x1086e6e40]
    +                                           2574 _unified_flush_unlocked  (in libiosched-unified.2.4.5.dylib) + 646  [0x1086e71d6]
    +                                             2574 ltfs_fsraw_write  (in libltfs.2.4.5.dylib) + 531  [0x108747623]
    +                                               2574 _ltfs_fsraw_write_data_unlocked  (in libltfs.2.4.5.dylib) + 859  [0x108745f5b]
    +                                                 2574 writetoread_mrsw  (in libltfs.2.4.5.dylib) + 33  [0x108746331]
    +                                                   2574 _pthread_rwlock_lock_slow  (in libsystem_pthread.dylib) + 565  [0x7ff80c5a6514]
    +                                                     2574 _pthread_rwlock_lock_wait  (in libsystem_pthread.dylib) + 56  [0x7ff80c5a7efd]
    +                                                       2574 __psynch_rw_rdlock  (in libsystem_kernel.dylib) + 10  [0x7ff80c570a12]
    +                                                         2574 ???  (in <unknown binary>)  [0x7ff89ca3e940]
    2574 Thread_272801: com.apple.rosetta.exceptionserver
    + 2574 ???  (in runtime)  load address 0x7ff7ffd76000 + 0x13e58  [0x7ff7ffd89e58]
    +   2574 ???  (in runtime)  load address 0x7ff7ffd76000 + 0x123e0  [0x7ff7ffd883e0]
    +     2574 ???  (in runtime)  load address 0x7ff7ffd76000 + 0x4944  [0x7ff7ffd7a944]
    2574 Thread_272806
      2574 thread_start  (in libsystem_pthread.dylib) + 15  [0x7ff80c5a4f6b]
        2574 _pthread_start  (in libsystem_pthread.dylib) + 125  [0x7ff80c5a94e1]
          2574 _unified_writer_thread  (in libiosched-unified.2.4.5.dylib) + 557  [0x1086e669d]
            2574 _unified_process_queue  (in libiosched-unified.2.4.5.dylib) + 144  [0x1086eb2c0]
              2574 _unified_process_data_queue  (in libiosched-unified.2.4.5.dylib) + 1542  [0x1086ebc96]
                2574 ltfs_fsraw_write  (in libltfs.2.4.5.dylib) + 531  [0x108747623]
                  2574 _ltfs_fsraw_write_data_unlocked  (in libltfs.2.4.5.dylib) + 413  [0x108745d9d]
                    2574 tape_device_lock  (in libltfs.2.4.5.dylib) + 127  [0x1087575ff]
                      2574 ltfs_mutex_lock  (in libltfs.2.4.5.dylib) + 21  [0x108756635]
                        2574 _pthread_mutex_firstfit_lock_slow  (in libsystem_pthread.dylib) + 205  [0x7ff80c5a4cbb]
                          2574 _pthread_mutex_firstfit_lock_wait  (in libsystem_pthread.dylib) + 76  [0x7ff80c5a6e7e]
                            2574 __psynch_mutexwait  (in libsystem_kernel.dylib) + 10  [0x7ff80c56ebd2]
                              2574 ???  (in <unknown binary>)  [0x7ff89ca3e940]

greengreengreengit avatar Sep 19 '22 10:09 greengreengreengit

@piste-jp-ibm, I am unaware of how the macOS builds are currently being distributed (or if users are expected to build their own package from the source code). Would you know which implementation is used by default on macOS? configure.ac only enables the pthread_rwlock_t implementation when building for NetBSD, although --enable-new-locking is provided for those wanting to use it.

It is enabled by default only on master branch. So it is disabled by default on 2.4.5.0. It is same as IBM binary.

piste-jp avatar Sep 20 '22 01:09 piste-jp

Here is the full stack trace...

The stack trace is little bit funny. Because we didn't use new-locking option on 2.4.X. And pthread_rwlock is used only when new-locking is enabled...

From the stack trace,

  • Thread_272800 is waiting the downgrade of vol->lock
  • Thread_272801 waiting the lock of dev->backend_mutex

I can't find the root cause from the stack trace attached. We need to inspect the mutex itself and all threads.

piste-jp avatar Sep 20 '22 01:09 piste-jp

So again copying a sequence of small files, say 10 x 7MB files and un-mounting ltfs locks up very frequently. Copy the same sequence of files, then copy a 1GB file, then un-mount it never locks up.

I am using the IBM release build 2.4.5 on macOS. Here is the lldb backtrace for all threads.

(lldb) thread backtrace all
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007ff81de38a12 libsystem_kernel.dylib`__psynch_rw_rdlock + 10
    frame #1: 0x00007ff81de6fefd libsystem_pthread.dylib`_pthread_rwlock_lock_wait + 56
    frame #2: 0x00007ff81de6e514 libsystem_pthread.dylib`_pthread_rwlock_lock_slow + 565
    frame #3: 0x0000000108746331 libltfs.2.4.5.dylib`writetoread_mrsw + 33
    frame #4: 0x0000000108745f5b libltfs.2.4.5.dylib`_ltfs_fsraw_write_data_unlocked + 859
    frame #5: 0x0000000108747623 libltfs.2.4.5.dylib`ltfs_fsraw_write + 531
    frame #6: 0x00000001086e71d6 libiosched-unified.2.4.5.dylib`_unified_flush_unlocked + 646
    frame #7: 0x00000001086e6e40 libiosched-unified.2.4.5.dylib`unified_close + 320
    frame #8: 0x0000000108728207 libltfs.2.4.5.dylib`iosched_close + 615
    frame #9: 0x000000010873c595 libltfs.2.4.5.dylib`ltfs_fsops_close + 517
    frame #10: 0x000000010000850e ltfs`ltfs_fuse_release + 462
    frame #11: 0x00000001088a26c3 libosxfuse_i64.2.dylib`___lldb_unnamed_symbol1$$libosxfuse_i64.2.dylib + 19
    frame #12: 0x00000001088a269b libosxfuse_i64.2.dylib`fuse_fs_release + 123
    frame #13: 0x00000001088b91ce libosxfuse_i64.2.dylib`___lldb_unnamed_symbol509$$libosxfuse_i64.2.dylib + 46
    frame #14: 0x00000001088a26c3 libosxfuse_i64.2.dylib`___lldb_unnamed_symbol1$$libosxfuse_i64.2.dylib + 19
    frame #15: 0x00000001088a269b libosxfuse_i64.2.dylib`fuse_fs_release + 123
    frame #16: 0x00000001088ab1ef libosxfuse_i64.2.dylib`___lldb_unnamed_symbol142$$libosxfuse_i64.2.dylib + 79
    frame #17: 0x00000001088a782a libosxfuse_i64.2.dylib`___lldb_unnamed_symbol64$$libosxfuse_i64.2.dylib + 138
    frame #18: 0x00000001088af989 libosxfuse_i64.2.dylib`___lldb_unnamed_symbol235$$libosxfuse_i64.2.dylib + 121
    frame #19: 0x00000001088aec75 libosxfuse_i64.2.dylib`___lldb_unnamed_symbol205$$libosxfuse_i64.2.dylib + 1077
    frame #20: 0x00000001088b19b9 libosxfuse_i64.2.dylib`fuse_session_process_buf + 25
    frame #21: 0x00000001088ac599 libosxfuse_i64.2.dylib`fuse_session_loop + 153
    frame #22: 0x00000001088a4610 libosxfuse_i64.2.dylib`fuse_loop + 48
    frame #23: 0x00000001088b35f1 libosxfuse_i64.2.dylib`___lldb_unnamed_symbol316$$libosxfuse_i64.2.dylib + 81
    frame #24: 0x00000001088b359c libosxfuse_i64.2.dylib`fuse_main_real + 12
    frame #25: 0x00000001000059fb ltfs`single_drive_main + 5707
    frame #26: 0x0000000100004011 ltfs`main + 5713
    frame #27: 0x0000000100000eb4 ltfs`start + 52
  thread #2
    frame #0: 0x00007ff81de36bd2 libsystem_kernel.dylib`__psynch_mutexwait + 10
    frame #1: 0x00007ff81de6ee7e libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 76
    frame #2: 0x00007ff81de6ccbb libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 205
    frame #3: 0x0000000108756635 libltfs.2.4.5.dylib`ltfs_mutex_lock + 21
    frame #4: 0x00000001087575ff libltfs.2.4.5.dylib`tape_device_lock + 127
    frame #5: 0x0000000108745d9d libltfs.2.4.5.dylib`_ltfs_fsraw_write_data_unlocked + 413
    frame #6: 0x0000000108747623 libltfs.2.4.5.dylib`ltfs_fsraw_write + 531
    frame #7: 0x00000001086ebc96 libiosched-unified.2.4.5.dylib`_unified_process_data_queue + 1542
    frame #8: 0x00000001086eb2c0 libiosched-unified.2.4.5.dylib`_unified_process_queue + 144
    frame #9: 0x00000001086e669d libiosched-unified.2.4.5.dylib`_unified_writer_thread + 557
    frame #10: 0x00007ff81de714e1 libsystem_pthread.dylib`_pthread_start + 125
    frame #11: 0x00007ff81de6cf6b libsystem_pthread.dylib`thread_start + 15
(lldb)

greengreengreengit avatar Sep 23 '22 20:09 greengreengreengit

Technically it looks this is not a deadlock. It looks Thread1 is just stopped and Thread2 is just waiting Thread1.

We need to understand why Thread1 is waiting. To be more specific, we need to see the internal structure of mutex at frame4 and frame3 of Thread1.

It can be done if we can have the actual source code and full debug information. But I don't know this effort have worth to do.

Do you have an option to build LTFS (in this repository) by yourself on M1/M2 machine? Why do you stick with IBM binary?

I don't think big vendor says "Yes, we can support Rosetta translated binary." on a BSD licensed S/W.

piste-jp avatar Sep 24 '22 00:09 piste-jp

I can build on Intel, but obviously that is x86_64. When I build on Apple Silicon the code builds using arm64. However there are link errors as all the resource bundle files in messages like libtape_common_dat.a have been built for x86_64. How do I set the architecture used by genrb ?

greengreengreengit avatar Sep 27 '22 15:09 greengreengreengit

How do I set the architecture used by genrb ?

Please confirm the binary of genrb. In my best guess, it is a x86_64 binary and runs on Rosetta.

You need to install amd64 version ICU from the Homebrew, if so.

piste-jp avatar Sep 28 '22 00:09 piste-jp

Thanks for the info, I had to remove the installed Intel ICU, now it builds an arm64 version. This seems to be a solution and so far unmounting works. However I need to package the build so that we can test on non development M1 Macs. The issue is that the build script links in various brew libraries that aren't installed by default.

For older IBM LTFS there was a build_package_osx.sh, is there an updated version of this script that has been used for the 2.4.5.0 Mac release ?

greengreengreengit avatar Oct 06 '22 17:10 greengreengreengit

For older IBM LTFS there was a build_package_osx.sh, is there an updated version of this script that has been used for the 2.4.5.0 Mac release ?

I'm very sorry to say, I cannot answer this question.

But you can use the repository below with a few modification I believe.

https://github.com/piste2750/macpkg-ltfs

piste-jp avatar Oct 17 '22 01:10 piste-jp