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 #12288

Open
wants to merge 7 commits into
base: master
Choose a base branch
from
Open

output/eve: reduce fflush call count #12288

wants to merge 7 commits into from
+655 −93

Conversation

jlucovsky
Copy link
Contributor

Continuation of #12135

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:

  • Rebase

Suricata build information

$ src/suricata --build-info
This is Suricata version 8.0.0-dev (fc71dee8fd 2024-11-19)
Features: UNITTESTS PCAP_SET_BUFF AF_PACKET HAVE_PACKET_FANOUT LIBCAP_NG HAVE_HTP_URI_NORMALIZE_HOOK PCRE_JIT HAVE_NSS HTTP2_DECOMPRESSION HAVE_LUA HAVE_JA3 HAVE_JA4 HAVE_LIBJANSSON TLS TLS_C11 MAGIC RUST POPCNT64
SIMD support: SSE_4_2 SSE_4_1 SSE_3 SSE_2
Atomic intrinsics: 1 2 4 8 16 byte(s)
64-bits, Little-endian architecture
GCC version Ubuntu Clang 19.1.1 (1ubuntu1), C version 201112
compiled with _FORTIFY_SOURCE=0
L1 cache line size (CLS)=64
thread local storage method: _Thread_local
compiled with LibHTP v0.5.49, linked against LibHTP v0.5.49

Suricata Configuration:
  AF_PACKET support:                       yes
  AF_XDP support:                          no
  DPDK support:                            no
  eBPF support:                            no
  XDP support:                             no
  PF_RING support:                         no
  NFQueue support:                         no
  NFLOG support:                           no
  IPFW support:                            no
  Netmap support:                          no
  DAG enabled:                             no
  Napatech enabled:                        no
  WinDivert enabled:                       no

  Unix socket enabled:                     yes
  Detection enabled:                       yes

  Libmagic support:                        yes
  libjansson support:                      yes
  hiredis support:                         no
  hiredis async with libevent:             no
  PCRE jit:                                yes
  GeoIP2 support:                          yes
  JA3 support:                             yes
  JA4 support:                             yes
  Non-bundled htp:                         no
  Hyperscan support:                       yes
  Libnet support:                          no
  liblz4 support:                          yes
  Landlock support:                        yes
  Systemd support:                         yes

  Rust support:                            yes
  Rust strict mode:                        yes
  Rust compiler path:                      /home/jlucovsky/.cargo/bin/rustc
  Rust compiler version:                   rustc 1.81.0 (eeb90cda1 2024-09-04)
  Cargo path:                              /home/jlucovsky/.cargo/bin/cargo
  Cargo version:                           cargo 1.81.0 (2dbb1af80 2024-08-20)

  Python support:                          yes
  Python path:                             /usr/bin/python3
  Install suricatactl:                     yes
  Install suricatasc:                      yes
  Install suricata-update:                 no, not bundled

  Profiling enabled:                       no
  Profiling locks enabled:                 no
  Profiling rules enabled:                 no

  Plugin support (experimental):           yes
  DPDK Bond PMD:                           no

Development settings:
  Coccinelle / spatch:                     no
  Unit tests enabled:                      yes
  Debug output enabled:                    no
  Debug validation enabled:                no
  Fuzz targets enabled:                    no

Generic build parameters:
  Installation prefix:
  Configuration directory:                 /etc/suricata/
  Log directory:                           /var/log/suricata/

  --prefix
  --sysconfdir                             /etc
  --localstatedir                          /var
  --datarootdir                            /share

  Host:                                    x86_64-pc-linux-gnu
  Compiler:                                ccache clang (exec name) / g++ (real)
  GCC Protect enabled:                     no
  GCC march native enabled:                yes
  GCC Profile enabled:                     no
  Position Independent Executable enabled: no
  CFLAGS                                   -ggdb3 -O0 -Wall -fno-strict-aliasing -fstack-protector-all -fno-omit-frame-pointer -O3 -fPIC -DOS_LINUX -std=c11 -march=native -I${srcdir}/../rust/gen -I${srcdir}/../rust/dist -I../rust/gen -Wunused-macros -Wimplicit-int-float-conversion
  PCAP_CFLAGS                               -I/usr/include
  SECCFLAGS

Benchmarks/Measurements

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

Summary: Buffering had the biggest impact; using the flushing mechanism had little impact but is necessary for integrity.

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.178114 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=0 -v --no-random
  Time (mean ± σ):     105.042 s ±  0.694 s    [User: 392.799 s, System: 29.616 s]
  Range (min … max):   104.219 s … 105.846 s    5 runs
 
Benchmark 2: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=0 -v --no-random
  Time (mean ± σ):     101.037 s ±  0.220 s    [User: 381.299 s, System: 23.789 s]
  Range (min … max):   100.811 s … 101.397 s    5 runs
 
Benchmark 3: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=0 -v --no-random
  Time (mean ± σ):     101.512 s ±  0.411 s    [User: 380.713 s, System: 23.808 s]
  Range (min … max):   101.208 s … 102.158 s    5 runs
 
  Warning: The first benchmarking run for this command was significantly slower than the rest (102.158 s). This could be caused by (filesystem) caches that were not filled until after the first run. You are already using the '--prepare' option which can be used to clear caches. If you did not use a cache-clearing command with '--prepare', you can either try that or consider using the '--warmup' option to fill those caches before the actual benchmark.
 
Benchmark 4: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=0 -v --no-random
  Time (mean ± σ):     100.412 s ±  1.692 s    [User: 379.998 s, System: 23.466 s]
  Range (min … max):   98.078 s … 102.255 s    5 runs
 
Benchmark 5: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=0 -v --no-random
  Time (mean ± σ):     100.482 s ±  1.554 s    [User: 378.951 s, System: 23.317 s]
  Range (min … max):   97.797 s … 101.798 s    5 runs
 
Benchmark 6: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=15 -v --no-random
  Time (mean ± σ):     113.128 s ±  0.860 s    [User: 411.860 s, System: 42.776 s]
  Range (min … max):   112.254 s … 114.216 s    5 runs
 
Benchmark 7: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=15 -v --no-random
  Time (mean ± σ):     102.134 s ±  0.792 s    [User: 381.837 s, System: 24.454 s]
  Range (min … max):   101.008 s … 102.910 s    5 runs
 
Benchmark 8: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=15 -v --no-random
  Time (mean ± σ):     101.086 s ±  1.794 s    [User: 378.685 s, System: 23.989 s]
  Range (min … max):   97.951 s … 102.333 s    5 runs
 
Benchmark 9: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=15 -v --no-random
  Time (mean ± σ):     102.027 s ±  0.244 s    [User: 380.924 s, System: 23.449 s]
  Range (min … max):   101.754 s … 102.341 s    5 runs
 
Benchmark 10: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=15 -v --no-random
  Time (mean ± σ):     102.039 s ±  0.264 s    [User: 381.812 s, System: 23.590 s]
  Range (min … max):   101.600 s … 102.266 s    5 runs
 
Benchmark 11: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=30 -v --no-random
  Time (mean ± σ):     114.094 s ±  0.654 s    [User: 413.039 s, System: 43.291 s]
  Range (min … max):   113.330 s … 114.829 s    5 runs
 
Benchmark 12: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=30 -v --no-random
  Time (mean ± σ):     102.619 s ±  1.305 s    [User: 382.924 s, System: 24.457 s]
  Range (min … max):   100.850 s … 104.346 s    5 runs
 
Benchmark 13: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=30 -v --no-random
  Time (mean ± σ):     101.627 s ±  0.466 s    [User: 381.293 s, System: 23.830 s]
  Range (min … max):   101.172 s … 102.228 s    5 runs
 
Benchmark 14: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=30 -v --no-random
  Time (mean ± σ):     102.848 s ±  1.710 s    [User: 382.499 s, System: 23.826 s]
  Range (min … max):   101.879 s … 105.893 s    5 runs
 
  Warning: The first benchmarking run for this command was significantly slower than the rest (105.893 s). This could be caused by (filesystem) caches that were not filled until after the first run. You are already using the '--prepare' option which can be used to clear caches. If you did not use a cache-clearing command with '--prepare', you can either try that or consider using the '--warmup' option to fill those caches before the actual benchmark.
 
Benchmark 15: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=30 -v --no-random
  Time (mean ± σ):     100.282 s ±  2.112 s    [User: 378.376 s, System: 23.435 s]
  Range (min … max):   97.979 s … 102.508 s    5 runs
 
Benchmark 16: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=60 -v --no-random
  Time (mean ± σ):     112.440 s ±  1.739 s    [User: 412.086 s, System: 43.432 s]
  Range (min … max):   109.535 s … 113.848 s    5 runs
 
Benchmark 17: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=60 -v --no-random
  Time (mean ± σ):     101.794 s ±  0.338 s    [User: 381.459 s, System: 24.484 s]
  Range (min … max):   101.453 s … 102.236 s    5 runs
 
Benchmark 18: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=60 -v --no-random
  Time (mean ± σ):     102.923 s ±  1.531 s    [User: 382.588 s, System: 23.935 s]
  Range (min … max):   101.700 s … 105.492 s    5 runs
 
Benchmark 19: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=60 -v --no-random
  Time (mean ± σ):     100.927 s ±  1.225 s    [User: 380.923 s, System: 23.436 s]
  Range (min … max):   98.769 s … 101.820 s    5 runs
 
  Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet system without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options.
 
Benchmark 20: ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=60 -v --no-random
  Time (mean ± σ):     101.585 s ±  0.767 s    [User: 380.448 s, System: 23.464 s]
  Range (min … max):   100.734 s … 102.420 s    5 runs
 
Summary
  ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=30 -v --no-random ran
    1.00 ± 0.03 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=0 -v --no-random
    1.00 ± 0.03 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=0 -v --no-random
    1.01 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=60 -v --no-random
    1.01 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=0 -v --no-random
    1.01 ± 0.03 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=15 -v --no-random
    1.01 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=0 -v --no-random
    1.01 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=60 -v --no-random
    1.01 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=30 -v --no-random
    1.02 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=60 -v --no-random
    1.02 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=15 -v --no-random
    1.02 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=64kb --set heartbeat.output-flush-interval=15 -v --no-random
    1.02 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=15 -v --no-random
    1.02 ± 0.03 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=8kb --set heartbeat.output-flush-interval=30 -v --no-random
    1.03 ± 0.03 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=32kb --set heartbeat.output-flush-interval=30 -v --no-random
    1.03 ± 0.03 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=16kb --set heartbeat.output-flush-interval=60 -v --no-random
    1.05 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=0 -v --no-random
    1.12 ± 0.03 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=60 -v --no-random
    1.13 ± 0.03 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=15 -v --no-random
    1.14 ± 0.02 times faster than ./src/suricata -c suricata.yaml -S ~/suricata.rules -r ~/pcap -l /tmp/ll.178114 --set outputs.1.eve-log.buffer-size=0 --set heartbeat.output-flush-interval=30 -v --no-random

@jlucovsky
output/log: Add flush function, collapse params
aaa9f76 
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
3431fbf 
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
4b9f674
@jlucovsky
output: Support buffer-size value
5c5ea66 
Issue: 3449
@jlucovsky
output/log: Add flushing infrastructure
dec0d0a 
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
5928be4 
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
23e4945 
Issue: 3449
@jlucovsky jlucovsky mentioned this pull request Dec 14, 2024
Closed
@codecov Codecov
Copy link

codecov bot commented Dec 14, 2024

Codecov Report

Attention: Patch coverage is 50.46154% with 161 lines in your changes missing coverage. Please review.

Project coverage is 83.21%. Comparing base (0e4faba) to head (23e4945).
Report is 15 commits behind head on master.

Additional details and impacted files 
@@            Coverage Diff             @@
##           master   #12288      +/-   ##
==========================================
- Coverage   83.22%   83.21%   -0.02%     
==========================================
  Files         912      913       +1     
  Lines      257311   257891     +580     
==========================================
+ Hits       214154   214600     +446     
- Misses      43157    43291     +134
Flag Coverage Δ
fuzzcorpus 61.04% <44.30%> (-0.03%) ⬇️
livemode 19.57% <50.46%> (+0.04%) ⬆️
pcap 44.43% <48.30%> (+0.06%) ⬆️
suricata-verify 62.85% <50.15%> (+<0.01%) ⬆️
unittests 59.15% <35.69%> (-0.03%) ⬇️

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

@suricata-qa
Copy link

Information: QA ran without warnings.

Pipeline 23957

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

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

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

At least 1 approving review is required to merge this pull request.

Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

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