output/eve: reduce fflush call count

[jlucovsky]

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[bot]]

Codecov Report

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

Project coverage is 84.05%. Comparing base (b728916) to head (e82e49e). Report is 480 commits behind head on master.

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%)	:arrow_down:
livemode	19.82% <53.96%> (+0.25%)	:arrow_up:
pcap	46.42% <51.11%> (-0.02%)	:arrow_down:
suricata-verify	62.76% <52.69%> (-0.03%)	:arrow_down:
unittests	62.19% <39.04%> (-0.03%)	:arrow_down:

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

[suricata-qa]

Information: QA ran without warnings.

Pipeline 20584

[catenacyber]

Are you working on getting a green CI ?

[jlucovsky]

Are you working on getting a green CI ?

Yes, that's why this is a draft.

[suricata-qa]

ERROR:

ERROR: QA failed on build_fetch.

Pipeline 20658

[suricata-qa]

Information: QA ran without warnings.

Pipeline 20684

[jlucovsky]

Continued in #11882