Sendmail slow?
Knute Johnson
knute2009 at knutejohnson.com
Sun Feb 15 01:15:50 UTC 2009
Smoot Carl-Mitchell wrote:
> You might try running strace on the listening SMTP process with timer
> option to see where the delay is creeping in. Something like
>
> sudo strace -f -p <pid> -o <output_file> -t
>
> You need the -f to pick up the forked processes as the listening
> sendmail handles the connections. The -t will give you timestamps on
> each system call.
I sent the whole output but it was too big and rejected. Anyway, this
shows a 5 second gap but I don't know what it really means. If you can
decipher it, great!
Thanks,
5092 17:05:19 stat64("/etc/resolv.conf", {st_mode=S_IFREG|0644,
st_size=91, ...}) = 0
5092 17:05:19 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 5
5092 17:05:19 connect(5, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("207.181.0.10")}, 28) = 0
5092 17:05:19 fcntl64(5, F_GETFL) = 0x2 (flags O_RDWR)
5092 17:05:19 fcntl64(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
5092 17:05:19 gettimeofday({1234659919, 562536}, NULL) = 0
5092 17:05:19 poll([{fd=5, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
5092 17:05:19 send(5,
"\331S\1\0\0\1\0\0\0\0\0\0\6knute2\faerioconnect"..., 41, MSG_NOSIGNAL) = 41
5092 17:05:19 poll([{fd=5, events=POLLIN, revents=POLLIN}], 1, 5000) = 1
5092 17:05:19 ioctl(5, FIONREAD, [57]) = 0
5092 17:05:19 recvfrom(5,
"\331S\205\200\0\1\0\1\0\0\0\0\6knute2\faerioconnect"..., 1024, 0,
{sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("207.181.0.10")}, [16]) = 57
5092 17:05:19 close(5) = 0
5092 17:05:19 getsockname(8, {sa_family=AF_INET, sin_port=htons(587),
sin_addr=inet_addr("216.240.58.140")}, [16]) = 0
5092 17:05:19 open("/etc/services", O_RDONLY|0x80000 /* O_??? */) = 5
5092 17:05:19 fstat64(5, {st_mode=S_IFREG|0644, st_size=18449, ...}) = 0
5092 17:05:19 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7ed6000
5092 17:05:19 read(5, "# Network services, Internet sty"..., 4096) = 4096
5092 17:05:19 close(5) = 0
5092 17:05:19 munmap(0xb7ed6000, 4096) = 0
5092 17:05:19 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
5092 17:05:19 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
5092 17:05:19 time(NULL) = 1234659919
5092 17:05:19 rt_sigaction(SIGALRM, {0xb7f9e170, [], SA_RESTART},
{0xb7f9e170, [], SA_RESTART}, 8) = 0
5092 17:05:19 alarm(5) = 0
5092 17:05:19 rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0
5092 17:05:19 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 5
5092 17:05:19 bind(5, {sa_family=AF_INET, sin_port=htons(0),
sin_addr=inet_addr("216.240.58.140")}, 16) = 0
5092 17:05:19 connect(5, {sa_family=AF_INET, sin_port=htons(113),
sin_addr=inet_addr("216.240.58.138")}, 16 <unfinished ...>
16288 17:05:24 <... select resumed> ) = 0 (Timeout)
16288 17:05:24 rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
16288 17:05:24 time(NULL) = 1234659924
16288 17:05:24 time(NULL) = 1234659924
16288 17:05:24 open("/proc/loadavg", O_RDONLY) = 8
16288 17:05:24 fstat64(8, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
16288 17:05:24 read(8, "0.00 0.00 0.00 2/171 5092\n", 1024) = 26
16288 17:05:24 close(8) = 0
16288 17:05:24 time(NULL) = 1234659924
16288 17:05:24 time(NULL) = 1234659924
16288 17:05:24 open("/proc/loadavg", O_RDONLY) = 8
16288 17:05:24 fstat64(8, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
16288 17:05:24 read(8, "0.00 0.00 0.00 2/171 5092\n", 1024) = 26
16288 17:05:24 close(8) = 0
16288 17:05:24 time(NULL) = 1234659924
16288 17:05:24 rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0
16288 17:05:24 select(7, [4 5 6], NULL, NULL, {5, 0} <unfinished ...>
5092 17:05:24 <... connect resumed> ) = ? ERESTARTSYS (To be restarted)
5092 17:05:24 --- SIGALRM (Alarm clock) @ 0 (0) ---
5092 17:05:24 alarm(0) = 0
5092 17:05:24 time(NULL) = 1234659924
5092 17:05:24 time(NULL) = 1234659924
5092 17:05:24 alarm(580) = 0
5092 17:05:24 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
5092 17:05:24 close(5) = 0
5092 17:05:24 getsockopt(8, SOL_IP, IP_OPTIONS, "", [0]) = 0
5092 17:05:24 time(NULL) = 1234659924
5092 17:05:24 time(NULL) = 1234659924
5092 17:05:24 open("/proc/loadavg", O_RDONLY) = 5
5092 17:05:24 fstat64(5, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
5092 17:05:24 read(5, "0.00 0.00 0.00 1/171 5092\n", 1024) = 26
5092 17:05:24 close(5) = 0
5092 17:05:24 time(NULL) = 1234659924
5092 17:05:24 stat64("/etc/mail/access.db", {st_mode=S_IFREG|0640,
st_size=12288, ...}) = 0
5092 17:05:24 lstat64("/", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
5092 17:05:24 geteuid32() = 0
5092 17:05:24 lstat64("/etc", {st_mode=S_IFDIR|0755, st_size=4096,
...}) = 0
5092 17:05:24 geteuid32() = 0
5092 17:05:24 lstat64("/etc/mail", {st_mode=S_IFDIR|S_ISGID|0755,
st_size=4096, ...}) = 0
5092 17:05:24 geteuid32() = 0
5092 17:05:24 open("/etc/mail/access.db", O_RDONLY) = 5
5092 17:05:24 fstat64(5, {st_mode=S_IFREG|0640, st_size=12288, ...}) = 0
5092 17:05:24 fcntl64(5, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET,
start=0, len=0}) = 0
5092 17:05:24 stat64("/etc/mail/access.db", {st_mode=S_IFREG|0640,
st_size=12288, ...}) = 0
5092 17:05:24 open("/etc/mail/access.db", O_RDONLY|O_LARGEFILE) = 6
5092 17:05:24 fcntl64(6, F_SETFD, FD_CLOEXEC) = 0
5092 17:05:24 read(6,
"\0\0\0\0\1\0\0\0\0\0\0\0a\25\6\0\t\0\0\0\0\20\0\0\0\10"..., 512) = 512
5092 17:05:24 open("DB_CONFIG", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No
such file or directory)
5092 17:05:24 stat64("/var/tmp", {st_mode=S_IFDIR|S_ISVTX|0777,
st_size=4096, ...}) = 0
5092 17:05:24 time(NULL) = 1234659924
5092 17:05:24 gettimeofday({1234659924, 571143}, NULL) = 0
5092 17:05:24 open("/proc/stat", O_RDONLY) = 7
5092 17:05:24 fstat64(7, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
5092 17:05:24 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7ed6000
5092 17:05:24 read(7, "cpu 40339 0 16567 57923774 2284"..., 1024) = 697
5092 17:05:24 read(7, "", 1024) = 0
5092 17:05:24 close(7) = 0
5092 17:05:24 munmap(0xb7ed6000, 4096) = 0
5092 17:05:24 mmap2(NULL, 159744, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7811000
5092 17:05:24 open("/etc/mail/access.db", O_RDONLY|O_LARGEFILE) = 7
5092 17:05:24 fcntl64(7, F_SETFD, FD_CLOEXEC) = 0
5092 17:05:24 fstat64(7, {st_mode=S_IFREG|0640, st_size=12288, ...}) = 0
5092 17:05:24 pread64(7,
"\0\0\0\0\1\0\0\0\0\0\0\0a\25\6\0\t\0\0\0\0\20\0\0\0\10"..., 4096, 0) = 4096
5092 17:05:24 close(5) = 0
5092 17:05:24 fstat64(7, {st_mode=S_IFREG|0640, st_size=12288, ...}) = 0
5092 17:05:24 fstat64(7, {st_mode=S_IFREG|0640, st_size=12288, ...}) = 0
5092 17:05:24 fcntl64(7, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET,
start=0, len=0}) = 0
5092 17:05:24 fstat64(7, {st_mode=S_IFREG|0640, st_size=12288, ...}) = 0
--
Knute Johnson
"The urge to save humanity is almost always a false front for the urge
to rule."
H.L. Mencken
More information about the ubuntu-users
mailing list