grok_exporter v 0.2.6 resident memory rising

[raokrutarth]

I have a fairly frequently updated log file that I am using grok exporter to count specific log entries. I see that the resident memory usage by the exporter is quite high and growing. This happens 3/4 of the time in my env.

Graph:

The config is:

global:
  config_version: 2
grok:
  additional_patterns:
  - BASE10NUM (?<![0-9.+-])(?>[+-]?(?:(?:[0-9]+(?:\.[0-9]+)?)|(?:\.[0-9]+)))
  - DATA .*?
  - NUMBER (?:%{BASE10NUM})
  - DAEMON [a-zA-Z_\-]+
  - NAELOGLEVEL LOG_[\S+]
  - MESSAGE [\S\s\S]?*
  - YEAR (?>\d\d){1,2}
  - HOUR (?:2[0123]|[01]?[0-9])
  - MINUTE (?:[0-5][0-9])
  - SECOND (?:(?:[0-5]?[0-9]|60)(?:[:.,][0-9]+)?)
  - TIME (?!<[0-9])%{HOUR}:%{MINUTE}(?::%{SECOND})(?![0-9])
  - MONTHNUM (?:0?[1-9]|1[0-2])
  - MONTHDAY (?:(?:0[1-9])|(?:[12][0-9])|(?:3[01])|[1-9])
  - ISO8601_TIMEZONE (?:Z|[+-]%{HOUR}(?::?%{MINUTE}))
  - TIMESTAMP_ISO8601 %{YEAR}-%{MONTHNUM}-%{MONTHDAY}[T ]%{HOUR}:?%{MINUTE}(?::?%{SECOND})?%{ISO8601_TIMEZONE}?
  - LEVEL (LOG_)?([Aa]lert|ALERT|[Tt]race|TRACE|[Dd]ebug|DEBUG|DBG|[Nn]otice|NOTICE|[Ii]nfo|INFO|[Ww]arn?(?:ing)?|WARN?(?:ING)?|[Ee]rr|ERR?(?:OR)?|[Cc](rit)+(?:ical)?|CRIT?(?:ICAL)?|[Ff]atal|FATAL|[Ss]evere|SEVERE|EMERG(?:ENCY)?|[Ee]merg(?:ency)?)
input:
  path: /var/log/messages
  poll_interval_seconds: 5
  type: file
metrics:
- help: all log entries seperated by daemon
  labels:
    daemon: '{{.daemon}}'
  match: '%{TIMESTAMP_ISO8601:time} %{DAEMON:daemon}.*%{LEVEL:level}.*'
  name: benchmark_all_daemon_log_entry_counts
  type: counter
- help: count of panic entries in the log by go daemons
  labels:
    daemon: '{{.daemon}}'
  match: '%{TIMESTAMP_ISO8601:time} %{DAEMON:daemon}.*panic.*'
  name: benchmark_go_daemon_log_panic_counts
  type: counter

[other confidential counters]

[fstab]

This is a bug. Will investigate where this comes from. Thanks for reporting.

[fstab]

Found a memory leak in gsub. Pushed a fix and will make a bugfix release soon. Thanks for reporting!
Are you actually using gsub (in your [other confidential counters] config) or is there another memory leak I am not aware of?

[raokrutarth]

I'm using summary and gauge metrics. Do those call gsub in any way?

[fstab]

I released a bugfix release 0.2.7. Could you check if this solves the issue?

[raokrutarth]

I used the 0.2.7 release binary in my env but I am still seeing the leak. Currently, a bash script restarts the exporter every 1.5 hrs.

[fstab]

There's a buffer in grok_exporter where new log lines are cached before they are processed by the matchers. The load of this buffer can be monitored with the grok_exporter_line_buffer_peak_load metric. Could you monitor this metric and check if this is constantly growing? This would help me figure out where the memory leak happens.

[raokrutarth]

[raokrutarth]

I also noticed a different trend over a longer run (~2.5 days), the peaks are not as large later on.

[fstab]

Thanks for the data. If I see the colors correctly the grok_exporter_line_buffer_peak_load is constantly increasing. That means log lines are written faster than grok_exporter processes them. The buffer with unprocessed log lines keeps growing, and grok_exporter eventually runs out of memory.

One thing you could do is to figure out why processing takes so long. Sometimes there is a single regular expression taking most of the processing time. The metric grok_exporter_lines_processing_time_microseconds_total gives you the total processing time in microseconds per metric. With a Prometheus query like rate(grok_exporter_lines_processing_time_microseconds_total[5m]) you can evaluate that in the time window of the last 5 minutes.

Could you run that query to see if there is any metric that takes significantly longer than the others? Maybe we can optimize the regular expression for that metric to make processing faster.

[raokrutarth]

I can take out all_daemon_log_entry_counts but benchmark_ovsdb_logs are needed.

The metric is
- help: ovsdb-server log entries labels: level: '{{.level}}' match: '%{TIMESTAMP_ISO8601:time} ovsdb-server(\[%{NUMBER}\])?: .*%{LEVEL:level}' name: benchmark_ovsdb_logs type: counter

The frequency of this log is quite high, any chance this can be optimized?

[fstab]

It doesn't look too bad. Some things you can try:

• as far as I can see you only use level as a label, so you could replace %{TIMESTAMP_ISO8601:time} with %{TIMESTAMP_ISO8601} or even leave it out entirely.
• (\[%{NUMBER}\])?: is optional and you don't use it, so you could remove it
• It might be faster to replace .* with .*? depending on if the level is more at the end of the line or the beginning of the line.

[raokrutarth]

An optional flag like --max-rss=1G for the exporter could help. Once the cap is reached, it drops older items for new ones. Just a suggestion.

[fstab]

I didn't add a buffer limit so far because dropping log lines makes grok_exporter unreliable, you might miss fatal log messages.

On the other hand, if you have to restart grok_exporter you also might miss messages. So an optional flag is probably the lesser evil. I will look into it.

Meanwhile I added a log message, so if log messages are written faster than they are processed grok_exporter will print a warning to the console.