Ticket #4287 (closed defect: fixed)

Opened 3 years ago

Last modified 3 years ago

Quadratic(?) slowdown on file moves across filesystems

Reported by: slyfox Owned by: andrew_b
Priority: major Milestone: 4.8.28
Component: mc-core Version: master
Keywords: Cc:
Blocked By: Blocking:
Branch state: merged Votes for changeset: committed-master

Description

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.

Attachments

Screenshot_2021-10-02_09-03-53.png (71.0 KB) - added by Axanar 3 years ago.
Picture ilustrating the issue.

Change History

comment:1 follow-up: ↓ 2 Changed 3 years ago by 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.

comment:2 in reply to: ↑ 1 Changed 3 years ago by 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.

Version 0, edited 3 years ago by andrew_b (next)

comment:3 Changed 3 years ago by andrew_b

  • Owner set to andrew_b
  • Status changed from new to accepted
  • Branch state changed from no branch to on review
  • Milestone changed from Future Releases to 4.8.28

comment:4 Changed 3 years ago by slyfox

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

Thank you!

comment:5 Changed 3 years ago by andrew_b

  • Votes for changeset set to slyfox andrew_b
  • Branch state changed from on review to approved

comment:6 Changed 3 years ago by andrew_b

  • Status changed from accepted to testing
  • Votes for changeset changed from slyfox andrew_b to committed-master
  • Resolution set to fixed
  • Branch state changed from approved to merged

comment:7 Changed 3 years ago by andrew_b

  • Status changed from testing to closed

comment:8 Changed 3 years ago by 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.

Changed 3 years ago by Axanar

Picture ilustrating the issue.

comment:9 Changed 3 years ago by andrew_b

Thanks for the comment!

Fixed: [8b79bfe32d776f0f0299b77b422211b14be29f51].

Note: See TracTickets for help on using tickets.