output/eve: reduce fflush call count

[jlucovsky]

Continuation of #11882

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 never to cause the EVE output to be flushed.
• Add a mechanism to periodically send pseudo packets to detect threads to trigger a flush. Controlled by heartbeat.output-flush-interval
• Add "log flusher" thread when flushing is configured (heartbeat.output-flush-interval is between 1 and 60 in seconds).

Updates:

• Formatting fixup
• CI issue with DEBUG builds resolved

Benchmarks/Measurements

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

Summary: Log buffering and a moderate flush interval give the best results (16kb buffer, 30-second flush interval).

Recommendation:

• eve-log.buffer-size: TBD
• heartbeat.output-flush-interval TBD

Permutations benchmarked for buffer-size and output-flush-interval

• 0, 0s
• 0, 15s
• 0, 30s
• 0, 60s
• 8kb, 0s,
• 8kb, 15s
• 8kb, 30s
• 8kb, 60s
• 16kb, 0s,
• 16kb, 15s
• 16kb, 30s
• 16kb, 60s
• 32kb, 0s
• 32kb, 15s
• 32kb, 30s
• 32kb, 60s
• 64kb, 0s
• 64kb, 15s
• 64kb, 30s
• 64kb, 60s

Hyperfine output

Benchmark 1: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=0 -v
  Time (mean ± σ):     206.605 s ± 41.550 s    [User: 853.860 s, System: 55.990 s]
  Range (min … max):   158.766 s … 233.678 s    3 runs
 
Benchmark 2: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=0 -v
  Time (mean ± σ):     222.465 s ±  5.450 s    [User: 868.992 s, System: 49.658 s]
  Range (min … max):   216.276 s … 226.548 s    3 runs
 
Benchmark 3: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=0 -v
  Time (mean ± σ):     226.617 s ±  9.892 s    [User: 871.200 s, System: 50.199 s]
  Range (min … max):   216.465 s … 236.226 s    3 runs
 
Benchmark 4: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=0 -v
  Time (mean ± σ):     177.002 s ± 61.784 s    [User: 817.633 s, System: 49.582 s]
  Range (min … max):   106.964 s … 223.783 s    3 runs
 
Benchmark 5: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=0 -v
  Time (mean ± σ):     225.018 s ±  9.724 s    [User: 868.404 s, System: 50.875 s]
  Range (min … max):   214.537 s … 233.747 s    3 runs
 
Benchmark 6: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=15 -v
  Time (mean ± σ):     189.019 s ± 21.132 s    [User: 833.653 s, System: 56.385 s]
  Range (min … max):   172.622 s … 212.868 s    3 runs
 
Benchmark 7: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=15 -v
  Time (mean ± σ):     206.963 s ±  1.494 s    [User: 856.126 s, System: 49.655 s]
  Range (min … max):   205.559 s … 208.534 s    3 runs
 
Benchmark 8: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=15 -v
  Time (mean ± σ):     184.239 s ± 67.331 s    [User: 826.816 s, System: 50.089 s]
  Range (min … max):   107.433 s … 233.091 s    3 runs
 
Benchmark 9: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=15 -v
  Time (mean ± σ):     202.861 s ± 29.341 s    [User: 843.299 s, System: 50.067 s]
  Range (min … max):   170.053 s … 226.586 s    3 runs
 
Benchmark 10: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=15 -v
  Time (mean ± σ):     174.238 s ± 50.479 s    [User: 807.545 s, System: 49.614 s]
  Range (min … max):   120.819 s … 221.145 s    3 runs
 
Benchmark 11: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=30 -v
  Time (mean ± σ):     224.641 s ±  5.907 s    [User: 877.109 s, System: 57.536 s]
  Range (min … max):   219.412 s … 231.049 s    3 runs
 
Benchmark 12: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=30 -v
  Time (mean ± σ):     230.322 s ±  5.617 s    [User: 874.903 s, System: 50.481 s]
  Range (min … max):   226.854 s … 236.802 s    3 runs

Benchmark 13: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=30 -v
  Time (mean ± σ):     131.530 s ± 30.980 s    [User: 762.951 s, System: 49.157 s]
  Range (min … max):   106.245 s … 166.088 s    3 runs
 
Benchmark 14: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=30 -v
  Time (mean ± σ):     188.971 s ± 61.516 s    [User: 832.483 s, System: 49.780 s]
  Range (min … max):   118.056 s … 227.978 s    3 runs
 
Benchmark 15: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=30 -v
  Time (mean ± σ):     226.673 s ± 13.047 s    [User: 873.159 s, System: 50.534 s]
  Range (min … max):   211.653 s … 235.205 s    3 runs
 
Benchmark 16: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=60 -v
  Time (mean ± σ):     229.852 s ±  6.303 s    [User: 886.346 s, System: 57.812 s]
  Range (min … max):   222.912 s … 235.221 s    3 runs
 
Benchmark 17: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=60 -v
  Time (mean ± σ):     223.676 s ± 11.276 s    [User: 862.248 s, System: 50.050 s]
  Range (min … max):   214.265 s … 236.173 s    3 runs
 
Benchmark 18: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=60 -v
  Time (mean ± σ):     223.082 s ± 17.962 s    [User: 871.015 s, System: 50.152 s]
  Range (min … max):   204.295 s … 240.086 s    3 runs
 
Benchmark 19: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=60 -v
  Time (mean ± σ):     198.999 s ± 33.897 s    [User: 839.426 s, System: 50.105 s]
  Range (min … max):   160.412 s … 223.975 s    3 runs
 
Benchmark 20: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=60 -v
  Time (mean ± σ):     219.658 s ± 17.197 s    [User: 863.904 s, System: 50.254 s]
  Range (min … max):   200.042 s … 232.141 s    3 runs
 
Summary
  ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=30 -v ran
    1.32 ± 0.49 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=15 -v
    1.35 ± 0.57 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=0 -v
    1.40 ± 0.61 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=15 -v
    1.44 ± 0.58 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=30 -v
    1.44 ± 0.37 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=15 -v
    1.51 ± 0.44 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=60 -v
    1.54 ± 0.43 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=15 -v
    1.57 ± 0.49 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=0 -v
    1.57 ± 0.37 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=15 -v
    1.67 ± 0.41 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=60 -v
    1.69 ± 0.40 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=0 -v
    1.70 ± 0.42 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=60 -v
    1.70 ± 0.41 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=60 -v
    1.71 ± 0.40 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=30 -v
    1.71 ± 0.41 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=0 -v
    1.72 ± 0.41 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=0 -v
    1.72 ± 0.42 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=30 -v
    1.75 ± 0.41 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=60 -v
    1.75 ± 0.41 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.1863600 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=30 -v