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.

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

output/eve: reduce fflush call count #12135

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

Conversation

jlucovsky
Copy link
Contributor

@jlucovsky jlucovsky commented Nov 20, 2024

Continuation of #11883

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

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


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
Copy link

codecov bot commented Nov 20, 2024

Codecov Report

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

Project coverage is 83.07%. Comparing base (5d766df) to head (c41ed85).

Additional details and impacted files
@@             Coverage Diff             @@
##           master   #12135       +/-   ##
===========================================
+ Coverage   62.68%   83.07%   +20.39%     
===========================================
  Files         840      910       +70     
  Lines      153669   258147   +104478     
===========================================
+ Hits        96323   214462   +118139     
+ Misses      57346    43685    -13661     
Flag Coverage Δ
fuzzcorpus 60.90% <44.30%> (?)
livemode 19.48% <50.46%> (?)
pcap 44.40% <48.30%> (?)
suricata-verify 62.66% <50.15%> (-0.02%) ⬇️
unittests 59.24% <35.69%> (?)

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

---- 🚨 Try these New Features:

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
Copy link

Information: QA ran without warnings.

Pipeline 23450

@jlucovsky jlucovsky marked this pull request as ready for review November 22, 2024 14:43
@jlucovsky jlucovsky changed the title DRAFT: 3449.v4/4 output/eve: reduce fflush call count Nov 22, 2024
@@ -280,3 +284,14 @@ outputs:
# event-set: false # log packets that have a decoder/stream event
# state-update: false # log packets triggering a TCP state update
# spurious-retransmission: false # log spurious retransmission packets
#
heartbeat:
Copy link
Contributor

Choose a reason for hiding this comment

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

Should this not belong in outputs section ?

@catenacyber
Copy link
Contributor

Dummy question : why do we need the heartbeat flushing ?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

3 participants