[Filebeat] Reduce memory usage of multiline

[adriansr]

The use of time.After when multiline is enabled and lines don't match the multiline pattern increases the memory usage (from 30MB to 1GB).

This extra memory is attributed to unexpired timers allocated internally by the Go runtime when time.After(duration) is used. According to the docs: "If efficiency is a concern, use NewTimer instead and call Timer.Stop if the timer is no longer needed.".

It's not clear to me why this problem only appears when many lines on the input file don't match the pattern.

Reproduced with this config:

multiline.pattern: '^\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}\.d{3}'
multiline.negate: true
multiline.match: after
multiline.max_lines: 50
max_bytes: 1048576

and a random input file generated by:

cat <<EOF > genrandom.py
import base64
import os
import sys

LINE_SIZE = 160
RAW_SIZE = int(LINE_SIZE * 3 / 4)

if len(sys.argv) != 2:
    print 'Usage:', sys.argv[0], '<SIZE IN MEGABYTES>'
    sys.exit(1)

limit = int(sys.argv[1]) * 1024 * 1024
size = 0
f = open('/dev/urandom', 'rb')

while size < limit:
    os.write(2, '> written {0:.2f} MiB\r'.format(size / (1024.0 * 1024.0)))
    raw = f.read(RAW_SIZE * 100)
    while len(raw) >= RAW_SIZE:
        part, raw = raw[:RAW_SIZE], raw[RAW_SIZE:]
        line = base64.b64encode(part)
        print line
        size += len(line)
os.write(2, 'Done.\n')
EOF
python genrandom.py 1024 > 1gb.log

[adriansr]

Here's how the heap looks before this PR:

[faec]

Good catch! It looks to me like multiline might still have some issues, Next's handling of r.running looks suspicious, but this is a good step :-)

[faec]

This extra select looks redundant, is it still needed to free memory after timer.Stop? If so please explain in a comment

[adriansr]

You're right. Draining the channel is unnecessary unless the timer is going to be reused.

I took the opportunity to rewrite a little bit so that a single channel is used instead of allocating a new one every time.

[faec]

Unless we're seeing noticeable memory / cpu overhead from it, I actually like the ephemeral version better (allocate a timer each time). Reusing timers is a lot more subtle -- because Reset can only be called on a timer that has stopped or expired, and <-timer.C can deadlock if it's called in the wrong state... it looks to me like you've handled all the cases correctly here, but it takes considerable thought to make sure.

If this is a significant performance fix over the previous version, then this looks ok, but please comment on these issues (e.g. pointing out that timer.Reset is safe because in every code path the timer is Stopped or expired before this function returns, and that <-r.timer.C can't deadlock because Stop can only be called once per Reset and thus a false return value means there is an expiration signal waiting...)

If this doesn't affect performance much, though, I'd rather just create and deallocate the value every time, to save the next person who reads this function the cognitive load of thinking about state invariants :-)

[faec]

Thank you for fixing comments!

[urso]

Great find. We should not use time.After in general, but always use a timer as shown here. Even if it is a little less convenient.