output/eve: reduce fflush call count #11059

jlucovsky · 2024-05-13T13:51:55Z

Continuation of #9832

Reduce fflush calls on output streams (regular files only).

Output can be buffered, specify the buffer-size with outputs.<type>.buffer-size. A value of 0 selects no buffering; otherwise, up to the buffer-size value can be buffered. Note that this buffering is part of the stdio library.

Since output can be buffered, a mechanism that periodically flushes the output streams has been added. The heartbeat.output-flush-interval configuration setting specifies at what interval the output should be flushed. A value of 0 means never flush.

Link to redmine ticket: 3449

Describe changes:

Add EVE configuration parameter to control buffering: buffer-size. When 0, unbuffered I/O is used; other values are used to set the stdio buffer size. The value is outputs.eve-log.buffer-size
Add Suricata configuration parameter -- heartbeat.output-flush-interval -- to set cadence for Suricata periodically directing detect threads to flush EVE output. To be used in conjunction with buffer-size. Set heartbeat.output-flush-interval to the number of seconds Suricata should periodically cause the EVE output to be flushed. The default value is 0 which instructs Suricata to never cause the EVE output to be flushed.
Add mechanism to periodically send pseudo packets to detect threads as a way to trigger flush. Controlled by heartbeat.output-flush-interval
Add "log flusher" thread when flushing is configured (heartbeat.output-flush-interval is between 1 and 60).

Updates:

Rebased and reworked commits.

Benchmarks/Measurements

Hyperfine used to measure results with my pcap collection and ET Pro

Summary: buffer-size=0, output-flush-interval=0 was the slowest. Buffer-size gave a (slight) performance boost and adding a non-zero output-flush-interval did not degrade performance

Recommendation:

8-16kb buffer-size default
30sec output-flush-interval default

Permutations for buffer-size and output-flush-interval

0, 0s
0, 30s
0, 60s
16kb, 0s,
16kb, 30s
16kb, 60s
32kb, 0s
32kb, 30s
32kb, 60s
64kb, 0s
64kb, 30s
64kb, 60s

Benchmark 1: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=0
  Time (mean ± σ):     152.402 s ±  5.605 s    [User: 710.031 s, System: 153.376 s]
  Range (min … max):   148.793 s … 158.860 s    3 runs
Benchmark 2: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=0
  Time (mean ± σ):     147.232 s ±  1.138 s    [User: 706.350 s, System: 142.157 s]
  Range (min … max):   146.257 s … 148.482 s    3 runs
Benchmark 3: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=0
  Time (mean ± σ):     146.685 s ±  0.461 s    [User: 708.963 s, System: 142.136 s]
  Range (min … max):   146.306 s … 147.198 s    3 runs
Benchmark 4: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=0
  Time (mean ± σ):     146.264 s ±  1.257 s    [User: 706.745 s, System: 141.434 s]
  Range (min … max):   145.037 s … 147.549 s    3 runs
Benchmark 5: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=30
  Time (mean ± σ):     148.819 s ±  0.806 s    [User: 709.582 s, System: 154.714 s]
  Range (min … max):   147.948 s … 149.538 s    3 runs
Benchmark 6: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=30
  Time (mean ± σ):     146.967 s ±  0.439 s    [User: 705.405 s, System: 141.915 s]
  Range (min … max):   146.467 s … 147.290 s    3 runs
Benchmark 7: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=30
  Time (mean ± σ):     146.028 s ±  0.167 s    [User: 703.954 s, System: 142.012 s]
  Range (min … max):   145.870 s … 146.202 s    3 runs
Benchmark 8: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=30
  Time (mean ± σ):     146.136 s ±  0.329 s    [User: 709.029 s, System: 141.360 s]
  Range (min … max):   145.884 s … 146.508 s    3 runs
Benchmark 9: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=60
  Time (mean ± σ):     149.616 s ±  0.542 s    [User: 710.101 s, System: 153.354 s]
  Range (min … max):   149.085 s … 150.168 s    3 runs
Benchmark 10: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=60
  Time (mean ± σ):     145.994 s ±  0.232 s    [User: 706.439 s, System: 140.116 s]
  Range (min … max):   145.831 s … 146.260 s    3 runs
Benchmark 11: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=60
  Time (mean ± σ):     146.383 s ±  2.049 s    [User: 709.735 s, System: 140.538 s]
  Range (min … max):   144.524 s … 148.580 s    3 runs
Benchmark 12: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=60
  Time (mean ± σ):     146.729 s ±  0.693 s    [User: 708.769 s, System: 140.505 s]
  Range (min … max):   145.934 s … 147.207 s    3 runs
  Time (mean ± σ):     146.729 s ±  0.693 s    [User: 708.769 s, System: 140.505 s]
  Range (min … max):   145.934 s … 147.207 s    3 runs

Summary
  './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=60' ran
    1.00 ± 0.00 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=30'
    1.00 ± 0.00 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=30'
    1.00 ± 0.01 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=0'
    1.00 ± 0.01 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=60'
    1.00 ± 0.00 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=0'
    1.01 ± 0.01 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=60'
    1.01 ± 0.00 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=30'
    1.01 ± 0.01 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=0'
    1.02 ± 0.01 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=30'
    1.02 ± 0.00 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=60'
    1.04 ± 0.04 times faster than './src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1067755 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=0'
    ```

codecov · 2024-05-13T14:09:47Z

Codecov Report

Attention: Patch coverage is 53.96825% with 145 lines in your changes are missing coverage. Please review.

Project coverage is 84.05%. Comparing base (b728916) to head (e82e49e).

Additional details and impacted files

@@            Coverage Diff             @@
##           master   #11059      +/-   ##
==========================================
- Coverage   84.08%   84.05%   -0.04%     
==========================================
  Files         925      926       +1     
  Lines      250562   250804     +242     
==========================================
+ Hits       210687   210808     +121     
- Misses      39875    39996     +121

Flag	Coverage Δ
fuzzcorpus	`64.16% <47.30%> (-0.04%)`	⬇️
livemode	`19.82% <53.96%> (+0.25%)`	⬆️
pcap	`46.42% <51.11%> (-0.02%)`	⬇️
suricata-verify	`62.76% <52.69%> (-0.03%)`	⬇️
unittests	`62.19% <39.04%> (-0.03%)`	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

suricata-qa · 2024-05-13T17:30:04Z

Information: QA ran without warnings.

Pipeline 20584

catenacyber · 2024-05-14T12:40:38Z

Are you working on getting a green CI ?

jlucovsky · 2024-05-15T12:52:16Z

Are you working on getting a green CI ?

Yes, that's why this is a draft.

suricata-qa · 2024-05-16T18:55:03Z

ERROR:

ERROR: QA failed on build_fetch.

Pipeline 20658

Issue: 3449 Add a flush function to packet logger registration and collapse the parameter count for registration functions.

This commit adds 2 EVE output buffering settings - buffer-size value which specifies the amount of buffering, if any, for regular/file output types. - flush-interval Specifies the cadence at which Suricata will direct detect threads to flush EVE output. Issue: 3449

Issue: 3449

Issue: 3449 Add flushing functions and infrastructure. This includes: - Flushing functions for packet loggers - Log file flushing support

Issue: 3449 Add a flush directive to the packet that is distinct from the existing "log flush" flag as the new flag is to distinguish between the 2 use cases.

suricata-qa · 2024-05-18T15:30:03Z

Information: QA ran without warnings.

Pipeline 20684

catenacyber

Thanks for the work :-)

CI : 🟢
Code : Checking now
Commits segmentation : looks ok, but not sure as I did not dive into the code...
Commit messages : I no longer see flush-interval in the code, only in a git message...
Git ID set : looks fine for me
CLA : you already contributed :-p
Doc update : ok
Redmine ticket : ok
Rustfmt : no rust
Tests : What is the good way to test it ? QAlab for perf improvement ?
Dependencies added: none

catenacyber · 2024-05-31T13:13:40Z

doc/userguide/partials/eve-log.yaml

+      # Specify the amount of buffering, in bytes, for
+      # this output type. The default value 0 means "no
+      # buffering".
+      #buffer-size: 0


flush-interval is missing ?

Could be nice to be squashed into the suricata.yaml.in commit

flush-interval is missing ?

output-flush-interval is in the heartbeat section.

I see it added in suricata.yaml.in but not in docs

catenacyber · 2024-05-31T13:16:02Z

src/util-logopenfile.c

+        setbuf(ret, NULL);
+        SCLogConfig("Setting output to %s non-buffered", filename);
+    } else {
+        if (setvbuf(ret, NULL, _IOFBF, buffer_size) < 0)


This is the important line, right ?

catenacyber · 2024-05-31T13:19:27Z

src/log-flush.h

+ *
+ * \author Jeff Lucovsky <jlucovsky@oisf.net>
+ */
+#ifndef __LOG_FLUSH_H__


new guard style

catenacyber · 2024-05-31T13:19:36Z

suricata.yaml.in

 # Logging configuration.  This is not about logging IDS alerts/events, but
 # output about what Suricata is doing, like startup messages, errors, etc.
 logging:
+


jlucovsky mentioned this pull request May 13, 2024

output/eve: reduce fflush call count #9832

Closed

jlucovsky force-pushed the 3449.v4/1 branch 2 times, most recently from 2a7caba to ee0c87b Compare May 16, 2024 12:30

jlucovsky added 7 commits May 18, 2024 09:04

output/log: Add flush function, collapse params

7086118

Issue: 3449 Add a flush function to packet logger registration and collapse the parameter count for registration functions.

doc/output: EVE output buffering related settings

7490af0

output: Support buffer-size value

01261e1

Issue: 3449

output/log: Add flushing infrastructure

6e13994

Issue: 3449 Add flushing functions and infrastructure. This includes: - Flushing functions for packet loggers - Log file flushing support

detect/flag: Pseudo pkt "flush log" flag

f514df8

Issue: 3449 Add a flush directive to the packet that is distinct from the existing "log flush" flag as the new flag is to distinguish between the 2 use cases.

main/flush: Support periodic flush logs

e82e49e

jlucovsky force-pushed the 3449.v4/1 branch from ee0c87b to e82e49e Compare May 18, 2024 13:09

jlucovsky marked this pull request as ready for review May 19, 2024 14:27

jlucovsky requested review from jufajardini, victorjulien and a team as code owners May 19, 2024 14:27

catenacyber reviewed May 31, 2024

View reviewed changes

src/log-flush.h

*

* \author Jeff Lucovsky <jlucovsky@oisf.net>

*/

#ifndef __LOG_FLUSH_H__

Copy link

Contributor

catenacyber May 31, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

new guard style

catenacyber reviewed May 31, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

output/eve: reduce fflush call count #11059

output/eve: reduce fflush call count #11059

jlucovsky commented May 13, 2024 •

edited

codecov bot commented May 13, 2024 •

edited

suricata-qa commented May 13, 2024

catenacyber commented May 14, 2024

jlucovsky commented May 15, 2024

suricata-qa commented May 16, 2024

suricata-qa commented May 18, 2024

catenacyber left a comment

catenacyber May 31, 2024

catenacyber May 31, 2024

jlucovsky Jun 1, 2024

catenacyber Jun 2, 2024

catenacyber May 31, 2024

catenacyber May 31, 2024

catenacyber May 31, 2024

output/eve: reduce fflush call count #11059

Are you sure you want to change the base?

output/eve: reduce fflush call count #11059

Conversation

jlucovsky commented May 13, 2024 • edited

codecov bot commented May 13, 2024 • edited

Codecov Report

suricata-qa commented May 13, 2024

catenacyber commented May 14, 2024

jlucovsky commented May 15, 2024

suricata-qa commented May 16, 2024

suricata-qa commented May 18, 2024

catenacyber left a comment

Choose a reason for hiding this comment

catenacyber May 31, 2024

Choose a reason for hiding this comment

catenacyber May 31, 2024

Choose a reason for hiding this comment

jlucovsky Jun 1, 2024

Choose a reason for hiding this comment

catenacyber Jun 2, 2024

Choose a reason for hiding this comment

catenacyber May 31, 2024

Choose a reason for hiding this comment

catenacyber May 31, 2024

Choose a reason for hiding this comment

catenacyber May 31, 2024

Choose a reason for hiding this comment

jlucovsky commented May 13, 2024 •

edited

codecov bot commented May 13, 2024 •

edited