Sure. Here's the Ruby:

dns_open: 8 ms | dns_close: 0 ms
dns_open: 9 ms | dns_close: 0 ms
dns_open: 10 ms | dns_close: 0 ms
dns_open: 3013 ms | dns_close: 0 ms
dns_open: 5015 ms | dns_close: 0 ms
dns_open: 5011 ms | dns_close: 0 ms
dns_open: 5014 ms | dns_close: 0 ms
dns_open: 5015 ms | dns_close: 0 ms
dns_open: 5012 ms | dns_close: 0 ms
dns_open: 5015 ms | dns_close: 0 ms

https://gist.github.com/cholick/f8bab2d9752728671b94

And the Go:
dns_open: 16ms | dns_close: 0ms
dns_open: 11ms | dns_close: 0ms
dns_open: 19ms | dns_close: 0ms
dns_open: 12ms | dns_close: 0ms
dns_open: 16ms | dns_close: 0ms
dns_open: 3016ms | dns_close: 0ms
dns_open: 15ms | dns_close: 0ms
dns_open: 5033ms | dns_close: 0ms
dns_open: 11ms | dns_close: 0ms
dns_open: 5018ms | dns_close: 0ms
dns_open: 5017ms | dns_close: 0ms
dns_open: 12ms | dns_close: 0ms
dns_open: 5017ms | dns_close: 0ms
dns_open: 13ms | dns_close: 0ms
dns_open: 5015ms | dns_close: 0ms

https://gist.github.com/cholick/7d4e01dcf99588d13016


On Wed, Nov 18, 2015 at 10:10 PM, Amit Gupta <agupta(a)pivotal.io> wrote:

Thanks Matt, that's super interesting. It would be awesome to get the
strace from the Ruby thing, as well another strace from the Go thing but
this time starting from before it goes slow. I think there's some sort of
weird thing that happens once, and then after that happens, the fact that
Consul (or any other always-SERVFAIL server, e.g. Dmitriy's little Ruby DNS
server) is present makes all subsequent requests slow. So I'd like to see
strace from both the Ruby and the Go, with enough before and after the
slowness starts to establish the same pattern of behaviour.

The alternating slow/fast stuff with Go is interesting. Not clue yet
what that could be, maybe multiple goroutines?

On Wed, Nov 18, 2015 at 4:13 PM, Matt Cholick <cholick(a)gmail.com> wrote:

So things got a little more interesting yesterday. We have some custom
Golang jobs for auditing and some other purposes. A recent change added the
consult_agent template to the box with these jobs and I saw similar
behavior: requests with dns resolution taking +5s consistently, fixable by
restarting the process. I wrote a small Golang app to try and reproduce it.
I got similar, but not identical behavior in the test app.

package main


import (
"net"
"fmt"
"time"
)

func main() {
for {
startOpen := time.Now()
conn, err := net.Dial("tcp", "api.useast.appfog.qa.ctl.io:http")
if err != nil {
fmt.Printf("%#v", err)
} else {
endOpen := time.Now()
conn.Close()
endClose := time.Now()
openDur := endOpen.Sub(startOpen) / 1e6
closeDur := endClose.Sub(endOpen) / 1e6

fmt.Printf("dns_open: %dms | dns_close: %dms\n", openDur, closeDur)
}
}
}

After some time, I saw:
dns_open: 14ms | dns_close: 0ms
dns_open: 5019ms | dns_close: 1ms
dns_open: 25ms | dns_close: 1ms
dns_open: 27ms | dns_close: 1ms
dns_open: 20ms | dns_close: 0ms
dns_open: 5015ms | dns_close: 0ms
dns_open: 14ms | dns_close: 0ms
dns_open: 5018ms | dns_close: 1ms
dns_open: 15ms | dns_close: 0ms
dns_open: 5018ms | dns_close: 1ms
dns_open: 19ms | dns_close: 0ms
dns_open: 5046ms | dns_close: 0ms

To reiterate, the behavior in the actual app seemed to be every single
request. The test app went into a similar mode where a roughly every other
request failed. Here's the strace for that section:

https://gist.github.com/cholick/428df93c112067f50558

On some other runs it was quite consistently alternating slow and fast
calls (for ~300 calls in a row alternating slow/fast). Just like the Ruby,
once things get into an unhappy state they stay that way until restarting
the process. (The process ran for 12 hours and never recovered).

I can capture a Ruby strace too if you'd like, but I figured this was
more useful as it added more novel information to the mix.

These Golang jobs have run in production for months without showing this
behavior and, within a few hours of including the consul template, the
issue manifested.