On Fri, Sep 26, 2014 at 10:34:56AM -0700, Will Yardley wrote:
> On Fri, Sep 26, 2014 at 12:50:47PM +0000, Viktor Dukhovni wrote:
> >
> > Can you provide a bit more context from that trace. Replace the "..." with
> > 20 or so more lines above the "flock(21, LOCK_UN)"
>
> Yes, sorry for the delay; had to re-run it. Does this provide enough
> context (from MAIL FROM):
>
> 10:31:53.450736 write(13,
> "request\0resolve\0sender\0\0address\0recipi...@example.com\0\0", 53) = 53
> <0.000078>
> 10:31:53.450858 poll([{fd=13, events=POLLIN}], 1, 3600000) = 1 ([{fd=13,
> revents=POLLIN}]) <0.002264>
> 10:31:53.453159 read(13,
> "flags\0000\0transport\0local\0nexthop\0hostname.example.com\0recipient\0recipi...@example.com\0flags\000256\0\0",
> 4096) = 92 <0.000025>
Request and reply to trivial-rewrite(3) "resolve" service.
> 10:31:53.453244 flock(21, LOCK_SH) = 0 <0.000010>
> 10:31:53.453288 flock(21, LOCK_UN) = 0 <0.000010>
> 10:31:53.453319 flock(21, LOCK_SH) = 0 <0.000009>
> 10:31:53.453352 flock(21, LOCK_UN) = 0 <0.000009>
> 10:31:53.453381 flock(21, LOCK_SH) = 0 <0.000009>
> 10:31:53.453413 flock(21, LOCK_UN) = 0 <0.000022>
> 10:31:53.453455 flock(21, LOCK_SH) = 0 <0.000008>
> 10:31:53.453485 flock(21, LOCK_UN) = 0 <0.000008>
> 10:31:53.453525 flock(21, LOCK_SH) = 0 <0.000008>
> 10:31:53.453554 flock(21, LOCK_UN) = 0 <0.000008>
> 10:31:53.453580 flock(21, LOCK_SH) = 0 <0.000009>
> 10:31:53.453609 flock(21, LOCK_UN) = 0 <0.000008>
> 10:31:53.453635 flock(21, LOCK_SH) = 0 <0.000008>
> 10:31:53.453664 flock(21, LOCK_UN) = 0 <0.000008>
7 Berkeley DB lookups.
> 10:31:53.453735 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000009>
> 10:31:53.453774 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
> <0.000011>
> 10:31:53.453813 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000008>
> 10:31:53.453841 nanosleep({1, 0}, 0x7fffa29253c0) = 0 <1.000073>
1 second sleep.
> 10:31:54.453978 flock(23, LOCK_SH) = 0 <0.000011>
> 10:31:54.454030 flock(23, LOCK_UN) = 0 <0.000010>
> 10:31:54.454062 flock(23, LOCK_SH) = 0 <0.000009>
> 10:31:54.454096 flock(23, LOCK_UN) = 0 <0.000009>
> 10:31:54.454139 flock(23, LOCK_SH) = 0 <0.000008>
> 10:31:54.454171 flock(23, LOCK_UN) = 0 <0.000021>
> 10:31:54.454213 flock(23, LOCK_SH) = 0 <0.000009>
> 10:31:54.454260 flock(23, LOCK_UN) = 0 <0.000009>
> 10:31:54.454304 flock(27, LOCK_SH) = 0 <0.000010>
More Berkeley DB lookups. Please post "postconf -n" output, it is
difficult to determine where this sleep happens without more precise
configuration information.
--
Viktor.
