Public bug reported:
After upgrading Ubuntu 18.04 kernel from 4.15.0-136-generic to kernel
4.15.0-142-generic disk IOs (writes) are suffering from terrible delay.
Time required to write 1GB of data to the dist is ~12 minutes.
1GB in 12 minutes:
strace -ttvvff -o mel.strace dd bs=1024k count=1024 if=/dev/zero
of=/data/disk_test/dd_test
Before the upgrade, it took seconds to complete.
The only change which was done on the system was security upgrade done with
unattended-upgrade utility and main repositories for bionic and bionic-security.
This is physical server LENOVO System x3650 M5, with Symbios Logic
MegaRAID SAS-3 3108 disk controller.
The only difference which I see is that there are more modules loaded by
the latest kernel.
I would expect that the performance would be the same. There were no
changes to the physical server and the disks are reported as online and
healthy. No only dd is affected but also all disk-based operation by
barman (we are using postgres steaming backup along with rsync/ssh
archiving).
I think this could be a kernel bug. I would be happy to provide other
information which would help in fixing this problem.
=====================================================
Details:
lsb_release -rd
Description: Ubuntu 18.04.1 LTS
Release: 18.04
lsmod
Module Size Used by
ip6_tables 28672 0
iptable_filter 16384 0
ip_tables 28672 1 iptable_filter
x_tables 40960 3 iptable_filter,ip6_tables,ip_tables
tcp_diag 16384 0
udp_diag 16384 0
raw_diag 16384 0
inet_diag 24576 3 tcp_diag,raw_diag,udp_diag
unix_diag 16384 0
binfmt_misc 20480 1
ipmi_ssif 32768 0
kvm_intel 217088 0
kvm 614400 1 kvm_intel
irqbypass 16384 1 kvm
crct10dif_pclmul 16384 0
crc32_pclmul 16384 0
ghash_clmulni_intel 16384 0
pcbc 16384 0
aesni_intel 188416 0
aes_x86_64 20480 1 aesni_intel
crypto_simd 16384 1 aesni_intel
glue_helper 16384 1 aesni_intel
cryptd 24576 3 crypto_simd,ghash_clmulni_intel,aesni_intel
ipmi_si 57344 0
ipmi_devintf 20480 0
ipmi_msghandler 53248 3 ipmi_devintf,ipmi_si,ipmi_ssif
acpi_pad 180224 0
bonding 163840 0
lp 20480 0
parport 49152 1 lp
autofs4 40960 2
mgag200 45056 1
i2c_algo_bit 16384 1 mgag200
ttm 106496 1 mgag200
drm_kms_helper 172032 1 mgag200
syscopyarea 16384 1 drm_kms_helper
tg3 167936 0
sysfillrect 16384 1 drm_kms_helper
sysimgblt 16384 1 drm_kms_helper
fb_sys_fops 16384 1 drm_kms_helper
ptp 20480 1 tg3
drm 401408 4 drm_kms_helper,mgag200,ttm
pps_core 20480 1 ptp
megaraid_sas 143360 12
lspci -vnn -s 0b:00.0
0b:00.0 RAID bus controller [0104]: LSI Logic / Symbios Logic MegaRAID SAS-3
3108 [Invader] [1000:005d] (rev 02)
Subsystem: IBM MegaRAID SAS-3 3108 [Invader] [1014:0454]
Physical Slot: 9
Flags: bus master, fast devsel, latency 0, IRQ 31, NUMA node 0
I/O ports at 2e00 [size=256]
Memory at 903f0000 (64-bit, non-prefetchable) [size=64K]
Memory at 90400000 (64-bit, non-prefetchable) [size=1M]
Expansion ROM at <ignored> [disabled]
Capabilities: [50] Power Management version 3
Capabilities: [68] Express Endpoint, MSI 00
Capabilities: [d0] Vital Product Data
Capabilities: [a8] MSI: Enable- Count=1/1 Maskable+ 64bit+
Capabilities: [c0] MSI-X: Enable+ Count=97 Masked-
Capabilities: [100] Advanced Error Reporting
Capabilities: [1e0] #19
Capabilities: [1c0] Power Budgeting <?>
Capabilities: [148] Alternative Routing-ID Interpretation (ARI)
Kernel driver in use: megaraid_sas
Kernel modules: megaraid_sas
Strace example for 10MB:
strace -ttvvff -o mel.strace dd bs=1024k count=10 if=/dev/zero
of=/data/disk_test/dd_test
10+0 records in
10+0 records out
10485760 bytes (10 MB, 10 MiB) copied, 6.73972 s, 1.6 MB/s
14:59:19.145037 execve("/bin/dd", ["dd", "bs=1024k", "count=10",
"if=/dev/zero", "of=/data/disk_test/dd_test"],
["LS_COLORS=rs=0:di=01;34:ln=01;36"..., "LESSCLOSE=/usr/bin/lesspipe %s %"...,
"LANG=en_AU.UTF-8", "SUDO_GID=4118", "USERNAME=root", "SUDO_COMMAND=/bin/bash",
"S_COLORS=auto", "USER=root", "PWD=/data/disk_test", "HOME=/root",
"SUDO_USER=mariusz.boruc", "SUDO_UID=4118", "MAIL=/var/mail/root",
"SHELL=/bin/bash", "TERM=xterm-256color", "SHLVL=1", "LANGUAGE=en_AU:",
"LOGNAME=root", "PATH=/usr/local/sbin:/usr/local/"..., "LESSOPEN=|
/usr/bin/lesspipe %s", "_=/usr/bin/strace", "OLDPWD=/data"]) = 0
14:59:19.145685 brk(NULL) = 0x563734ec4000
14:59:19.145766 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or
directory)
14:59:19.145846 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or
directory)
14:59:19.145909 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
14:59:19.145970 fstat(3, {st_dev=makedev(8, 3), st_ino=845,
st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=64, st_size=28885, st_atime=1621301366 /*
2021-05-18T10:59:26.840044503+0930 */, st_atime_nsec=840044503,
st_mtime=1620610160 /* 2021-05-10T10:59:20.912915629+0930 */,
st_mtime_nsec=912915629, st_ctime=1620610160 /*
2021-05-10T10:59:20.912915629+0930 */, st_ctime_nsec=912915629}) = 0
14:59:19.146055 mmap(NULL, 28885, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f49d79db000
14:59:19.146108 close(3) = 0
14:59:19.146159 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or
directory)
14:59:19.146215 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6",
O_RDONLY|O_CLOEXEC) = 3
14:59:19.146270 read(3,
"\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..., 832) =
832
14:59:19.146327 fstat(3, {st_dev=makedev(8, 3), st_ino=1413,
st_mode=S_IFREG|0755, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=3968, st_size=2030544, st_atime=1621312135 /*
2021-05-18T13:58:55.539717705+0930 */, st_atime_nsec=539717705,
st_mtime=1591291526 /* 2020-06-05T02:55:26+0930 */, st_mtime_nsec=0,
st_ctime=1604896088 /* 2020-11-09T14:58:08.844042263+1030 */,
st_ctime_nsec=844042263}) = 0
14:59:19.146403 mmap(NULL, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f49d79d9000
14:59:19.146460 mmap(NULL, 4131552, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f49d73cb000
14:59:19.146510 mprotect(0x7f49d75b2000, 2097152, PROT_NONE) = 0
14:59:19.146567 mmap(0x7f49d77b2000, 24576, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7f49d77b2000
14:59:19.146629 mmap(0x7f49d77b8000, 15072, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f49d77b8000
14:59:19.146689 close(3) = 0
14:59:19.146758 arch_prctl(ARCH_SET_FS, 0x7f49d79da540) = 0
14:59:19.146895 mprotect(0x7f49d77b2000, 16384, PROT_READ) = 0
14:59:19.146990 mprotect(0x563733ac0000, 4096, PROT_READ) = 0
14:59:19.147044 mprotect(0x7f49d79e3000, 4096, PROT_READ) = 0
14:59:19.147093 munmap(0x7f49d79db000, 28885) = 0
14:59:19.147190 rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[],
sa_flags=0}, 8) = 0
14:59:19.147248 rt_sigaction(SIGUSR1, {sa_handler=0x5637338b30e0, sa_mask=[INT
USR1], sa_flags=SA_RESTORER, sa_restorer=0x7f49d7409fd0}, NULL, 8) = 0
14:59:19.147301 rt_sigaction(SIGINT, {sa_handler=0x5637338b30d0, sa_mask=[INT
USR1], sa_flags=SA_RESTORER|SA_NODEFER|SA_RESETHAND,
sa_restorer=0x7f49d7409fd0}, NULL, 8) = 0
14:59:19.147430 brk(NULL) = 0x563734ec4000
14:59:19.147475 brk(0x563734ee5000) = 0x563734ee5000
14:59:19.147535 openat(AT_FDCWD, "/usr/lib/locale/locale-archive",
O_RDONLY|O_CLOEXEC) = 3
14:59:19.147602 fstat(3, {st_dev=makedev(8, 7), st_ino=48819,
st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=3168, st_size=1687536, st_atime=1621312728 /*
2021-05-18T14:08:48.519742590+0930 */, st_atime_nsec=519742590,
st_mtime=1604896695 /* 2020-11-09T15:08:15.489844866+1030 */,
st_mtime_nsec=489844866, st_ctime=1604896695 /*
2020-11-09T15:08:15.489844866+1030 */, st_ctime_nsec=489844866}) = 0
14:59:19.147687 mmap(NULL, 1687536, PROT_READ, MAP_PRIVATE, 3, 0) =
0x7f49d783d000
14:59:19.147746 close(3) = 0
14:59:19.147853 openat(AT_FDCWD, "/dev/zero", O_RDONLY) = 3
14:59:19.147912 dup2(3, 0) = 0
14:59:19.147960 close(3) = 0
14:59:19.148005 lseek(0, 0, SEEK_CUR) = 0
14:59:19.148051 openat(AT_FDCWD, "/data/disk_test/dd_test",
O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
14:59:19.293893 dup2(3, 1) = 1
14:59:19.293961 close(3) = 0
14:59:19.294012 mmap(NULL, 1060864, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f49d72c8000
14:59:19.294069 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:19.294495 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.025616 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.025759 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.026304 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.026416 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.026966 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.027067 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.027605 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.027714 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.028242 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.028339 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.028841 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.028927 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.029459 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.029558 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.030123 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.030235 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.030790 read(0,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.030902 write(1,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576)
= 1048576
14:59:26.031457 close(0) = 0
14:59:26.031503 close(1) = 0
14:59:26.032941 openat(AT_FDCWD, "/usr/share/locale/locale.alias",
O_RDONLY|O_CLOEXEC) = 0
14:59:26.033098 fstat(0, {st_dev=makedev(8, 3), st_ino=992,
st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=8, st_size=2995, st_atime=1621312819 /*
2021-05-18T14:10:19.531746410+0930 */, st_atime_nsec=531746410,
st_mtime=1591291526 /* 2020-06-05T02:55:26+0930 */, st_mtime_nsec=0,
st_ctime=1604896693 /* 2020-11-09T15:08:13.373844883+1030 */,
st_ctime_nsec=373844883}) = 0
14:59:26.033168 read(0, "# Locale name alias data base.\n#"..., 4096) = 2995
14:59:26.033323 read(0, "", 4096) = 0
14:59:26.033358 close(0) = 0
14:59:26.033400 openat(AT_FDCWD,
"/usr/share/locale/en_AU/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No
such file or directory)
14:59:26.033447 openat(AT_FDCWD,
"/usr/share/locale/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such
file or directory)
14:59:26.033487 openat(AT_FDCWD,
"/usr/share/locale-langpack/en_AU/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
14:59:26.033616 openat(AT_FDCWD,
"/usr/share/locale-langpack/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT
(No such file or directory)
14:59:26.033678 write(2, "10+0 records in\n10+0 records out"..., 33) = 33
14:59:26.033747 write(2, "10485760 bytes (10 MB, 10 MiB) c"..., 58) = 58
14:59:26.033785 write(2, "\n", 1) = 1
14:59:26.033824 close(2) = 0
14:59:26.033863 exit_group(0) = ?
14:59:26.034041 +++ exited with 0 +++
** Affects: ubuntu
Importance: Undecided
Status: New
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1928744
Title:
Disk IO very slow on kernel 4.15.0-142-generic
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+bug/1928744/+subscriptions
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
