nsqd: message stalling with Snappy enabled

[amattn]

Hi,

Root problem:

Most of the messages that go through our system do so rapidly (tens or hundreds of milliseconds) but some messages stall for multiple seconds. The length of the stall is tied to the nsqd client heartbeat.

The stalled messages don't really stand out (roughly 6k of json). We send other large messages that don't seem to stall.

My own investigation so far suggests that this area of the code in protocol_v2.go is related:

func (p *protocolV2) Send(client *clientV2, frameType int32, data []byte) error {
    client.Lock()

    var zeroTime time.Time
    if client.HeartbeatInterval > 0 {
        client.SetWriteDeadline(time.Now().Add(client.HeartbeatInterval))
    } else {
        client.SetWriteDeadline(zeroTime)
    }

    _, err := util.SendFramedResponse(client.Writer, frameType, data)
    if err != nil {
        client.Unlock()
        return err
    }

    if frameType != frameTypeMessage {
        err = client.Flush()
    }

    client.Unlock()

    return err
}

Specifically, I believe that certain messages aren't being flushed properly. The heartbeat hits the client and then that flushes the stalled messages through.

Have you seen this behavior before?
Is there any reason that a message might get stuck in util.SendFramedResponse?
Is there a reason we don't explicitly flush frameTypeMessage?

[mreiferson]

hey @amattn

Can you paste the code you're using to configure the Consumer? There are a bunch of settings related to buffering and flushing...

[amattn]

Thanks! Here's our settings:
(we don't use magic numbers, but you get the idea)

config.HeartbeatInterval was higher, but we dropped it down to 3 seconds as a temporary workaround for force flushing.

config := nsq.NewConfig()
config.UserAgent = fmt.Sprintf("%s build %d", Version(), BuildNumber())
config.LookupdPollInterval = 11 * time.Second
config.Snappy = true
config.HeartbeatInterval = 3 * time.Second
config.MaxInFlight = 200

nsq_consumer, err := nsq.NewConsumer(topic, channel, config)
if err != nil {

}

// set handler
nsq_consumer.AddConcurrentHandlers(nr, 20)

[mreiferson]

Here are the two settings that affect buffering: https://github.com/bitly/go-nsq/blob/master/config.go#L92-L99

You shouldn't (ever) see a delay that's longer than OutputBufferTimeout.

HeartbeatInterval is a red herring, you can return HeartbeatInterval to its default after we figure this out...

[mreiferson]

It's possible this has something to do with Snappy = true, which is technically another layer of buffering.

Can you try disabling Snappy and see if the problem persists?

[amattn]

config.Snappy = false

Fixed!

Is this a snappy bug? For now we'll disable snappy and possibly try out deflate.

Any other recommendations?

[mreiferson]

I don't think it's a Snappy bug per-se, but most likely our use of snappy 🔥

[mreiferson]

(updated title)

[mreiferson]

@amattn is there some easy test case/code/app I can use to debug this? I'm having trouble reproducing 😞

[amattn]

I’ll see if I can reproduce in a test system…

[itsimba]

I also meet this problems
when consumer's snappy is true, I test for msgSize > 4096, it's stalled

https://github.com/nsqio/go-nsq/blob/master/protocol.go line 61

_, err = io.ReadFull(r, buf)

this code can not read full message, it's waiting for reading.
I test it, but I didn't know why.

---

also that, I replace nsqd's and consumer's snappy with google's snappy, it ok
https://github.com/golang/snappy

---

Just replacing the consumer's snappy code is correct too.

[mreiferson]

@lauyoume thanks for the tip! I've opened #830 to handle this. I think it's good to defer to official "golang" packages when possible anyway!