Skip to content

Comments

feat: memlogger#1

Open
zsystm wants to merge 14 commits intorelease/v0.53.xfrom
zsystm/memlogger
Open

feat: memlogger#1
zsystm wants to merge 14 commits intorelease/v0.53.xfrom
zsystm/memlogger

Conversation

@zsystm
Copy link

@zsystm zsystm commented Nov 1, 2025

Description

Adds MemLogger: a WAL-based in-memory compressing logger for high-throughput environments.

Key Features

  • Async compression: Buffers logs in memory, compresses with gzip in background
  • WAL persistence: Appends to write-ahead log with sidecar index for efficient replay
  • Configurable flushing: Time-based (e.g., 2s) and size-based (e.g., 64MB) triggers
  • Message filtering: Optional allow-list reduces log volume by ~90%
  • Console mirroring: Info/warn/error logs can mirror to stdout
  • Chronological ordering: Preserved even on failures (drops chunks vs reordering)

Usage

logger, err := log.NewMemLogger(log.MemLoggerConfig{
    Interval:         2 * time.Second,
    MemoryLimitBytes: 64 << 20,
    EnableFilter:     true,
    Console:          os.Stdout,
})

### Design

- Logs stored as: <dataDir>/data/log.wal/node-<id>/<date>/seg-XXXXXX.wal.gz
- Sidecar index: seg-XXXXXX.wal.idx (NDJSON with byte ranges)
- Auto-rotation at 1GB
- Uses fdatasync on Linux for better write performance

No breaking changes. New logger implementation alongside existing ones.

- Implement in-memory compressing logger and --memlog flag
- Extend log.Logger with Flush/Close (no-op for default/nop)
- Return memlogger in CreateSDKLogger when enabled
- Close then Flush in ListenForQuitSignals to persist pending logs
…g, add tests

- Append compressed chunks directly to WAL on interval/memory triggers
- Remove in-memory chunk retention by default; cap via memory-bytes
- Flush now compresses tail and fsyncs WAL; Close drains and closes
- Minimal walWriter (DataDir/NodeID), default 1 GiB rolling, big buf
- Derive WAL buf size from memory-bytes (≥1GiB→16MiB, ≥256MiB→8MiB, else 4MiB)
- Use fdatasync on Linux; fallback to fsync elsewhere
- Simplify app config to interval, memory-bytes, dir (max-bytes kept as deprecated alias)
- Add wal_writer unit tests and benchmarks (incl. bufSize vs chunk size)
@zsystm
Copy link
Author

zsystm commented Nov 2, 2025

Metrics

Testing Env

  • Binary: https://github.com/bft-labs/evm/tree/zsystm/memlogger
  • OS: Ubuntu 24.04.3 LTS (noble) — Kernel 6.x (64-bit)
  • CPU: AMD EPYC 4584PX 16-Core Processor (32 threads / 16 cores, 1 socket)
    • Base clock ~ 545 MHz (min) / 5759 MHz (max)
    • L1 512 KiB × 2 (L1d + L1i), L2 16 MiB, L3 128 MiB
    • Virtualization: AMD-V enabled
  • Memory: 62 GiB total (17 GiB used / 36 GiB free / 9.1 GiB cached)
  • Storage: Dual NVMe SSDs
    • /dev/nvme0n1 (894 GiB, xfs, root mount)
    • /dev/nvme1n1 (894 GiB, unmounted reserve disk)
  • Swap: Disabled
  • NUMA: Single node (0-31)
  • Virtualization Layer: Bare-metal (no nested VM)

Benchmark Setup

  • 4 local Cosmos/EVM nodes running on the same host
  • Load Generator: custom tool emitting basic Ethereum transfer transactions
  • Load Pattern: 400 TPS applied to a single node (then naturally broadcast and processed by all peers through CometBFT consensus)
  • Test duration: 3 minutes
  • Metrics collected: CPU, Memory, and Disk I/O profiles for each logger variant

Summary
Even when the filter is disabled (logging every message like the full Debug mode), MemLogger continues to demonstrate stable and predictable performance across CPU, memory, and disk metrics.

  • CPU overhead: Comparable to both Info and Debug loggers, even without filtering. The filtered variant remains slightly lower under sustained load, confirming that the in-memory buffering design—not just selective filtering—is the key efficiency driver.
  • Memory footprint: The unfiltered MemLogger shows a moderate increase in user memory and file-cache usage (≈ +1 GiB / +2–3 GiB respectively) but still avoids the large cache spikes observed in DefaultDebugLogger.
  • Disk utilization: Even without filtering, MemLogger maintains similar throughput (≈ 403 MB/s mean, 677 MB/s max) while keeping I/O utilization lower than DefaultDebugLogger, thanks to efficient write batching and compression.

Overall, both configurations confirm that MemLogger achieves high observability with minimal overhead.
The filtered mode is ideal for production deployment, while the unfiltered mode remains a safe, drop-in replacement for full Debug logging—delivering equivalent visibility with significantly better disk and memory efficiency.

CPU Usage

Logger Type Mean Max
MemLogger System 2.63% 4.93%
MemLogger User 15.2% 24.2%
DefaultInfoLogger System 2.23% 3.70%
DefaultInfoLogger User 14.2% 23.0%
DefaultDebugLogger System 2.61% 5.33%
DefaultDebugLogger User 15.0% 23.7%
MemLoggerWithoutFilter System 2.35% 4.43%
MemLoggerWithoutFilter User 17.0% 23.9%

Memory Usage

Logger Type Mean Max
MemLogger User 20.1 GiB 21.8 GiB
MemLogger File Cache 4.94 GiB 6.56 GiB
DefaultInfoLogger User 20.2 GiB 22.0 GiB
DefaultInfoLogger File Cache 5.28 GiB 6.94 GiB
DefaultDebugLogger User 19.9 GiB 21.3 GiB
DefaultDebugLogger File Cache 11.1 GiB 16.6 GiB
MemLoggerWithoutFilter User 21.2 GiB 22.5 GiB
MemLoggerWithoutFilter File Cache 7.01 GiB 9.21 GiB

Disk I/O

Logger Type Mean Max
MemLogger Write 802 io/s 1.38 K io/s
MemLogger Throughput 423 MB/s 759 MB/s
MemLogger I/O Utilization 14.8 % 27.0 %
DefaultInfoLogger Write 748 io/s 1.29 K io/s
DefaultInfoLogger Throughput 300 MB/s 678 MB/s
DefaultInfoLogger I/O Utilization 16.2 % 31.6 %
DefaultDebugLogger Write 749 io/s 1.46 K io/s
DefaultDebugLogger Throughput 415 MB/s 1.04 GB/s
DefaultDebugLogger I/O Utilization 18.9 % 52.1 %
MemLoggerWithoutFilter Write 759 io/s 1.25 K io/s
MemLoggerWithoutFilter Throughput 403 MB/s 677 MB/s
MemLoggerWithoutFilter I/O Utilization 16.3 % 36.0 %

Memory Debug Logger (WAL + Filter applied)

image image image image

Default Info Logger

image image image image

Default Debug Logger

image image image image

Memory Debulg Logger Without Filter (same logging contents as default debug logger)

image image image image

@zsystm zsystm marked this pull request as ready for review November 2, 2025 09:28
@djm07073 djm07073 self-requested a review November 5, 2025 13:28
- Add per-frame sidecar index (.wal.idx) alongside compressed WAL (.wal.gz).
- Each line records the target .gz file and compressed byte range (off,len) plus metadata (frame id, rec count, first/last ts, optional CRC32 of uncompressed payload).
- Purpose: enable reliable tail/stream of a single growing .gz via random-access reads, since most shippers cannot follow gzip; decouple production from shipping; support fast resume/backfill.
- Reader follows the .idx and fetches frames via section reads + gzip, switching files on rotation when the recorded file changes.
- Benefits: low-latency shipping with bounded memory, crash-resume from last processed line, integrity verification, and simpler external agents.
- Backwards-compatible: WAL format unchanged; index is append-only and optional. Writers append the .idx line after successfully writing the frame to the .gz.
- Note: durability still depends on appropriate fsync policy; consumers may verify CRC and line counts when needed.
Implements a production-ready logger that buffers logs in memory, compresses them asynchronously with gzip, and persists to a WAL with sidecar index for efficient replay.

Features:
- Time/size-based flushing with configurable thresholds
- Object pooling for zero-allocation compression
- Message filtering for consensus-critical events
- Chronological ordering preserved (drops on failure)
- Automatic segment rotation and platform-optimized fsync
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants