Can you include the timestamps in strace-root.txt, too? These are very
helpful
to see where it hangs/how much time some operations need.
Just tested with root + timestamp. With root everything happens within 1
second....
First line:
19:19:48 execve("/opt/zimbra/dspam/bin/dspam",
["/opt/zimbra/dspam/bin/dspam", "--process", "--debug", "--user",
"root", "--deliver=spam,innocent", "--stdout"], [/* 31 vars */]) = 0
Last line:
19:19:48 exit_group(0) = ?
Several things seem strange to me:
15:38:52
open("/opt/zimbra/dspam-3.6.2/var/dspam/data/z/i/zimbra/zimbra.blocklist",
O_RDONLY) = -1 ENOENT (No such file or directory)
15:38:52 time(NULL) = 1171287532
15:38:52 brk(0x81a0000) = 0x81a0000
15:55:17 open("/opt/zimbra/log/dspam.debug",
O_WRONLY|O_CREAT|O_APPEND, 0666) = 8
15:55:17 fstat64(8, {st_mode=S_IFREG|0664, st_size=173108, ...}) = 0
15:55:17 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7f0c000
...
15:55:17 time(NULL) = 1171288517
15:55:17 write(8, "1383: [02/12/2007 15:55:17] Resu"..., 52) = 52
15:55:17 close(8) = 0
15:55:17 munmap(0xb7f0c000, 4096) = 0
15:59:28 time(NULL) = 1171288768
15:59:28
stat64("/opt/zimbra/dspam-3.6.2/var/dspam/data/z/i/zimbra/zimbra.sig/45d072c013831859018504.sig",
0xbff07b70) = -1 ENOENT (No such file or directory)
15:59:29 open("/opt/zimbra/log/dspam.debug",
O_WRONLY|O_CREAT|O_APPEND, 0666) = 8
15:59:29 fstat64(8, {st_mode=S_IFREG|0664, st_size=176833, ...}) = 0
This seems to indicate that the message processing takes 16:25 + 4:11
= 20: 36
minutes which are just spent waiting. How much RAM is in your server?
Does it
swap heavily? Can you look at the load numbers?
The server has only 1 GB of RAM. As dspam is running it starts with very
little memory and gradually grows up to 25% at the most.
Here is a typical top output while dspam is running, about halfway
through the process:
top - 19:29:06 up 20:05, 3 users, load average: 3.92, 2.29, 1.34
Tasks: 207 total, 1 running, 206 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.2% us, 0.5% sy, 0.0% ni, 74.3% id, 25.0% wa, 0.1% hi, 0.0% si
Mem: 1032304k total, 1017456k used, 14848k free, 5324k buffers
Swap: 4096564k total, 635820k used, 3460744k free, 278584k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
27 root 10 -5 0 0 0 S 1 0.0 3:46.68 kblockd/3
28959 zimbra 18 0 405m 108m 107m D 1 10.7 0:01.26 dspam
2890 zimbra 16 0 448m 131m 3444 S 0 13.0 1:52.56 mysqld
3240 zimbra 17 0 608m 268m 6880 S 0 26.6 10:18.23 java
1 root 16 0 1992 576 552 S 0 0.1 0:01.08 init
And here is top when dspam is not running:
top - 19:34:32 up 20:11, 3 users, load average: 3.74, 3.82, 2.31
Tasks: 198 total, 2 running, 196 sleeping, 0 stopped, 0 zombie
Cpu(s): 1.2% us, 2.1% sy, 0.0% ni, 84.9% id, 11.7% wa, 0.0% hi, 0.1% si
Mem: 1032304k total, 1005716k used, 26588k free, 5208k buffers
Swap: 4096564k total, 688688k used, 3407876k free, 373524k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
24 root 10 -5 0 0 0 R 7 0.0 3:46.50 kblockd/0
31185 zimbra 16 0 57472 29m 2848 D 3 2.9 0:00.44 amavisd
28364 zimbra 16 0 59516 33m 3252 S 2 3.3 0:03.41 amavisd
3240 zimbra 17 0 608m 209m 6852 S 1 20.8 10:19.62 java
Thanks, Eric
