Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

output/eve: reduce fflush call count #11883

Closed
wants to merge 7 commits into from
Closed

output/eve: reduce fflush call count #11883

wants to merge 7 commits into from

Conversation

jlucovsky
Copy link
Contributor

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

@jlucovsky
output/log: Add flush function, collapse params
2a3ce50 
Issue: 3449

Add a flush function to packet logger registration and collapse the
parameter count for registration functions.
@jlucovsky
conf/output: Buffering related config settings
80c868f 
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
@jlucovsky
doc/output: EVE output buffering related settings
824c1c7
@jlucovsky
output: Support buffer-size value
6bdc378 
Issue: 3449
@jlucovsky
output/log: Add flushing infrastructure
9b68167 
Issue: 3449

Add flushing functions and infrastructure. This includes:
- Flushing functions for packet loggers
- Log file flushing support
@jlucovsky
detect/flag: Pseudo pkt "flush log" flag
9780410 
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.
@jlucovsky
main/flush: Support periodic flush logs
885f7fc
@jlucovsky jlucovsky requested review from jufajardini, victorjulien and a team as code owners October 6, 2024 12:58
@jlucovsky jlucovsky mentioned this pull request Oct 6, 2024
Closed
@codecov Codecov
Copy link

codecov bot commented Oct 6, 2024 •
edited
Loading

Codecov Report

Attention: Patch coverage is 51.45631% with 150 lines in your changes missing coverage. Please review.

Project coverage is 82.54%. Comparing base (3f0512e) to head (885f7fc).
Report is 125 commits behind head on master.

Additional details and impacted files 
@@            Coverage Diff             @@
##           master   #11883      +/-   ##
==========================================
- Coverage   82.61%   82.54%   -0.07%     
==========================================
  Files         912      913       +1     
  Lines      249354   249603     +249     
==========================================
+ Hits       205992   206024      +32     
- Misses      43362    43579     +217
Flag Coverage Δ
fuzzcorpus 60.52% <45.95%> (-0.11%) ⬇️
livemode 18.78% <51.45%> (-0.08%) ⬇️
pcap 43.97% <49.83%> (-0.12%) ⬇️
suricata-verify 62.00% <51.45%> (-0.01%) ⬇️
unittests 58.91% <37.54%> (-0.02%) ⬇️

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

---- 🚨 Try these New Features:

@suricata-qa
Copy link

Information: QA ran without warnings.

Pipeline 22997

@victorjulien
Copy link
Member

What is the buffer 0 behavior? It seems 0/60s has the same increase as 8k/30s?

@jlucovsky
Copy link
Contributor Author

What is the buffer 0 behavior? It seems 0/60s has the same increase as 8k/30s?

A buffer size of 0 means "no buffering" so a non-zero flush-interval doesn't make sense.

Perhaps I should handle that case and require that buffer-size and flush-interval are either both 0 or both non-zero?

@victorjulien
Copy link
Member

So it turns out I misread the output, completely :)

Should be rerun, at least a subset of it with Suricata's --no-random option, to hopefully get a bit more stable times.

catenacyber
catenacyber requested changes Nov 18, 2024
View reviewed changes
Copy link
Contributor

@catenacyber catenacyber left a comment

Choose a reason for hiding this comment

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

needs rebase, and some comment by Victor needs to be considered

@jlucovsky jlucovsky mentioned this pull request Nov 22, 2024
Closed
@jlucovsky
Copy link
Contributor Author

Continued in #12135

@jlucovsky jlucovsky closed this Nov 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@catenacyber catenacyber catenacyber requested changes

@jufajardini jufajardini Awaiting requested review from jufajardini jufajardini is a code owner

@victorjulien victorjulien Awaiting requested review from victorjulien victorjulien is a code owner

Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
4 participants
@jlucovsky @suricata-qa @victorjulien @catenacyber