mozilla-services/heka — pull request #1215 by dcarley (2014-12-06 22:54:32+00:00)
Title: Fix logstreamer journal saving loop

`LogstreamerInput` keeps repeatably writing the same journal entry to disk
when it reaches the end of a log file. This puts a lot of strain on the disk
where the journal files are located, eg. 100 monitored log files results in
400 IOPS (write).

Fix this by removing the extraneous `SavePosition()` call (and reset of
`recordCount`) in `LogstreamInput` when it runs out of input. This should be
safe to do because `countRecord` will still save when we reach the threshold
of 500 records and the underlying `Logstream` already calls `Save()`
whenever it hits EOF.

The issue can be demonstrated with the following config:

[test_input]
type = "LogstreamerInput"
parser_type = "token"
log_directory = "/var/log/heka_test"
file_match = '(?P.+)\.log'
differentiator = ["test_input.", "Name"]
priority = ["^Index"]

Writing a single line to a matching file and monitoring writes using `sysdig`
shows a journal entry with the same `seek` and `last_hash` values being written
every 0.25 seconds:

root@graphite-1:~# echo hello world > /var/log/heka_test/1.log
root@graphite-1:~# sysdig -c spy_file "fd.directory=/var/cache/hekad/logstreamer/"
22:26:47.955585858 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:48.206101677 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:48.456563080 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:48.706010894 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:48.956700377 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:49.206755665 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}

---

Example of 100 log files:

root@logging-1:~# date; service heka start
Sat Dec 6 21:56:20 UTC 2014
heka start/running, process 3259

root@logging-1:~# date; for i in $(seq 1 100); do echo hello world > /var/log/heka_test/${i}.log; done
Sat Dec 6 21:57:12 UTC 2014

Corresponding graph of IOPS:

![heka_logstreamer_iops-20141206](https://cloud.githubusercontent.com/assets/260438/5329219/c3e1d716-7d9a-11e4-9249-b8b79c37100e.png)