#15585: IO stall for a long time during creation or deletion of many small files
-----------------------------+----------------------------
Reporter: X512 | Owner: nobody
Type: bug | Status: new
Priority: normal | Milestone: Unscheduled
Component: System/Kernel | Version: R1/Development
Resolution: | Keywords:
Blocked By: | Blocking:
Has a Patch: 0 | Platform: All
-----------------------------+----------------------------
Comment (by waddlesplash):
I think I managed to catch it during one of these "pauses", and this is
the stack trace:
{{{
kdebug> bt 547
stack trace for thread 547 "tar"
kernel stack: 0xffffffff81169000 to 0xffffffff8116e000
user stack: 0x00007f4aa268f000 to 0x00007f4aa368f000
frame caller <image>:function + offset
0 ffffffff8116d7b0 (+ 112) ffffffff80098102 <kernel_x86_64>
reschedule(int) + 0x4f2
1 ffffffff8116d820 (+ 64) ffffffff80088086 <kernel_x86_64>
thread_block + 0xf6
2 ffffffff8116d860 (+ 80) ffffffff80054e15 <kernel_x86_64>
ConditionVariableEntry::Wait(unsigned int, long) + 0xf5
3 ffffffff8116d8b0 (+ 96) ffffffff8151857c <nvme_disk>
await_status(nvme_disk_driver_info*, nvme_qpair*, int&) + 0x4c
4 ffffffff8116d910 (+ 80) ffffffff8151870b <nvme_disk>
nvme_disk_ioctl(void*, unsigned int, void*, unsigned long) + 0x13b
5 ffffffff8116d960 (+ 320) ffffffff800ce726 <kernel_x86_64>
devfs_ioctl(fs_volume*, fs_vnode*, void*, unsigned int, void*, unsigned
long) + 0x206
6 ffffffff8116daa0 (+ 64) ffffffff800f044c <kernel_x86_64>
fd_ioctl(bool, int, unsigned int, void*, unsigned long) + 0x5c
7 ffffffff8116dae0 (+ 32) ffffffff800f1b09 <kernel_x86_64> _kern_ioctl
+ 0x39
8 ffffffff8116db00 (+ 112) ffffffff8016b90d <kernel_x86_64> ioctl +
0x2d
9 ffffffff8116db70 (+ 384) ffffffff818a6d14 <bfs>
_ZN7Journal22_WriteTransactionToLogEv.localalias.9 + 0x7e4
10 ffffffff8116dcf0 (+ 48) ffffffff818a6fe5 <bfs>
Journal::Unlock(Transaction*, bool) + 0x35
11 ffffffff8116dd20 (+ 128) ffffffff818ac211 <bfs>
bfs_create_dir(fs_volume*, fs_vnode*, char const*, int) + 0x131
12 ffffffff8116dda0 (+ 304) ffffffff80104b92 <kernel_x86_64>
dir_create(int, char*, int, bool) + 0x62
13 ffffffff8116ded0 (+ 80) ffffffff8010d484 <kernel_x86_64>
_user_create_dir + 0x84
14 ffffffff8116df20 (+ 16) ffffffff8014fd34 <kernel_x86_64>
x86_64_syscall_entry + 0xfe
user iframe at 0xffffffff8116df30 (end = 0xffffffff8116dff8)
rax 0x74 rbx 0x7f4aa368f648 rcx 0x14ed6357b64
rdx 0x1c0 rsi 0x240c34cee0 rdi 0xffffffff
rbp 0x7f4aa368e830 r8 0x7f4aa368e8c0 r9 0x1
r10 0x240c34cee0 r11 0x3206 r12 0x3
r13 0x7f4aa368f668 r14 0x0 r15 0x0
rip 0x14ed6357b64 rsp 0x7f4aa368e818 rflags 0x3206
vector: 0x63, error code: 0x0
15 ffffffff8116df30 (+139960675076352) 0000014ed6357b64 <libroot.so>
_kern_create_dir + 0x0c
16 00007f4aa368e830 (+ 192) 000001d055fb07fa <tar>
remove_delayed_set_stat (nearest) + 0xbdb
17 00007f4aa368e8f0 (+ 48) 000001d055fb1ed1 <tar> extract_archive +
0x293
18 00007f4aa368e920 (+ 192) 000001d055fbabf0 <tar> read_and + 0x24c
19 00007f4aa368e9e0 (+ 32) 000001d055fcd84c <tar> main + 0x199
20 00007f4aa368ea00 (+ 48) 000001d055fa20d1 <tar> _start + 0x51
21 00007f4aa368ea30 (+ 48) 0000009d0e3dd485
</boot/system/runtime_loader@0x0000009d0e3c9000> <unknown> + 0x14485
22 00007f4aa368ea60 (+ 0) 00007fff8f567260 <commpage>
commpage_thread_exit + 0x00
kdebug>
}}}
So it seems that it's waiting for the drive cache to flush. ram_disk has
nothing to do here, so it makes sense that the "stall" is not seen on the
ramdisk; it also explains why we are, despite the pauses, not slower than
Windows: after flushing the drive cache it will be empty, so we can then
saturate it again before things get slow.
--
Ticket URL: <https://dev.haiku-os.org/ticket/15585#comment:25>
Haiku <https://dev.haiku-os.org>
The Haiku operating system.
