# Big gaps in recorded logs **URL:** \ **Category:** Logstash\ **Created:** [August 12, 2015, 2:29pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266 "2015-08-12T14:29:08Z")\ **Posts on this page:** 9\ **Page:** 1
**Author:** ![bschopman](https://avatars.discourse-cdn.com/v4/letter/b/df788c/32.png) [@bschopman](https://discuss.elastic.co/u/bschopman)\ **Post date:** [August 12, 2015, 2:29pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/1 "2015-08-12T14:29:08Z")
We're running Logstash on a single server to compare its performance to Heka and decide if we want to use one or the other. We have some high-traffic web servers of which the log lines are sent to a Kafka cluster consisting of 3 nodes. Running Heka all log message come in without a problem, but with Logstash we see enormous gaps of recorded log messages. As in: gaps of more than 10 minutes. To minimize the load on the web server, it basically does no parsing. The only thing Logstash adds to the log line is the host name and delimiter char. The Logstash configuration: ```auto input { file { path => "/var/log/nginx/access.log" start_position => "beginning" # if we haven't seen the file before } } output { kafka { broker_list => "kafka1:9092,kafka2:9092,kafka3:9092" topic_id => "log_stats" request_required_acks => 1 codec => plain { format => '%{host}¦%{message}' } producer_type => async } } ``` The only overridden default setting is the heap size: ```auto LS_HEAP_SIZE="1500m" ``` Resulting in the following running process: ```auto $ ps aux | grep logstash logstash 41920 9.6 0.5 4385308 669724 pts/3 SNl 13:01 4:08 /usr/bin/java -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Djava.awt.headless=true -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -Djava.io.tmpdir=/var/lib/logstash -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintClassHistogram -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -Xloggc:./logstash-gc.log -Xmx1500m -Xss2048k -Djffi.boot.library.path=/opt/logstash/vendor/jruby/lib/jni -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Djava.awt.headless=true -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -Djava.io.tmpdir=/var/lib/logstash -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintClassHistogram -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -Xloggc:./logstash-gc.log -Xbootclasspath/a:/opt/logstash/vendor/jruby/lib/jruby.jar -classpath : -Djruby.home=/opt/logstash/vendor/jruby -Djruby.lib=/opt/logstash/vendor/jruby/lib -Djruby.script=jruby -Djruby.shell=/bin/sh org.jruby.Main --1.9 /opt/logstash/lib/bootstrap/environment.rb logstash/runner.rb agent -f /etc/logstash/conf.d -l /var/log/logstash/logstash.log --verbose ``` We're running Oracle java 1.7.0\_80. So far we haven't seen any error whatsoever in `/var/log/logstash/*`. Even with the log level decreased to `info` we don't see any alarming messages. The amount of log lines added to the monitored files is 6M per hour = 100k per minute. The server in question has 20 cores and 128GB ram. The load is quite low. The active logstash thread uses about 5-13% of a single cpu core and 0.5% of the ram memory. Is there something in this setup that's completely off, causing these long periods of inactivity? We've manually checked the access logs to see that there is activity during the gaps. ---
**Author:** ![warkolm](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/warkolm/32/39224_2.png) [@warkolm](https://discuss.elastic.co/u/warkolm)\ **Post date:** [August 12, 2015, 11:56pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/2 "2015-08-12T23:56:37Z")
I'd suggest looking at the [heartbeat](https://www.elastic.co/guide/en/logstash/current/plugins-inputs-heartbeat.html) plugin to see if you can determine if LS is pausing or if it might be something else. You can also try running in `--verbose` and/or `--debug` modes, but that'll get pretty noisy. ---
**Author:** ![Joe\_Lawson](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/joe_lawson/32/3390_2.png) [@Joe\_Lawson](https://discuss.elastic.co/u/Joe_Lawson)\ **Post date:** [August 14, 2015, 6:12pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/3 "2015-08-14T18:12:33Z")
Are you seeing the gap in Elasticsearch? How many partitions are on the topic and how many consumer threads are there? If you have a mismatch of threads to partitions then what you can see is some partitions aren't serviced immediately because the others are full of data as well so a single consumer thread doesn't hit the others until it does a rebalance. You can see if you are getting partition starvation by checking the consumer offsets on those partitions for a particular consumer group by using a tool in the Kafka binary: `bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker`. I suspect this is similar to [https://github.com/logstash-plugins/logstash-input-kafka/issues/32](https://github.com/logstash-plugins/logstash-input-kafka/issues/32) Check out that thread for more detailed discussion of the issue. ---
**Author:** ![bschopman](https://avatars.discourse-cdn.com/v4/letter/b/df788c/32.png) [@bschopman](https://discuss.elastic.co/u/bschopman)\ **Post date:** [August 18, 2015, 12:16pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/4 "2015-08-18T12:16:41Z")
Thanks for the replies. Here's what the ConsumerOffsetChecker gives: ```auto schopman@kafka02001:/opt/kafka$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zookeeper zk:2181 --topic stats --group stats_group Group Topic Pid Offset logSize Lag Owner stats_group stats 0 19762754697 19762762247 7550 stats_group_spark02001.domain.com-1439827006595-f1bc4064-0 stats_group stats 1 19870546253 19870554978 8725 stats_group_spark02001.domain.com-1439827006595-f1bc4064-0 stats_group stats 2 19960084344 19960093310 8966 stats_group_spark02001.domain.com-1439827006595-f1bc4064-0 stats_group stats 3 19943964765 19943972606 7841 stats_group_spark02001.domain.com-1439827006595-f1bc4064-1 stats_group stats 4 19864658095 19864667346 9251 stats_group_spark02001.domain.com-1439827006595-f1bc4064-1 stats_group stats 5 19960056579 19960065712 9133 stats_group_spark02001.domain.com-1439827006595-f1bc4064-1 stats_group stats 6 19759376148 19759384078 7930 stats_group_spark02001.domain.com-1439827006595-f1bc4064-2 stats_group stats 7 19873547885 19873557164 9279 stats_group_spark02001.domain.com-1439827006595-f1bc4064-2 stats_group stats 8 19963853577 19963862948 9371 stats_group_spark02001.domain.com-1439827006595-f1bc4064-2 stats_group stats 9 19939534399 19939539183 4784 stats_group_spark02002.domain.com-1439827008412-68947d80-0 stats_group stats 10 19868892614 19868899862 7248 stats_group_spark02002.domain.com-1439827008412-68947d80-0 stats_group stats 11 19954080890 19954086385 5495 stats_group_spark02002.domain.com-1439827008412-68947d80-1 stats_group stats 12 19766966638 19766971724 5086 stats_group_spark02002.domain.com-1439827008412-68947d80-1 stats_group stats 13 19870931440 19870938649 7209 stats_group_spark02002.domain.com-1439827008412-68947d80-2 stats_group stats 14 19961013687 19961019275 5588 stats_group_spark02002.domain.com-1439827008412-68947d80-2 stats_group stats 15 19941549743 19941554704 4961 stats_group_spark02002.domain.com-1439827008412-f83c964a-0 stats_group stats 16 19871918725 19871925927 7202 stats_group_spark02002.domain.com-1439827008412-f83c964a-0 stats_group stats 17 23288972312 23288978001 5689 stats_group_spark02002.domain.com-1439827008412-f83c964a-1 stats_group stats 18 19764435777 19764440766 4989 stats_group_spark02002.domain.com-1439827008412-f83c964a-1 stats_group stats 19 19866098656 19866105890 7234 stats_group_spark02002.domain.com-1439827008412-f83c964a-2 stats_group stats 20 19960739425 19960745355 5930 stats_group_spark02002.domain.com-1439827008412-f83c964a-2 schopman@kafka02001:/opt/kafka$ ``` I'm actively doing investigations on this topic, but does this output look healthy to you? (I don't see any issues.) ---
**Author:** ![bschopman](https://avatars.discourse-cdn.com/v4/letter/b/df788c/32.png) [@bschopman](https://discuss.elastic.co/u/bschopman)\ **Post date:** [August 18, 2015, 12:33pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/5 "2015-08-18T12:33:40Z")
To investigate I've let Logstash write to stdout for a bit. What I see is quite alarming. Here's a line that I see: ```auto 2015-08-18T11:33:26.108Z server.domain.com 1439895678.299¦200¦http://www.dom.com/sub/¦Mozilla/5.0 agent¦0.000¦... ``` At the start is the time of when Logstash creates the message. The nginx log line follows after the domain, which starts with the timestamp in ms (1439895678.299). This timestamp translates to Tue Aug 18 11:01:18 UTC 2015 That is a half hour difference between the line logged by nginx and the corresponding message created by Logstash! The gaps we see are always at the end of the hour, eg between 11:45 and 12:00. Considering we have an hourly log rotation, it's clear that the gaps are caused by log rotation combined with Logstash lagging behind. I'm puzzled with this behavior, because the logstash process doesn't seem busy: it doesn't use much cpu (as written above, 5-13% of a single core) and it doesn't use the full heap size that it got assigned. Any ideas of what may cause this delay? ---
**Author:** ![Joe\_Lawson](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/joe_lawson/32/3390_2.png) [@Joe\_Lawson](https://discuss.elastic.co/u/Joe_Lawson)\ **Post date:** [August 18, 2015, 2:02pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/6 "2015-08-18T14:02:28Z")
I wonder if you are getting bit by nginx not really supporting logrotation. Most articles suggest a kill -USR1 in the script: [https://www.loggly.com/docs/log-rotate/](https://www.loggly.com/docs/log-rotate/) and [https://www.digitalocean.com/community/tutorials/how-to-configure-logging-and-log-rotation-in-nginx-on-an-ubuntu-vps](https://www.digitalocean.com/community/tutorials/how-to-configure-logging-and-log-rotation-in-nginx-on-an-ubuntu-vps) Side comments ... Looking at your offset, the lag is what you are interested in. IMO 1000's are a little high to be in but if it kinda hangs around that then you are okay. Guessing from your Owner row it appears that you have two or three logstash instances that supply read from Kafka and submit the logs to Elasticsearch all with three threads. What type of boxes are those, specifically how many cores? You should try to make sure your threads match the number of cores for best performance, otherwise the threads will just fight each other to process when a single thread can still handle all the partitions. Other thought, get those nginx logs into a json format so there is almost zero processing that has to happen for logstash and you get those timestamps synced up. Check out this post for some guidance: [https://blog.pkhamre.com/logging-to-logstash-json-format-in-nginx/](https://blog.pkhamre.com/logging-to-logstash-json-format-in-nginx/) ---
**Author:** ![Joe\_Lawson](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/joe_lawson/32/3390_2.png) [@Joe\_Lawson](https://discuss.elastic.co/u/Joe_Lawson)\ **Post date:** [August 25, 2015, 2:18pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/7 "2015-08-25T14:18:19Z")
@bschopman did you ever figure this out? ---
**Author:** ![bschopman](https://avatars.discourse-cdn.com/v4/letter/b/df788c/32.png) [@bschopman](https://discuss.elastic.co/u/bschopman)\ **Post date:** [August 25, 2015, 3:27pm UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/8 "2015-08-25T15:27:19Z")
Yes, it's quite simple. The data isn't processed fast enough and it lags behind. Then, when the log rotation happens the data is cut off. So all log lines that haven't been read are lost and we see a gap in the graphs. ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [July 6, 2017, 5:30am UTC](https://discuss.elastic.co/t/big-gaps-in-recorded-logs/27266/9 "2017-07-06T05:30:57Z")