Quadratic(?) slowdown on file moves across filesystems

[slyfox]

Tried to move firefox build tree from one btrfs subvolume to another on NVMe device. It contained ~2M files. Normally it should take under a minute to relink a few gigabytes. But mc did not not succeed in 1 hour.

Looks like there is a quadratic behavior in file moves related to single list traversal.

Here is the reproducer:

1. create 1M files in a firectory structure (we will create 1000 dirs 1000 files each)
2. put them all in one directory 'd'
3. move this 'd' from one tmpfs to another

Expected behavior: operation should take seconds (rougly the same time it takes to create the directory tree).

Actual behaviour: it takes tens of minutes to move the dir.

Script to build a directory:

#!/usr/bin/env bash

# fail on first problem
set -e

echo "prepating two new tmpfs filesystems: /tmp/tmpfs-src and /tmp/tmpfs-dst"

mkdir /tmp/tmpfs-src
mkdir /tmp/tmpfs-dst

sudo mount -t tmpfs tmpfs /tmp/tmpfs-src
sudo mount -t tmpfs tmpfs /tmp/tmpfs-dst

# allow current user to fiddle with it
sudo chown ${USER} /tmp/tmpfs-src /tmp/tmpfs-dst

echo "creating 1M files"
# create 1 million empty files
mkdir /tmp/tmpfs-src/d
for d in {1..1000}; do
    mkdir /tmp/tmpfs-src/d/$d
    touch /tmp/tmpfs-src/d/$d/{1..1000}
done

echo "don't forget cleanup: 'sudo umount /tmp/tmpfs-src; sudo umount /tmp/tmpfs-dst'"
echo "Now you can run 'mc /tmp/tmpfs-src /tmp/tmpfs-dst' and try to move 'd' directory with F6."

Run as:

1. Run '$ prepare_environment.bash'
2. Run 'mc /tmp/tmpfs-src /tmp/tmpfs-dst'
3. Start moving with 'F6' on 'd' dir.

[slyfox]

'perf record / perf report' renders the following:

    96.41%  mc       libglib-2.0.so.0.6800.3  [.] g_slist_last
     0.83%  mc       libslang.so.2.3.2        [.] _pSLstring_hash.localalias
     0.16%  mc       libslang.so.2.3.2        [.] SLtt_smart_puts
     0.15%  mc       libc-2.33.so             [.] __memcmp_avx2_movbe
     0.14%  mc       mc                       [.] str_utf8_make_make_term_form
     0.11%  mc       libglib-2.0.so.0.6800.3  [.] g_unichar_type
     0.07%  mc       libc-2.33.so             [.] __strlen_avx2
     0.07%  mc       libc-2.33.so             [.] __dcigettext
     0.07%  mc       libglib-2.0.so.0.6800.3  [.] g_unichar_isprint

GDB's backtrace for possible location:

(gdb) bt
#0  0x00007fecf24dfe77 in g_slist_last ()
   from /nix/store/94iv84rv2d1cl0fk1l1mkmmbnxg7fyzz-glib-2.68.3/lib/libglib-2.0.so.0
#1  0x00007fecf24dfeaf in g_slist_append ()
   from /nix/store/94iv84rv2d1cl0fk1l1mkmmbnxg7fyzz-glib-2.68.3/lib/libglib-2.0.so.0
#2  0x000000000046d2dd in copy_dir_dir (tctx=0xc27ff0, ctx=0xc27f50,
    s=0xc24f00 "/tmp/tmpfs-src/d/591", d=<optimized out>, toplevel=<optimized out>,
    move_over=<optimized out>, do_delete=1, parent_dirs=0xa6c9ab0) at file.c:2989
#3  0x000000000046d162 in copy_dir_dir (tctx=tctx@entry=0xc27ff0, ctx=ctx@entry=0xc27f50,
    s=s@entry=0xc2d490 "/tmp/tmpfs-src/d", d=<optimized out>, d@entry=0xc0b490 "/tmp/tmpfs-dst/d",
    toplevel=toplevel@entry=0, move_over=move_over@entry=0, do_delete=1, parent_dirs=0xb54cc0)
    at file.c:2967
#4  0x000000000046d7fa in do_move_dir_dir (panel=0x7ffc76c9e490, tctx=0xc27ff0, ctx=0xc27f50,
    s=0xc2d490 "/tmp/tmpfs-src/d", d=0xc0b490 "/tmp/tmpfs-dst/d") at file.c:1674
#5  0x000000000046ed11 in operate_single_file (dialog_type=<optimized out>, dest=<optimized out>,
    src_stat=0x7ffc76c9e740, src=<optimized out>, ctx=0xc27f50, tctx=0xc27ff0, operation=OP_MOVE,
    panel=0xc19000) at file.c:2050
#6  panel_operate (source_panel=source_panel@entry=0xc19000, operation=operation@entry=OP_MOVE,
    force_single=force_single@entry=0) at file.c:3334
#7  0x0000000000465f18 in rename_cmd (panel=0xc19000) at cmd.c:795
#8  0x0000000000418bf0 in midnight_execute_cmd (sender=0xc17c00, command=23) at filemanager.c:1355
#9  0x000000000049db59 in buttonbar_callback (w=0xc17c00, sender=<optimized out>,
    msg=<optimized out>, parm=1006, data=<optimized out>) at buttonbar.c:171
#10 0x00000000004a07f0 in send_message (data=0x0, parm=1006, msg=MSG_HOTKEY, sender=0x0,
    w=<optimized out>) at ../../lib/widget/widget-common.h:254
#11 group_handle_hotkey (key=1006, g=0xc04580) at group.c:567
#12 group_default_callback (w=0xc04580, sender=<optimized out>, msg=<optimized out>,
    parm=<optimized out>, data=<optimized out>) at group.c:643
#13 0x00000000004a0680 in send_message (data=0x0, parm=1006, msg=MSG_HOTKEY, sender=0x0, w=0xc04580)
    at ../../lib/widget/widget-common.h:254
#14 group_handle_key (key=1006, g=0xc04580) at group.c:504
#15 group_default_callback (w=0xc04580, sender=<optimized out>, msg=<optimized out>, parm=1006,
    data=<optimized out>) at group.c:640
#16 0x000000000049f06d in dlg_key_event (d_key=1006, h=0xc04580) at dialog.c:251
#17 dlg_process_event (h=0xc04580, key=1006, event=<optimized out>) at dialog.c:566
#18 0x000000000049f346 in frontend_dlg_run (h=0xc04580) at dialog.c:320
#19 dlg_run (h=0xc04580) at dialog.c:600
#20 0x000000000041a07c in do_nc () at filemanager.c:1838
#21 0x000000000040b0a5 in main (argc=<optimized out>, argv=<optimized out>) at main.c:455

​https://people.gnome.org/~ryanl/glib-docs/glib-Singly-Linked-Lists.html warns about 'g_slist_append':

Note that g_slist_append() has to traverse the entire list to find the end,
which is inefficient when adding multiple elements. A common idiom to avoid
the inefficiency is to prepend the elements and reverse the list when all
elements have been added.

[andrew_b]

Replying to slyfox:

    96.41%  mc       libglib-2.0.so.0.6800.3  [.] g_slist_last

[...]

#2  0x000000000046d2dd in copy_dir_dir (tctx=0xc27ff0, ctx=0xc27f50,
    s=0xc24f00 "/tmp/tmpfs-src/d/591", d=<optimized out>, toplevel=<optimized out>,
    move_over=<optimized out>, do_delete=1, parent_dirs=0xa6c9ab0) at file.c:2989

I can propose to replace g_list_append() with g_list_prepend() if order of erase_list items is no matter or reimplement erase_list using GQueue otherwise.

[andrew_b]

Branch: 4287_slow_move
changeset:1b39025049322bd311654a4ddaaaeafc1cb39164

[slyfox]

The patch works for me: 1M files move in ~30 seconds.

Thank you!

[andrew_b]

Merged to master: [130e50ec89be9a2d5fd0025dbab5a5d22e575db0].

[Axanar]

I believe, that I triggered an issue with the last merged patch as you can see in the attachment.

When moving single files or a list of files, then the move went fine. As soon as you move a directory with no, one or many files then this critical assertion pops up all the time.

May I ask to have a review of the last merged patch ? This issue won't happen with the last official release but happens with mc git.

[Axanar]

Picture ilustrating the issue.

[andrew_b]

Thanks for the comment!

Fixed: [8b79bfe32d776f0f0299b77b422211b14be29f51].