You are not logged in.

#1 2020-12-30 22:15:31

MickeyMouse
Member
Registered: 2014-10-24
Posts: 5

Freeze on file copy after a new fresh installation on ciphered FS

Hi,

I made a fresh installation on my x280 using grub + dmcrypt + LVM + ext4 layout on a NVME SSD.

- When i made huge file copy inside my encrypted partition using rsync my system is coming more and more slow an nearly hangs until the copy his done. I get dmesg stack traces that indicate that the kernel code is blocked inside ext4 filesystem.
The statistics of the copy :

    sent 4,720,278,622 bytes  received 35 bytes  5,802,432.28 bytes/sec
    total size is 11,526,537,216  speedup is 2.44

-I observe the same behavior when i made a copy from an external un-ciphered HDD to my internal NVME SSD

    sent 4,739,240,065 bytes  received 35 bytes  6,272,984.91 bytes/sec
    total size is 11,526,471,680  speedup is 2.43

- copy from my NVME SSD to the external HDD is normal

    sent 4,720,278,622 bytes  received 35 bytes  38,220,879.81 bytes/sec
    total size is 11,526,537,216  speedup is 2.44

- copy from my external HDD to my external HDD is normal too :

    sent 4,739,240,065 bytes  received 35 bytes  15,771,181.70 bytes/sec
    total size is 11,526,471,680  speedup is 2.43

I assuming that the writes are slow due to dm-crypt.

The cryptsetup luksDump

    cipher: aes-xts-plain64
    sector: 512 [bytes]

The cryptsetup benchmark

        aes-xts        512b      1565,9 MiB/s      1610,6 MiB/s

Thank you for your help

The stack trace

[27647.778482] INFO: task ThreadPoolForeg:17005 blocked for more than 122 seconds.
[27647.778490]       Not tainted 5.9.14-arch1-1 #1
[27647.778494] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27647.778498] task:ThreadPoolForeg state:D stack:    0 pid:17005 ppid:  1771 flags:0x00004080
[27647.778504] Call Trace:
[27647.778521]  __schedule+0x292/0x830
[27647.778531]  ? out_of_line_wait_on_bit_lock+0xb0/0xb0
[27647.778536]  schedule+0x46/0xf0
[27647.778541]  io_schedule+0x42/0x70
[27647.778547]  bit_wait_io+0xd/0x50
[27647.778552]  __wait_on_bit+0x2a/0x90
[27647.778559]  out_of_line_wait_on_bit+0x92/0xb0
[27647.778566]  ? var_wake_function+0x20/0x20
[27647.778583]  do_get_write_access+0x2a9/0x440 [jbd2]
[27647.778598]  jbd2_journal_get_write_access+0x4f/0x80 [jbd2]
[27647.778637]  __ext4_journal_get_write_access+0x72/0x120 [ext4]
[27647.778675]  ? __ext4_new_inode+0x1650/0x1700 [ext4]
[27647.778713]  ext4_reserve_inode_write+0x93/0xc0 [ext4]
[27647.778719]  ? get_acl+0x1a/0x160
[27647.778755]  __ext4_mark_inode_dirty+0x73/0x270 [ext4]
[27647.778791]  __ext4_new_inode+0x1650/0x1700 [ext4]
[27647.778836]  ext4_create+0xd1/0x1a0 [ext4]
[27647.778846]  path_openat+0xda7/0x10b0
[27647.778856]  do_filp_open+0x9c/0x140
[27647.778870]  do_sys_openat2+0xb1/0x160
[27647.778877]  __x64_sys_openat+0x54/0x90
[27647.778884]  do_syscall_64+0x33/0x40
[27647.778889]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27647.778895] RIP: 0033:0x7f8f763f3774
[27647.778899] RSP: 002b:00007f8f6a188da0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
[27647.778903] RAX: ffffffffffffffda RBX: 0000000000008048 RCX: 00007f8f763f3774
[27647.778905] RDX: 0000000000000241 RSI: 000024edec58c8c0 RDI: 00000000ffffff9c
[27647.778908] RBP: 000024edec58c8c0 R08: 0000000000000000 R09: 00000000000000c5
[27647.778910] R10: 0000000000000180 R11: 0000000000000293 R12: 0000000000000241
[27647.778912] R13: 0000000000000241 R14: 00007f8f763f36a0 R15: 00007f8f763f6010
[27647.778922] INFO: task ThreadPoolForeg:17039 blocked for more than 122 seconds.
[27647.778927]       Not tainted 5.9.14-arch1-1 #1
[27647.778929] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27647.778933] task:ThreadPoolForeg state:D stack:    0 pid:17039 ppid:  1771 flags:0x00004080
[27647.778936] Call Trace:
[27647.778944]  __schedule+0x292/0x830
[27647.778951]  schedule+0x46/0xf0
[27647.778956]  io_schedule+0x42/0x70
[27647.778961]  wait_on_page_bit_common+0x129/0x3d0
[27647.778967]  ? file_fdatawait_range+0x20/0x20
[27647.778972]  __filemap_fdatawait_range+0x8c/0xf0
[27647.778982]  file_write_and_wait_range+0x8c/0xb0
[27647.779015]  ext4_sync_file+0x109/0x390 [ext4]
[27647.779024]  __x64_sys_fdatasync+0x47/0x80
[27647.779030]  do_syscall_64+0x33/0x40
[27647.779034]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27647.779037] RIP: 0033:0x7f8f723c1e4b
[27647.779039] RSP: 002b:00007f8f6b98be10 EFLAGS: 00000293 ORIG_RAX: 000000000000004b
[27647.779043] RAX: ffffffffffffffda RBX: 00007f8f6b98be50 RCX: 00007f8f723c1e4b
[27647.779045] RDX: 0000000000000002 RSI: 00007f8f6b98bbf8 RDI: 000000000000001a
[27647.779047] RBP: 00007f8f6b98bed0 R08: 0000000000000000 R09: 000000000000001e
[27647.779049] R10: 00007ffe55fcd080 R11: 0000000000000293 R12: 00007f8f763f6010
[27647.779051] R13: 000000000000016e R14: 00007f8f6b98c000 R15: 00007f8f723c1e10
[27647.779165] INFO: task kworker/u16:1:15946 blocked for more than 122 seconds.
[27647.779169]       Not tainted 5.9.14-arch1-1 #1
[27647.779171] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27647.779174] task:kworker/u16:1   state:D stack:    0 pid:15946 ppid:     2 flags:0x00004080
[27647.779218] Workqueue: ext4-rsv-conversion ext4_end_io_rsv_work [ext4]
[27647.779221] Call Trace:
[27647.779228]  __schedule+0x292/0x830
[27647.779236]  ? out_of_line_wait_on_bit_lock+0xb0/0xb0
[27647.779241]  schedule+0x46/0xf0
[27647.779245]  io_schedule+0x42/0x70
[27647.779251]  bit_wait_io+0xd/0x50
[27647.779256]  __wait_on_bit+0x2a/0x90
[27647.779262]  out_of_line_wait_on_bit+0x92/0xb0
[27647.779267]  ? var_wake_function+0x20/0x20
[27647.779280]  do_get_write_access+0x2a9/0x440 [jbd2]
[27647.779293]  jbd2_journal_get_write_access+0x4f/0x80 [jbd2]
[27647.779323]  __ext4_journal_get_write_access+0x72/0x120 [ext4]
[27647.779355]  ? ext4_ext_map_blocks+0x10bc/0x1b10 [ext4]
[27647.779389]  ext4_reserve_inode_write+0x93/0xc0 [ext4]
[27647.779423]  __ext4_mark_inode_dirty+0x73/0x270 [ext4]
[27647.779456]  ext4_ext_map_blocks+0x10bc/0x1b10 [ext4]
[27647.779464]  ? ttwu_do_wakeup+0x19/0x160
[27647.779505]  ? _raw_spin_unlock_irqrestore+0x20/0x40
[27647.779510]  ? __wake_up_common_lock+0x8b/0xc0
[27647.779548]  ext4_map_blocks+0x119/0x5a0 [ext4]
[27647.779582]  ext4_convert_unwritten_extents+0x176/0x230 [ext4]
[27647.779614]  ext4_convert_unwritten_io_end_vec+0x60/0xe0 [ext4]
[27647.779651]  ext4_end_io_rsv_work+0xfb/0x190 [ext4]
[27647.779661]  process_one_work+0x1da/0x3d0
[27647.779667]  worker_thread+0x4d/0x3d0
[27647.779673]  ? rescuer_thread+0x410/0x410
[27647.779679]  kthread+0x142/0x160
[27647.779685]  ? __kthread_bind_mask+0x60/0x60
[27647.779693]  ret_from_fork+0x22/0x30
[27647.779711] INFO: task rsync:16975 blocked for more than 122 seconds.
[27647.779715]       Not tainted 5.9.14-arch1-1 #1
[27647.779717] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[27647.779720] task:rsync           state:D stack:    0 pid:16975 ppid: 16974 flags:0x00004080
[27647.779724] Call Trace:
[27647.779731]  __schedule+0x292/0x830
[27647.779738]  ? out_of_line_wait_on_bit_lock+0xb0/0xb0
[27647.779743]  schedule+0x46/0xf0
[27647.779748]  io_schedule+0x42/0x70
[27647.779753]  bit_wait_io+0xd/0x50
[27647.779758]  __wait_on_bit+0x2a/0x90
[27647.779764]  out_of_line_wait_on_bit+0x92/0xb0
[27647.779769]  ? var_wake_function+0x20/0x20
[27647.779780]  do_get_write_access+0x2a9/0x440 [jbd2]
[27647.779793]  jbd2_journal_get_write_access+0x4f/0x80 [jbd2]
[27647.779823]  __ext4_journal_get_write_access+0x72/0x120 [ext4]
[27647.779859]  ? ext4_dirty_inode+0x5f/0x80 [ext4]
[27647.779892]  ext4_reserve_inode_write+0x93/0xc0 [ext4]
[27647.779926]  __ext4_mark_inode_dirty+0x73/0x270 [ext4]
[27647.779957]  ? __ext4_journal_start_sb+0x74/0x130 [ext4]
[27647.779991]  ext4_dirty_inode+0x5f/0x80 [ext4]
[27647.779998]  __mark_inode_dirty+0x281/0x3e0
[27647.780006]  generic_write_end+0xf1/0x160
[27647.780041]  ext4_da_write_end+0xac/0x2c0 [ext4]
[27647.780049]  generic_perform_write+0x112/0x1e0
[27647.780083]  ext4_buffered_write_iter+0x9f/0x150 [ext4]
[27647.780092]  new_sync_write+0x156/0x1f0
[27647.780100]  vfs_write+0x1a9/0x210
[27647.780105]  ksys_write+0x67/0xe0
[27647.780112]  do_syscall_64+0x33/0x40
[27647.780116]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27647.780120] RIP: 0033:0x7f3bd42a3f67
[27647.780122] RSP: 002b:00007ffea2436038 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[27647.780126] RAX: ffffffffffffffda RBX: 000056183a4e6410 RCX: 00007f3bd42a3f67
[27647.780128] RDX: 0000000000040000 RSI: 000056183a4e6410 RDI: 0000000000000003
[27647.780130] RBP: 0000000000000003 R08: 0000000000020000 R09: 0000000000020000
[27647.780133] R10: 0000000000000080 R11: 0000000000000246 R12: 0000000000020000
[27647.780135] R13: 0000000000040000 R14: 000056183a4a6400 R15: 00007ffea2436128

Last edited by MickeyMouse (2020-12-30 23:09:22)

Offline

Board footer

Powered by FluxBB