|
Hi Stan, thank you very much for your comments, I need some time to follow through all of your suggestions. Yes, this is a dovecot IMAP and sendmail SMTP server, and there are 1360 mailboxes. With this email, I'd like to give you a bit more information with strace -T and others commands. Because "# CONFIG_LOCK_STAT is not set", I can not run perf lock record. Since this is a production server, I am reluctant to rebuild the kernel on it. But I hope the info below may give you an idea that it is not "lock" related. As slow "ls -l" and "du" also happen on the two file servers (64TB and 32TB), it does not feel like it is lock related. I run this "(time strace -T ls -l /var/spool/mail > ls-out) >& ls-trace" and got quite a bit data. First "time" output: ===== real 0m17.720s user 0m0.574s sys 0m1.271s ===== Some 14s was spent on 164 "poll" calls on fd=5 that took more than 10ms, total number of "poll" call is 6618! Below is the trace output, red numbers are the three longest time taken, listed at top are those that took more than 100ms, the three sections are for the top three time taken, note the three mailboxes are not special compare to another mailboxes, a run at another time would produce calls on different mailboxes. Also, cache seams to play a role too, after a fresh run that takes long time, subsequent runs give instant results: ===== poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.144634> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.104580> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.104812> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.181959> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.102520> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.107539> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.142462> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.215745> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.309854> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.166665> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.101035> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.113119> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.120745> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.110027> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.137906> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.249039> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.104079> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.250003> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.103791> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.102018> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.103551> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.103696> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.102164> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.105843> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.104413> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.101304> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.101869> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.101366> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.132958> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.309411> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.100342> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.101279> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.144725> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.109867> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.109951> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.290189> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.102449> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.101182> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.111699> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.107351> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.104558> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.115447> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.163904> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.266427> ##### df=5 opened: socket(PF_FILE, SOCK_STREAM, 0) = 5 <0.000016> fcntl(5, F_GETFL) = 0x2 (flags O_RDWR) <0.000010> fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000010> fcntl(5, F_GETFD) = 0 <0.000010> fcntl(5, F_SETFD, FD_CLOEXEC) = 0 <0.000010> connect(5, {sa_family=AF_FILE, path="/var/lib/sss/pipes/nss"}, 110) = 0 <0.001886> fstat(5, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 <0.000010> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000012> sendto(5, "\24\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0", 16, MSG_NOSIGNAL, NULL, 0) = 16 <0.000029> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000012> sendto(5, "\1\0\0\0", 4, MSG_NOSIGNAL, NULL, 0) = 4 <0.000027> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000011> read(5, "\24\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0", 16) = 16 <0.000013> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000011> read(5, "\1\0\0\0", 4) = 4 <0.000025> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000011> sendto(5, "\24\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0", 16, MSG_NOSIGNAL, NULL, 0) = 16 <0.000026> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000011> sendto(5, "\225N\0\0", 4, MSG_NOSIGNAL, NULL, 0) = 4 <0.000025> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000515> read(5, "L\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0", 16) = 16 <0.000012> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000011> read(5, "\1\0\0\0\0\0\0\0\225N\0\0\311\0\0\0qchang\0*\0Qing Ch"..., 60) = 60 <0.000026> open("/etc/group", O_RDONLY|O_CLOEXEC) = 6 <0.000017> fstat(6, {st_mode=S_IFREG|0644, st_size=790, ...}) = 0 <0.000010> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd5d53f4000 <0.004539> read(6, "root:x:0:root\nbin:x:1:root,bin,d"..., 4096) = 790 <0.000018> read(6, "", 4096) = 0 <0.000011> close(6) = 0 <0.000011> munmap(0x7fd5d53f4000, 4096) = 0 <0.000016> open("/var/lib/sss/mc/group", O_RDONLY|O_CLOEXEC) = 6 <0.000021> fstat(6, {st_mode=S_IFREG|0644, st_size=5206312, ...}) = 0 <0.000010> mmap(NULL, 5206312, PROT_READ, MAP_SHARED, 6, 0) = 0x7fd5ce3c1000 <0.000015> poll([{fd=5, events=POLLIN|POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000012> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000011> sendto(5, "\24\0\0\0\"\0\0\0\0\0\0\0\0\0\0\0", 16, MSG_NOSIGNAL, NULL, 0) = 16 <0.000031> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000011> sendto(5, "\311\0\0\0", 4, MSG_NOSIGNAL, NULL, 0) = 4 <0.000025> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000427> read(5, "?\0\0\0\"\0\0\0\0\0\0\0\0\0\0\0", 16) = 16 <0.000013> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000011> read(5, "\1\0\0\0\0\0\0\0\311\0\0\0\3\0\0\0\0*\0qiu"..., 47) = 47 <0.000017> lstat("/var/spool/mail/root", {st_mode=S_IFREG|0600, st_size=187649403, ...}) = 0 <0.000019> lgetxattr("/var/spool/mail/root", "security.selinux", "unconfined_u:object_r:file_t:s0", 255) = 32 <0.000020> lstat("/var/spool/mail/root", {st_mode=S_IFREG|0600, st_size=187649403, ...}) = 0 <0.000014> lgetxattr("/var/spool/mail/root", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available) <0.000018> lgetxattr("/var/spool/mail/root", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available) <0.000016> lstat("/var/spool/mail/agutstei", {st_mode=S_IFREG|0600, st_size=3864251, ...}) = 0 <0.000016> lgetxattr("/var/spool/mail/agutstei", "security.selinux", "unconfined_u:object_r:file_t:s0", 255) = 32 <0.000018> lstat("/var/spool/mail/agutstei", {st_mode=S_IFREG|0600, st_size=3864251, ...}) = 0 <0.000015> lgetxattr("/var/spool/mail/agutstei", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available) <0.000016> lgetxattr("/var/spool/mail/agutstei", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available) <0.000015> open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 7 <0.000017> fstat(7, {st_mode=S_IFREG|0644, st_size=1835, ...}) = 0 <0.000011> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd5ce3c0000 <0.000014> read(7, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1835 <0.000020> read(7, "", 4096) = 0 <0.000011> close(7) = 0 <0.000012> ###### took 0.309854s: munmap(0x7fd5ce3c0000, 4096) = 0 <0.000015> poll([{fd=5, events=POLLIN|POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000011> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000010> sendto(5, "\24\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0", 16, MSG_NOSIGNAL, NULL, 0) = 16 <0.000034> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000010> sendto(5, "\253\260\0\0", 4, MSG_NOSIGNAL, NULL, 0) = 4 <0.000335> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.309854> read(5, "N\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0", 16) = 16 <0.000012> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000010> read(5, "\1\0\0\0\0\0\0\0\253\260\0\0\253\1\0\0acqu\0*\0Chen Ge A"..., 62) = 62 <0.000016> lstat("/var/spool/mail/araouf", {st_mode=S_IFREG|0600, st_size=3943191, ...}) = 0 <0.000052> lgetxattr("/var/spool/mail/araouf", "security.selinux", "unconfined_u:object_r:file_t:s0", 255) = 32 <0.000021> lstat("/var/spool/mail/araouf", {st_mode=S_IFREG|0600, st_size=3943191, ...}) = 0 <0.000014> lgetxattr("/var/spool/mail/araouf", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available) <0.000017> lgetxattr("/var/spool/mail/araouf", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available) <0.000015> open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 7 <0.000016> fstat(7, {st_mode=S_IFREG|0644, st_size=1835, ...}) = 0 <0.000010> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd5ce3c0000 <0.000012> read(7, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1835 <0.000018> read(7, "", 4096) = 0 <0.000010> close(7) = 0 <0.000012> ###### took 0.309411: munmap(0x7fd5ce3c0000, 4096) = 0 <0.000015> poll([{fd=5, events=POLLIN|POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000010> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000009> sendto(5, "\24\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0", 16, MSG_NOSIGNAL, NULL, 0) = 16 <0.000035> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000010> sendto(5, "\357\246\0\0", 4, MSG_NOSIGNAL, NULL, 0) = 4 <0.000342> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.309411> read(5, "V\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0", 16) = 16 <0.000012> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000010> read(5, "\1\0\0\0\0\0\0\0\357\246\0\0\253\1\0\0pthaya\0*\0Parthip"..., 70) = 70 <0.000018> lstat("/var/spool/mail/ptsao", {st_mode=S_IFREG|0600, st_size=515358, ...}) = 0 <0.000025> lgetxattr("/var/spool/mail/ptsao", "security.selinux", "unconfined_u:object_r:file_t:s0", 255) = 32 <0.000021> lstat("/var/spool/mail/ptsao", {st_mode=S_IFREG|0600, st_size=515358, ...}) = 0 <0.000014> lgetxattr("/var/spool/mail/ptsao", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available) <0.000019> lgetxattr("/var/spool/mail/ptsao", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available) <0.000014> open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 7 <0.000017> fstat(7, {st_mode=S_IFREG|0644, st_size=1835, ...}) = 0 <0.000010> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd5ce3c0000 <0.000012> read(7, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1835 <0.000019> read(7, "", 4096) = 0 <0.000009> close(7) = 0 <0.000011> ###### took 0.290189: munmap(0x7fd5ce3c0000, 4096) = 0 <0.000015> poll([{fd=5, events=POLLIN|POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000011> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000010> sendto(5, "\24\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0", 16, MSG_NOSIGNAL, NULL, 0) = 16 <0.000034> poll([{fd=5, events=POLLOUT}], 1, 300000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000010> sendto(5, "\10\270\0\0", 4, MSG_NOSIGNAL, NULL, 0) = 4 <0.000391> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.290189> read(5, "N\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0", 16) = 16 <0.000012> poll([{fd=5, events=POLLIN}], 1, 300000) = 1 ([{fd=5, revents=POLLIN}]) <0.000010> read(5, "\1\0\0\0\0\0\0\0\10\270\0\0\327\1\0\0taberk\0*\0Thomas "..., 62) = 62 <0.000017> lstat("/var/spool/mail/taha", {st_mode=S_IFREG|0600, st_size=293648143, ...}) = 0 <0.000018> lgetxattr("/var/spool/mail/taha", "security.selinux", "unconfined_u:object_r:file_t:s0", 255) = 32 <0.000022> lstat("/var/spool/mail/taha", {st_mode=S_IFREG|0600, st_size=293648143, ...}) = 0 <0.000013> lgetxattr("/var/spool/mail/taha", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available) <0.000021> lgetxattr("/var/spool/mail/taha", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available) <0.000014> open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 7 <0.000021> fstat(7, {st_mode=S_IFREG|0644, st_size=1835, ...}) = 0 <0.000010> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd5ce3c0000 <0.000015> read(7, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1835 <0.000033> read(7, "", 4096) = 0 <0.000011> close(7) = 0 <0.000013> ===== ====== iostat around the time ls -l was run ===== [root@dovecot2 ~]# iostat -xmz 5 Linux 2.6.32-358.18.1.el6.x86_64 (dovecot2.sri.utoronto.ca) 11/12/2013 _x86_64_ (16 CPU) avg-cpu: %user %nice %system %iowait %steal %idle 0.56 0.00 0.17 0.06 0.00 99.21 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util sda 0.01 19.88 0.14 26.86 0.00 0.18 14.18 0.02 0.57 0.28 0.75 sdb 0.23 0.08 1.75 1.98 0.04 0.02 30.38 0.01 2.81 1.26 0.47 sdc 0.00 0.03 13.78 0.71 1.34 0.05 196.35 0.02 1.60 0.77 1.11 dm-0 0.00 0.00 0.09 2.42 0.00 0.01 8.49 0.00 1.18 0.52 0.13 dm-1 0.00 0.00 0.00 0.00 0.00 0.00 8.00 0.00 3.09 0.27 0.00 dm-2 0.00 0.00 0.06 44.33 0.00 0.17 8.14 0.04 0.90 0.14 0.63 avg-cpu: %user %nice %system %iowait %steal %idle 1.31 0.00 0.46 0.10 0.00 98.12 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 27.40 1.00 65.80 0.02 0.36 11.78 0.04 0.61 0.43 2.86 sdb 0.00 0.00 1.80 0.00 0.03 0.00 31.11 0.01 6.44 2.00 0.36 sdc 0.00 1.00 0.00 4.80 0.00 0.03 11.79 0.03 6.88 0.46 0.22 dm-0 0.00 0.00 0.80 1.20 0.02 0.00 24.00 0.01 6.10 6.10 1.22 dm-2 0.00 0.00 0.00 92.00 0.00 0.36 8.00 0.06 0.62 0.19 1.76 avg-cpu: %user %nice %system %iowait %steal %idle 5.76 0.00 1.62 0.59 0.00 92.03 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 1045.60 0.80 959.40 0.05 7.83 16.82 0.44 0.46 0.21 19.98 sdb 0.00 0.00 1.40 1.20 0.01 0.01 9.23 0.00 0.62 0.54 0.14 sdc 0.00 0.00 0.00 0.60 0.00 0.01 18.67 0.00 0.33 0.33 0.02 dm-0 0.00 0.00 0.80 8.00 0.05 0.03 20.00 0.02 2.05 1.41 1.24 dm-2 0.00 0.00 0.00 1997.00 0.00 7.80 8.00 1.24 0.62 0.09 18.86 avg-cpu: %user %nice %system %iowait %steal %idle 4.38 0.00 1.29 0.67 0.00 93.66 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 1204.40 0.00 1074.60 0.00 8.90 16.97 0.41 0.38 0.20 21.04 sdb 0.20 0.00 2.00 0.00 0.01 0.00 13.60 0.01 6.80 4.00 0.80 dm-0 0.00 0.00 0.00 9.00 0.00 0.04 8.00 0.01 1.27 0.42 0.38 dm-2 0.00 0.00 0.00 2270.00 0.00 8.87 8.00 1.33 0.59 0.09 20.74 avg-cpu: %user %nice %system %iowait %steal %idle 4.24 0.00 1.16 0.58 0.00 94.02 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 1159.20 0.00 985.80 0.00 8.38 17.41 0.34 0.35 0.18 17.84 sdb 0.00 0.00 0.20 1.40 0.00 0.01 8.62 0.00 0.75 0.75 0.12 sdc 0.00 0.00 0.00 0.20 0.00 0.00 16.00 0.00 1.00 1.00 0.02 dm-0 0.00 0.00 0.00 5.00 0.00 0.02 8.00 0.00 0.24 0.24 0.12 dm-2 0.00 0.00 0.00 2140.00 0.00 8.36 8.00 1.23 0.58 0.08 17.90 avg-cpu: %user %nice %system %iowait %steal %idle 2.77 0.00 1.14 0.54 0.00 95.55 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 768.20 0.00 847.40 0.00 6.31 15.25 0.36 0.43 0.19 16.40 sdb 0.00 0.00 0.00 2.00 0.00 0.01 7.00 0.00 0.10 0.10 0.02 sdc 0.00 0.00 0.00 2.00 0.00 0.04 37.60 0.00 0.70 0.40 0.08 dm-0 0.00 0.00 0.00 18.80 0.00 0.07 8.00 0.09 4.84 0.27 0.50 dm-2 0.00 0.00 0.00 1596.80 0.00 6.24 8.00 0.84 0.52 0.10 16.22 ===== ===== vmstat ===== [root@dovecot2 ~]# vmstat 5 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 2 0 3476 785664 223836 29329692 0 0 88 16 1 1 1 0 99 0 0 1 0 3476 783512 223844 29330448 0 0 84 3383 2210 3985 3 1 96 0 0 0 1 3476 779328 223848 29331208 0 0 20 9254 4530 9894 5 2 92 1 0 2 0 3476 778616 223856 29331956 0 0 1 9104 4160 10909 4 1 94 1 0 1 0 3476 777584 223864 29332932 0 0 0 10056 4428 10263 4 1 94 1 0 0 0 3476 778312 223872 29333044 0 0 2 660 921 1871 1 0 99 0 0 ===== Really appreciate your willingness to help and your time spent on this! Qing On 04/11/2013 1:42 AM, Stan Hoeppner
wrote:
On 11/1/2013 2:11 PM, Qing Chang wrote:I have collected some info following the FAQ guide. It may still not be enough. Please let me know.You say /var/spool/mail contains 1360 "items". That's ambiguous. You mean 1360 user mbox files, yes?# time to run ls -l (1360 items): time ls -l /var/spool/mail real 0m10.271s user 0m0.097s sys 0m0.162sThe combined CPU execution time is apparently 0.259s. Something else is adding 10s+ of delay. mbox is notorious for locking problems. I wonder if stat() is waiting on release of exclusive write locks being held by your MDA during delivery. This would also tend to explain the variability you demonstrated, with one run being 10s and another being 7s--fewer files locked on the second run. Run 'ls' with "strace -T" to find out which system call is adding the delay. Run perf-lock concurrently to see the locks. More comments below.# Oct 29, 2013 # # XFS slowness with ls du etc. kernel version (uname -a) Linux dovecot2.sri.utoronto.ca 2.6.32-358.18.1.el6.x86_64 #1 SMP Fri Aug 2 17:04:38 EDT 2013 x86_64 x86_64 x86_64 GNU/Linux xfsprogs version (xfs_repair -V) xfs_repair version 3.1.1 number of CPUs: 16 virtual CPUs contents of /proc/meminfo MemTotal: 32878632 kB MemFree: 310260 kB Buffers: 220496 kB Cached: 29971428 kB SwapCached: 212 kB Active: 9726912 kB Inactive: 21180124 kB Active(anon): 385040 kB Inactive(anon): 330260 kB Active(file): 9341872 kB Inactive(file): 20849864 kB Unevictable: 0 kB Mlocked: 0 kB SwapTotal: 6160376 kB SwapFree: 6159896 kB Dirty: 772 kB Writeback: 0 kB AnonPages: 714912 kB Mapped: 52696 kB Shmem: 184 kB Slab: 1045988 kB SReclaimable: 776440 kB SUnreclaim: 269548 kB KernelStack: 8736 kB PageTables: 57172 kB NFS_Unstable: 0 kB Bounce: 0 kB WritebackTmp: 0 kB CommitLimit: 22599692 kB Committed_AS: 1148180 kB VmallocTotal: 34359738367 kB VmallocUsed: 335224 kB VmallocChunk: 34333710552 kB HardwareCorrupted: 0 kB AnonHugePages: 180224 kB HugePages_Total: 0 HugePages_Free: 0 HugePages_Rsvd: 0 HugePages_Surp: 0 Hugepagesize: 2048 kB DirectMap4k: 10240 kB DirectMap2M: 33544192 kB contents of /proc/mounts [root@dovecot2 ~]# cat /proc/mounts rootfs / rootfs rw 0 0 proc /proc proc rw,relatime 0 0 sysfs /sys sysfs rw,seclabel,relatime 0 0 devtmpfs /dev devtmpfs rw,seclabel,relatime,size=16429456k,nr_inodes=4107364,mode=755 0 0 devpts /dev/pts devpts rw,seclabel,relatime,gid=5,mode=620,ptmxmode=000 0 0 tmpfs /dev/shm tmpfs rw,seclabel,relatime 0 0 /dev/mapper/vg_ipa1-lv_root / ext4 rw,seclabel,relatime,barrier=1,data="" 0 0 none /selinux selinuxfs rw,relatime 0 0 devtmpfs /dev devtmpfs rw,seclabel,relatime,size=16429456k,nr_inodes=4107364,mode=755 0 0 /proc/bus/usb /proc/bus/usb usbfs rw,relatime 0 0 /dev/sda1 /boot ext4 rw,seclabel,relatime,barrier=1,data="" 0 0 /dev/mapper/vg_ipa1-lv_home /var ext4 rw,seclabel,relatime,barrier=1,data="" 0 0 /dev/sdb1 /mailhomes xfs rw,seclabel,relatime,attr2,delaylog,nobarrier,inode64,usrquota 0 0 /dev/sdc1 /var/spool/mail xfs rw,seclabel,relatime,attr2,delaylog,nobarrier,inode64,usrquota 0 0 none /proc/sys/fs/binfmt_misc binfmt_misc rw,relatime 0 0 sunrpc /var/lib/nfs/rpc_pipefs rpc_pipefs rw,relatime 0 0 contents of /proc/partitions major minor #blocks name 8 0 83886080 sda 8 1 512000 sda1 8 2 83373056 sda2 8 16 5368709120 sdb 8 17 5368707072 sdb1 8 32 2147483648 sdc 8 33 2147481600 sdc1 253 0 56729600 dm-0 253 1 6160384 dm-1 253 2 20480000 dm-2 RAID layout (hardware and/or software): Hardware RAID6 IBM Storwize V7000What we're looking for here is the RAID geometry of the local disk device, logical volume, SAN LUN, etc, underlying the XFS filesystem, i.e. number of disks in the array, RAID level, stripe unit and stripe width.LVM configuration: XFS not configured type of disks you are using: SAS dirves write cache status of drives: V7000 has 16 GB of cache size of BBWC and mode it is running in: N/AThe 16GB of BBWC in the V7000 defaults to write-back mode, or has been manually enabled. If not you're playing Russian roulette, because you're mounting with nobarrier. You only disable barriers if you have persistent write cache, either battery or flash based. |
_______________________________________________ xfs mailing list xfs@xxxxxxxxxxx http://oss.sgi.com/mailman/listinfo/xfs
