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

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

output/eve: reduce fflush call count #12527

wants to merge 7 commits into from
+655 −92

Conversation

jlucovsky
Copy link
Contributor

Continuation of #12525

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
  • Fixed rebase error causing DBV faults.

Suricata build information

This is Suricata version 8.0.0-dev (ca94c1a8cb 2025-02-03)
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:                          yes
  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 strict mode:                        yes
  Rust compiler path:                      /home/jlucovsky/.cargo/bin/rustc
  Rust compiler version:                   rustc 1.83.0 (90b35a623 2024-11-26)
  Cargo path:                              /home/jlucovsky/.cargo/bin/cargo
  Cargo version:                           cargo 1.83.0 (5ffbef321 2024-10-29)

  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 -Wshadow -Wunused -Wuninitialized -Wchar-subscripts -Wno-unused-function -Wno-unused-parameter -Werror=sign-compare  -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 effect but is necessary for integrity.

Recommendation:

Adding buffering in any amount improves performance. When buffering, a flush interval of 30 seconds is recommented

  • eve-log.buffer-size: 64kb
  • heartbeat.output-flush-interval: 30 (seconds)

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
7bffe5e 
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
233cc8f 
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
7127e67
@jlucovsky
output: Support buffer-size value
448c9cc 
Issue: 3449
@jlucovsky
output/log: Add flushing infrastructure
8e34977 
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
c8a3f21 
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
e580546 
Issue: 3449
@jlucovsky jlucovsky mentioned this pull request Feb 3, 2025
Closed
@codecov Codecov
Copy link

codecov bot commented Feb 3, 2025

Codecov Report

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

Project coverage is 80.66%. Comparing base (d4330ef) to head (e580546).

Additional details and impacted files 
@@            Coverage Diff             @@
##           master   #12527      +/-   ##
==========================================
- Coverage   80.68%   80.66%   -0.03%     
==========================================
  Files         925      926       +1     
  Lines      258914   259178     +264     
==========================================
+ Hits       208914   209071     +157     
- Misses      50000    50107     +107
Flag Coverage Δ
fuzzcorpus 56.81% <44.13%> (-0.02%) ⬇️
livemode 19.46% <50.30%> (+0.05%) ⬆️
pcap 44.20% <48.14%> (+<0.01%) ⬆️
suricata-verify 63.37% <50.15%> (-0.03%) ⬇️
unittests 58.35% <35.80%> (-0.03%) ⬇️

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

@suricata-qa
Copy link

WARNING:

field baseline test %
SURI_TLPR1_stats_chk
.uptime 636 610 95.91%

Pipeline 24556

@jasonish
Copy link
Member

jasonish commented Feb 4, 2025

I'm running this live now with a log ingestor. So far so good but its only been about an hour, but the implementation seems sane.

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

@jasonish jasonish jasonish left review comments

@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.
3 participants
@jlucovsky @suricata-qa @jasonish