From 3004a7100e325c006971cc2e8d0f157338c0ce5c Mon Sep 17 00:00:00 2001 From: Paul Buetow Date: Wed, 22 Jul 2026 23:52:52 +0300 Subject: =?UTF-8?q?docs:=20DTail=20fork=20=E2=80=94=20documentation,=20age?= =?UTF-8?q?nt=20guide,=20example=20configs?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Squashed development of the documentation and example configuration: - AGENTS.md / CLAUDE.md: repository guide describing build/test/benchmark/PGO workflows and the single default read/output path (formerly "turbo"). - doc/ and docs/: query-language reference, log formats, auth-key fast reconnect, journal source reads, performance analyses (dated point-in-time records kept under historical-note disclaimers), and the turbo-vs-normal benchmark report with its result CSVs. - README.md updates; examples/ config + JSON schema aligned with the current Output* server tuning fields (the removed TurboBoost* keys dropped). Co-Authored-By: Claude Opus 4.8 --- doc/asciinema/README.md | 41 ---- doc/auth-key-fast-reconnect.md | 200 +++++++++++++++++ doc/index.md | 1 + doc/installation.md | 59 ++++- doc/logformats.md | 5 +- doc/performance_optimization_summary.md | 69 ++++++ doc/pgo_commands_detail.md | 216 ++++++++++++++++++ doc/pgo_implementation.md | 173 +++++++++++++++ doc/profiling.md | 376 ++++++++++++++++++++++++++++++++ doc/querylanguage.md | 40 +++- doc/refactoring_guide.md | 240 ++++++++++++++++++++ doc/turbo_performance_analysis.md | 104 +++++++++ doc/turboboost_optimization.md | 117 ++++++++++ 13 files changed, 1595 insertions(+), 46 deletions(-) delete mode 100644 doc/asciinema/README.md create mode 100644 doc/auth-key-fast-reconnect.md create mode 100644 doc/performance_optimization_summary.md create mode 100644 doc/pgo_commands_detail.md create mode 100644 doc/pgo_implementation.md create mode 100644 doc/profiling.md create mode 100644 doc/refactoring_guide.md create mode 100644 doc/turbo_performance_analysis.md create mode 100644 doc/turboboost_optimization.md (limited to 'doc') diff --git a/doc/asciinema/README.md b/doc/asciinema/README.md deleted file mode 100644 index 1eb1a2e..0000000 --- a/doc/asciinema/README.md +++ /dev/null @@ -1,41 +0,0 @@ -asciinema -========= - -The animated Gifs you find in the DTail docs were created using: - -* [asciinema](https://asciinema.org) -* [asciicast2gif](https://github.com/asciinema/asciicast2gif) - -On Fedora Linux 35. - -## Installing prerequisites - -On Fedora Linux 35 install `asciinema`: - -```shell -% sudo dnf install -y asciinema -``` - -and `asciicast2gif` (for simplicity, the Docker image was used): - -```shell -% docker pull asciinema/asciicast2gif -``` - -This of course assumes that Docker is up and running on your machine (out of scope for this documentation). - -## Record a shell session - -This is as simple as running - -```shell -% asciinema rec recording.json -``` - -This will launch a sub-shell to be recorded. Once done, exit the sub-shell with `exit`. - -## Convert the recording to a gif - -```shell -% docker run --rm -v $PWD:/data asciinema/asciicast2gif -t tango -s 2 recording.json recording.gif -``` diff --git a/doc/auth-key-fast-reconnect.md b/doc/auth-key-fast-reconnect.md new file mode 100644 index 0000000..cb9884a --- /dev/null +++ b/doc/auth-key-fast-reconnect.md @@ -0,0 +1,200 @@ +# Auth-Key Fast-Reconnect for DTail + +## Problem + +When using a YubiKey for SSH authentication, each DTail connection requires a +physical touch of the YubiKey during the SSH handshake. This is slow and becomes +painful when connecting to many servers concurrently — the YubiKey serialises +all signing requests, turning parallel connections into sequential ones. + +## Solution + +Allow the DTail client to register a local SSH public key with the DTail server +over an already-authenticated SSH session. The server caches this key +**in-memory only** (never written to disk). On subsequent connections the client +offers that local key first — a pure in-memory RSA verify with no YubiKey +interaction — and falls back to the original auth method if the server does not +recognise the key. + +## Design Principles + +1. **Transparent fallback** — Go's `golang.org/x/crypto/ssh` tries each + `AuthMethod` in order; if the fast key is rejected the client silently falls + back to the SSH agent / YubiKey. No user interaction required. +2. **Server keys are ephemeral** — the in-memory store is lost on server + restart. No file I/O, no persistence. +3. **Trust chain preserved** — an auth-key can only be registered over a session + that was already authenticated via the normal (YubiKey) path. +4. **Minimal protocol addition** — a single `AUTHKEY ` command + sent over the existing SSH session text protocol. + +## Architecture Overview + +``` +┌─────────────────────────────────────────────────────────┐ +│ DTail Client │ +│ │ +│ Auth methods (tried in order): │ +│ 1. Local private key (~/.ssh/id_rsa) ← FAST │ +│ 2. SSH Agent / YubiKey ← SLOW fallback │ +│ │ +│ After slow-path auth: │ +│ → sends AUTHKEY <~/.ssh/id_rsa.pub> to server │ +└────────────────────────┬────────────────────────────────┘ + │ SSH +┌────────────────────────▼────────────────────────────────┐ +│ DTail Server (dserver) │ +│ │ +│ PublicKeyCallback: │ +│ 1. Check in-memory authkeystore ← FAST │ +│ 2. Check authorized_keys file ← existing path │ +│ │ +│ AUTHKEY command handler: │ +│ → authkeystore.Add(user, pubkey) │ +│ → responds AUTHKEY OK / AUTHKEY ERR │ +│ │ +│ authkeystore (in-memory only): │ +│ map[username] → []PublicKey (with TTL, max per user) │ +└─────────────────────────────────────────────────────────┘ +``` + +## Sequence of Events + +### First Connection (slow path — YubiKey) + +1. Client checks for local private key at `~/.ssh/id_rsa` (or `--auth-key-path`). +2. Client builds auth methods list: `[localKey, sshAgent]`. +3. SSH handshake begins; server's `PublicKeyCallback` is called with local key. +4. Server checks in-memory authkeystore → not found. +5. Server checks `authorized_keys` file → not found (this key isn't in there). +6. Server rejects the key. +7. Go SSH client automatically tries next auth method: SSH agent (YubiKey). +8. YubiKey signs the challenge; server finds the YubiKey pubkey in + `authorized_keys` → auth succeeds. +9. Session is established; client sends DTail commands as usual. +10. Client reads `~/.ssh/id_rsa.pub` and sends `AUTHKEY `. +11. Server's handler parses the command, calls `authkeystore.Add(user, pubkey)`. +12. Server responds `AUTHKEY OK`. + +### Subsequent Connections (fast path — no YubiKey) + +1. Client builds auth methods list: `[localKey, sshAgent]`. +2. SSH handshake begins; server's `PublicKeyCallback` is called with local key. +3. Server checks in-memory authkeystore → **found** → auth succeeds immediately. +4. No YubiKey touch needed. Session is established instantly. + +### Fallback (server restarted, key expired) + +1. Client offers local key → server's authkeystore is empty → rejected. +2. Client falls back to SSH agent → YubiKey auth succeeds. +3. Client re-registers local pubkey via `AUTHKEY` command. + +## Components + +### 1. Server: In-Memory Auth-Key Store + +**New file:** `internal/ssh/server/authkeystore.go` + +- Thread-safe store using `sync.RWMutex`. +- Data structure: `map[string][]authKeyEntry` where key is username. +- Each `authKeyEntry` holds `gossh.PublicKey` + `time.Time` (registered at). +- Methods: `Add(user, pubkey)`, `Has(user, pubkey) bool`, `Remove(user, pubkey)`. +- Per-user max key limit (default 5, configurable via `AuthKeyMaxPerUser`). +- TTL-based expiry (default 24h, configurable via `AuthKeyTTLSeconds`). +- Lazy expiry: check TTL on `Has()` calls; optionally a background reaper. +- Package-level singleton or passed via dependency injection. + +### 2. Server: Extend PublicKeyCallback + +**Modified file:** `internal/ssh/server/publickeycallback.go` + +- Before the existing `authorizedKeysFile` lookup, check `authkeystore.Has(user, offeredPubKey)`. +- If found → return success immediately (fast path). +- If not found → fall through to existing file-based logic (no behaviour change). + +### 3. Server: AUTHKEY Command Handler + +**Modified file:** `internal/server/handlers/serverhandler.go` (or relevant handler) + +- Parse incoming line for `AUTHKEY ` prefix. +- Decode the base64 public key using `gossh.ParsePublicKey()`. +- Call `authkeystore.Add(user, pubkey)`. +- Write `AUTHKEY OK\n` or `AUTHKEY ERR \n` back to the client. +- Guard: only accept if `AuthKeyEnabled` is true in server config. + +### 4. Client: Auth Method Ordering (Multi-Method Support) + +**Modified file:** `internal/ssh/client/authmethods.go` + +- Change `initKnownHostsAuthMethods` to **collect multiple auth methods** + instead of returning after the first successful one. +- Order: local private key first (from `--auth-key-path`, default `~/.ssh/id_rsa`), + then SSH agent, then other default keys. +- This ensures Go's SSH client tries the fast key before the YubiKey. + +### 5. Client: Auth-Key Registration After Slow-Path Connection + +**Modified file:** `internal/clients/connectors/serverconnection.go` (or handler layer) + +- After session is established and DTail commands are sent, determine whether + the connection used the fast path or slow path. +- If slow path (YubiKey was used): read the public key file + (`--auth-key-path` + `.pub`), send `AUTHKEY ` command. +- Parse `AUTHKEY OK` / `AUTHKEY ERR` response. +- A simple heuristic: if the auth-key-path private key exists and we have a + corresponding `.pub` file, always send the registration — sending it again is + idempotent and cheap. + +### 6. Configuration + +**Modified files:** `internal/config/server.go`, `internal/config/client.go`, `internal/config/args.go` + +Server config (`dtail.json`): +- `AuthKeyEnabled` (bool, default `true`) +- `AuthKeyTTLSeconds` (int, default `86400` = 24h) +- `AuthKeyMaxPerUser` (int, default `5`) + +Client config / CLI flags: +- `--auth-key-path` (string, default `~/.ssh/id_rsa`) — path to the local + private key to try first and whose `.pub` counterpart is registered +- `--no-auth-key` (bool, default `false`) — disable auth-key feature entirely + +### 7. Integration Tests + +**Modified/new files in:** `integrationtests/` + +- Test that auth-key registration works end-to-end. +- Test that fast-path auth succeeds after registration. +- Test fallback when server has no cached key (simulating restart). +- Test TTL expiry and max-keys-per-user limits. +- Test `--no-auth-key` disables the feature. + +### 8. Documentation + +- Update `README.md` with auth-key feature description. +- Update `AGENTS.md` / `CLAUDE.md` with new config options and architecture notes. + +## Security Considerations + +- **No server-side disk persistence** — keys exist only in memory, lost on restart. +- **Trust chain** — auth-keys can only be registered over an already-authenticated + session. An attacker cannot register a key without first proving identity. +- **TTL expiry** — keys auto-expire (default 24h), limiting exposure window. +- **Per-user limits** — max 5 keys per user prevents memory exhaustion. +- **Same security model as `~/.ssh/id_rsa`** — the local key is protected by + filesystem permissions (0600). If an attacker has access to `~/.ssh/id_rsa`, + they already have SSH access anyway. +- **No new attack surface** — the `AUTHKEY` command is only processed inside an + authenticated session. The `PublicKeyCallback` fast-path is equivalent to + having the key in `authorized_keys`. + +## Implementation Order + +1. Auth-key store (server, standalone, unit-testable) +2. Extend `PublicKeyCallback` (server, minimal change) +3. `AUTHKEY` command handler (server handler) +4. Client auth method ordering (multi-method collection) +5. Client auth-key registration (send pubkey after slow-path) +6. Configuration and CLI flags +7. Integration tests +8. Documentation diff --git a/doc/index.md b/doc/index.md index 565253b..c45569d 100644 --- a/doc/index.md +++ b/doc/index.md @@ -10,5 +10,6 @@ DTail Documentation ## Advanced topics * The [DTail Query Language](./querylanguage.md) is the starting point to dig deeper into DTail's own SQL-like mapreduce language for extraction/aggregation stats from log files. +* The [Interactive Query Reload](../README.md#interactive-query-reload) section in the main README documents `:reload`, `:show`, `:help`, `:quit`, capability fallback on mixed-version servers, and session reuse semantics. * [Log Formats](./logformats.md) explains how to create your own custom log format for use with mapreduce queries. * Check out the [Testing Guide](./testing.md) for unit and integration testing. diff --git a/doc/installation.md b/doc/installation.md index 1f54050..c80e011 100644 --- a/doc/installation.md +++ b/doc/installation.md @@ -25,7 +25,17 @@ Set the `DTAIL_USE_ACL` environment variable before invoking the make command. % export DTAIL_USE_ACL=yes ``` -Alternatively, you could add `-tags linuxacl` to the Go compiler. +Alternatively, you could add `-tags linuxacl` to the Go compiler. + +## Build without zstd (optional) + +For targets where CGO-based zstd is unavailable (for example cross-compiling `dserver` for another architecture), build with the `nozstd` tag. Compressed `.zst` log files will not be supported in that binary. + +```console +% export DTAIL_NO_ZSTD=yes +``` + +This sets `-tags nozstd` via the Makefile. Plain `go build` users can pass `-tags nozstd` directly. # Install it @@ -61,15 +71,28 @@ uid=1001(dserver) 1001=670(dserver) groups=1001(dserver) sudo tee /etc/dserver/dtail.json ``` +### SSH listen address (``SSHBindAddress``) + +The example config sets ``Server.SSHBindAddress`` to ``0.0.0.0``, so dserver listens on **every** local IPv4 address, including your LAN (e.g. ``192.168.1.x`` on eth0) and any other interface (loopback, WireGuard, etc.). Clients reach it as ``:2222``; you do **not** need to change this for normal LAN access. + +To listen **only** on a specific address—for example only the home LAN and not on a VPN—set ``SSHBindAddress`` in ``/etc/dserver/dtail.json`` to **that machine’s** address (each host needs its own value), e.g. ``192.168.1.125`` on ``pi0``, ``192.168.1.126`` on ``pi1``. Alternatively, override from the command line (after ``-cfg``): ``dserver -cfg /etc/dserver/dtail.json -bindAddress 192.168.1.125``. Then reload or restart dserver. + 5. It is recommended to configure DTail server as a service to ``systemd``. An example unit file for ``systemd`` can be found [here](../examples/dserver.service.example). ```console % curl https://raw.githubusercontent.com/mimecast/dtail/master/examples/dserver.service.example | sudo tee /etc/systemd/system/dserver.service % sudo systemctl daemon-reload -% sudo systemctl enable dserver ``` +The unit is intended to stay **disabled** until you opt in. Start DTail server manually when needed: + +```console +% sudo systemctl start dserver +``` + +To start it automatically at boot, run once: `sudo systemctl enable dserver`. + # Start it To start the DTail server via ``systemd`` run: @@ -93,6 +116,20 @@ To start the DTail server via ``systemd`` run: Dec 06 13:21:24 serv-001.lan.example.org dserver[12296]: SERVER|serv-001|INFO|Binding server|1.2.3.4:2222 ``` +### Firewall (firewalld on RHEL, Rocky Linux, Fedora, …) + +The DTail server listens on TCP port ``2222`` (see ``SSHPort`` in ``dtail.json``). **ICMP (ping) may work while TCP to 2222 is blocked**, because host firewalls often allow ping but not arbitrary ports. + +If ``firewalld`` is active, allow the DTail port permanently and reload: + +```console +% sudo firewall-cmd --permanent --add-port=2222/tcp +% sudo firewall-cmd --reload +% sudo firewall-cmd --list-ports +``` + +Clients may report ``dial tcp …: connect: no route to host`` when the firewall rejects the connection with an ICMP unreachable—opening ``2222/tcp`` fixes that. For other firewalls (nftables, ufw, …), add an equivalent allow rule for ``2222/tcp``. A small helper script is [firewalld-dserver-port.sh.example](../examples/firewalld-dserver-port.sh.example). + # Register SSH public keys in DTail server The DTail server now runs as a ``systemd`` service under system user ``dserver``. However, the system user ``dserver`` has no permissions to read the SSH public keys from ``/home/USER/.ssh/authorized_keys``. Therefore, no user would be able to establish an SSH session to DTail server. As an alternative path DTail server also checks for public SSH key files in ``/var/run/dserver/cache/USER.authorized_keys``. @@ -113,6 +150,24 @@ It is recommended to execute [update_key_cache.sh](../examples/update_key_cache. % sudo systemctl start dserver-update-keycache.timer ``` +# Prune old dserver log files + +Log files live under ``/var/run/dserver/log`` (see ``LogDir`` in ``dtail.json``). To remove ``*.log`` files **older than seven days**, install [prune_dserver_logs.sh](../examples/prune_dserver_logs.sh.example) and a systemd timer (runs daily with a randomized delay): + +```console +% curl https://raw.githubusercontent.com/mimecast/dtail/master/examples/prune_dserver_logs.sh.example | + sudo tee /var/run/dserver/prune_dserver_logs.sh +% sudo chmod 755 /var/run/dserver/prune_dserver_logs.sh +% curl https://raw.githubusercontent.com/mimecast/dtail/master/examples/dserver-prune-logs.service.example | + sudo tee /etc/systemd/system/dserver-prune-logs.service +% curl https://raw.githubusercontent.com/mimecast/dtail/master/examples/dserver-prune-logs.timer.example | + sudo tee /etc/systemd/system/dserver-prune-logs.timer +% sudo systemctl daemon-reload +% sudo systemctl enable --now dserver-prune-logs.timer +``` + +The script uses ``find /var/run/dserver/log -type f -name '*.log' -mtime +7 -delete``. + # Run DTail client Now you should be able to use DTail client like outlined in the [Quick Starting Guide](quickstart.md). Also, have a look at the [Examples](examples.md). diff --git a/doc/logformats.md b/doc/logformats.md index dbf2051..29e2559 100644 --- a/doc/logformats.md +++ b/doc/logformats.md @@ -42,7 +42,7 @@ func newGenericKVParser(hostname, timeZoneName string, timeZoneOffset int) (*gen return &genericKVParser{defaultParser: *defaultParser}, nil } -func (p *genericKVParser) MakeFields(maprLine string) (map[string]string, error) { +func (p *genericKVParser) MakeFields(maprLine, _ string) (map[string]string, error) { splitted := strings.Split(maprLine, protocol.FieldDelimiter) fields := make(map[string]string, len(splitted)) @@ -70,6 +70,7 @@ func (p *genericKVParser) MakeFields(maprLine string) (map[string]string, error) ... whereas: * `maprLine` is the whole raw log line to be parsed by the log format. +* `sourceID` is the stable identifier of the log file / stream the line came from. Stateful parsers (e.g. CSV with a header row per file) should key their per-file state by this value; stateless parsers may ignore it. * `protocol.FieldDelimiter` is the field delimiter used by the log format, here: `|`. * All field names starting with `$` are variables. They store some custom values. * All other fields are bareword-fields and are extracted from the log lines directly, e.g. `field1=value1|field2=value2|...` @@ -139,7 +140,7 @@ func newFooParser(hostname, timeZoneName string, timeZoneOffset int) (*fooParser return &fooParser{defaultParser: *defaultParser}, nil } -func (p *fooParser) MakeFields(maprLine string) (map[string]string, error) { +func (p *fooParser) MakeFields(maprLine, sourceID string) (map[string]string, error) { fields := make(map[string]string, 3) .. diff --git a/doc/performance_optimization_summary.md b/doc/performance_optimization_summary.md new file mode 100644 index 0000000..e54d9a9 --- /dev/null +++ b/doc/performance_optimization_summary.md @@ -0,0 +1,69 @@ +# DTail Performance Optimization Summary + +> **Historical note:** This is a point-in-time record of a specific optimization +> effort (trace-logging and buffering fixes) with the measurements taken at that +> time; the numbers and file paths (e.g. `turbo_writer.go`, since renamed to +> `line_writer.go`) are preserved as-is. The "turbo mode" it compares against a +> "non-turbo mode" is now the single, default read/output path — there is no mode +> split any more, and the `DTAIL_TURBOBOOST_DISABLE` toggle has been removed. + +## Changes Made + +### 1. Optimized Trace Logging (`/internal/io/dlog/dlog.go`) + +**Problem**: The `Trace()` and `Devel()` functions were calling `runtime.Caller(1)` for every invocation, even when trace logging was disabled. This was causing ~497ns overhead per call. + +**Solution**: Added early level checks before the expensive `runtime.Caller()` operation: + +```go +func (d *DLog) Trace(args ...interface{}) string { + // Early check to avoid expensive runtime.Caller when trace is disabled + if d.maxLevel < Trace { + return "" + } + // ... rest of function +} +``` + +### 2. Improved Buffering in Turbo Mode (`/internal/server/handlers/turbo_writer.go`) + +**Problem**: Turbo mode was forcing immediate flush after every line in serverless mode, defeating the purpose of buffering. + +**Solution**: Removed the immediate flush condition for serverless mode, allowing proper buffering: + +```go +// Changed from: +if w.writeBuf.Len() >= w.bufSize || w.serverless { + return w.flushBuffer() +} + +// To: +if w.writeBuf.Len() >= w.bufSize { + return w.flushBuffer() +} +``` + +## Performance Results + +### Before Optimization +- Turbo mode was **3-5x slower** than non-turbo mode +- DCat (10MB): 678ms (turbo) vs 210ms (non-turbo) +- DGrep (10MB): 570ms (turbo) vs 96ms (non-turbo) + +### After Optimization +- Turbo mode is now **2.87x faster** than non-turbo mode +- DCat (1M lines): 0.66s (turbo) vs 1.89s (non-turbo) - **65% improvement** +- DCat with colors: 1.69s (turbo) vs 2.24s (non-turbo) - **24% improvement** + +## Verification +- ✅ All unit tests pass +- ✅ All integration tests pass +- ✅ No functionality regression +- ✅ Backward compatible + +## Files Modified +1. `/internal/io/dlog/dlog.go` - Lines 196-216 +2. `/internal/server/handlers/turbo_writer.go` - Lines 104-108 + +## Key Takeaway +The trace logging overhead was the primary bottleneck, causing DTail to spend more time logging than processing data. By adding simple level checks before expensive operations, we achieved a ~3x performance improvement in turbo mode. \ No newline at end of file diff --git a/doc/pgo_commands_detail.md b/doc/pgo_commands_detail.md new file mode 100644 index 0000000..e874ba8 --- /dev/null +++ b/doc/pgo_commands_detail.md @@ -0,0 +1,216 @@ +# PGO Command Execution Details + +This document shows the exact commands executed during Profile-Guided Optimization (PGO) generation for DTail tools. + +## Overview + +When running `make pgo-generate` or `dtail-tools pgo`, the following commands are executed to generate performance profiles for each tool. + +## Commands Executed + +### 1. Building Baseline Binaries + +```bash +go build -o pgo-build/dtail-baseline ./cmd/dtail +go build -o pgo-build/dcat-baseline ./cmd/dcat +go build -o pgo-build/dgrep-baseline ./cmd/dgrep +go build -o pgo-build/dmap-baseline ./cmd/dmap +go build -o pgo-build/dserver-baseline ./cmd/dserver +``` + +### 2. Profile Generation Commands + +#### DTail Profile Generation +```bash +# Background log writer process +bash -c "for i in {1..200}; do + level=$((i % 4)) + case $level in + 0) lvl=INFO;; + 1) lvl=WARN;; + 2) lvl=ERROR;; + 3) lvl=DEBUG;; + esac + echo \"[2025-07-04 15:00:00] $lvl - Test log line number $i with some additional text to process\" >> growing.log + sleep 0.015 +done" + +# DTail command +pgo-build/dtail-baseline \ + -cfg none \ + -plain \ + -profile \ + -profiledir pgo-profiles/iter_dtail_TIMESTAMP \ + -regex "ERROR|WARN" \ + -shutdownAfter 3 \ + pgo-profiles/growing.log +``` + +#### DCat Profile Generation +```bash +pgo-build/dcat-baseline \ + -cfg none \ + -plain \ + -profile \ + -profiledir pgo-profiles/iter_dcat_TIMESTAMP \ + pgo-profiles/test.log +``` + +#### DGrep Profile Generation +```bash +pgo-build/dgrep-baseline \ + -cfg none \ + -plain \ + -profile \ + -profiledir pgo-profiles/iter_dgrep_TIMESTAMP \ + -regex "ERROR|WARN" \ + pgo-profiles/test.log +``` + +#### DMap Profile Generation +```bash +pgo-build/dmap-baseline \ + -cfg none \ + -plain \ + -profile \ + -profiledir pgo-profiles/iter_dmap_TIMESTAMP \ + -files pgo-profiles/test.csv \ + -query "select status, count(*) group by status" +``` + +#### DServer Profile Generation +```bash +# Start dserver with pprof endpoint +pgo-build/dserver-baseline \ + -cfg none \ + -pprof localhost:16060 \ + -port 12222 + +# Client commands to generate server load (run concurrently): +pgo-build/dcat-baseline \ + -cfg none \ + -server localhost:12222 \ + pgo-profiles/test.log + +pgo-build/dgrep-baseline \ + -cfg none \ + -server localhost:12222 \ + -regex "ERROR|WARN" \ + pgo-profiles/test.log + +pgo-build/dgrep-baseline \ + -cfg none \ + -server localhost:12222 \ + -regex "INFO.*action" \ + pgo-profiles/test.log + +pgo-build/dmap-baseline \ + -cfg none \ + -server localhost:12222 \ + -files pgo-profiles/test.csv \ + -query "select status, count(*) group by status" + +pgo-build/dmap-baseline \ + -cfg none \ + -server localhost:12222 \ + -files pgo-profiles/test.csv \ + -query "select department, avg(salary) group by department" + +# Capture CPU profile via HTTP +curl http://localhost:16060/debug/pprof/profile?seconds=5 > dserver.pprof +``` + +### 3. Profile Merging + +When multiple iterations are run, profiles are merged: + +```bash +# Merge multiple profile iterations +go tool pprof -proto \ + pgo-profiles/dcat.pprof.0.pprof \ + pgo-profiles/dcat.pprof.1.pprof \ + > pgo-profiles/dcat.pprof +``` + +### 4. Building with PGO + +```bash +# Build optimized binaries using profiles +go build -pgo=pgo-profiles/dcat.pprof -o pgo-build/dcat ./cmd/dcat +go build -pgo=pgo-profiles/dgrep.pprof -o pgo-build/dgrep ./cmd/dgrep +go build -pgo=pgo-profiles/dmap.pprof -o pgo-build/dmap ./cmd/dmap +go build -pgo=pgo-profiles/dtail.pprof -o pgo-build/dtail ./cmd/dtail +go build -pgo=pgo-profiles/dserver.pprof -o pgo-build/dserver ./cmd/dserver +``` + +### 5. Performance Comparison Commands + +Quick benchmarks are run to compare baseline vs optimized: + +```bash +# Baseline benchmark +pgo-build/dcat-baseline -cfg none -plain /tmp/pgo_bench.log + +# Optimized benchmark +pgo-build/dcat -cfg none -plain /tmp/pgo_bench.log + +# Similar commands for dgrep and dmap +pgo-build/dgrep-baseline -cfg none -plain -regex ERROR /tmp/pgo_bench.log +pgo-build/dmap-baseline -cfg none -plain -files /tmp/pgo_bench.csv -query "select count(*)" +``` + +## Test Data Generation + +The PGO framework generates realistic test data: + +### Log File (test.log) +- Contains timestamps, log levels (INFO, WARN, ERROR, DEBUG) +- Includes user actions, durations, and status information +- Default size: 1,000,000 lines (configurable with -datasize) + +### CSV File (test.csv) +- Contains employee data with departments, salaries, status +- Used for MapReduce queries +- Default size: 100,000 rows (1/10 of log file size) + +### Growing Log File (growing.log) +- Used specifically for dtail testing +- Simulates real-time log generation +- Writes ~200 lines over 3 seconds with mixed log levels + +## Customization Options + +### Adjust Test Data Size +```bash +dtail-tools pgo -datasize 5000000 # 5 million lines +``` + +### Run More Iterations +```bash +dtail-tools pgo -iterations 5 # Run 5 iterations per command +``` + +### Profile Specific Commands Only +```bash +dtail-tools pgo dcat dgrep # Only optimize dcat and dgrep +``` + +### Verbose Output +```bash +dtail-tools pgo -v # Show all command execution details +``` + +### Profile Generation Only +```bash +dtail-tools pgo -profileonly # Skip building optimized binaries +``` + +## Notes + +1. **Empty Profiles**: Some commands (like dtail) may generate empty profiles if they are I/O-bound. This is handled gracefully. + +2. **DServer Profiling**: Uses HTTP pprof endpoint instead of command-line profiling to capture server-side performance data. + +3. **Concurrent Execution**: Multiple client commands are run concurrently against dserver to generate realistic load patterns. + +4. **Profile Quality**: The effectiveness of PGO depends on how well the test workload represents real-world usage patterns. \ No newline at end of file diff --git a/doc/pgo_implementation.md b/doc/pgo_implementation.md new file mode 100644 index 0000000..b404668 --- /dev/null +++ b/doc/pgo_implementation.md @@ -0,0 +1,173 @@ +# Profile-Guided Optimization (PGO) Implementation for DTail + +## Overview + +This document describes the Profile-Guided Optimization (PGO) implementation for DTail tools. PGO is a compiler optimization technique that uses runtime profiling data to guide optimization decisions, resulting in better performance for real-world usage patterns. + +## Implementation Details + +### Architecture + +The PGO implementation is integrated into the dtail-tools command as a subcommand: + +```bash +dtail-tools pgo [options] [commands...] +``` + +### Core Components + +1. **PGO Module** (`internal/tools/pgo/pgo.go`) + - Handles the complete PGO workflow + - Manages profile generation, merging, and PGO builds + - Provides performance comparison + +2. **Profiling Integration** + - All dtail commands now support the `-profile` flag + - dserver uses HTTP pprof endpoint for profiling + - Profiles are generated during realistic workloads + +3. **Makefile Integration** + - `make pgo` - Complete PGO workflow + - `make pgo-quick` - Quick PGO with smaller datasets + - `make pgo-generate` - Generate profiles only + - `make build-pgo` - Build with existing profiles + - `make install-pgo` - Install PGO-optimized binaries + +### Workflow + +1. **Build Baseline Binaries**: Standard Go builds without PGO +2. **Generate Profiles**: Run workloads to collect CPU profiles +3. **Merge Profiles**: Combine multiple profile iterations +4. **Build with PGO**: Use profiles to guide optimization +5. **Compare Performance**: Measure improvement + +### Profile Generation Details + +Each command has specific workloads designed to exercise common code paths: + +- **dcat**: Reading large log files +- **dgrep**: Pattern matching with various regex patterns +- **dmap**: MapReduce queries on CSV data +- **dtail**: Following growing log files with filtering +- **dserver**: Handling concurrent client connections + +### Special Handling + +1. **Empty Profiles**: I/O-bound operations may generate empty profiles. The implementation handles this gracefully by creating empty profile files that allow the workflow to continue. + +2. **dserver Profiling**: Uses HTTP pprof endpoint instead of command-line flags, allowing profile capture during server operation. + +3. **dtail Workload**: Simulates a growing log file with various log levels to exercise the tail functionality. + +## Performance Results + +Based on testing with PGO optimization: + +### Individual Command Improvements +- **dcat**: 3.75-5.40% improvement +- **dgrep**: Up to 19% improvement (varies by pattern hit rate) +- **dmap**: Up to 39% improvement for specific queries + +### Overall Performance Progression +From the original pre-optimization baseline to the current PGO-optimized build +(the channel-less read/output path, formerly called "turbo", is now the default +and only path): +- **dcat**: 14-21x faster overall +- **dgrep**: 9-15x faster overall +- **dmap**: 9-29% faster overall + +## Usage Examples + +### Generate PGO-Optimized Binaries +```bash +# Full PGO workflow +make pgo + +# Quick PGO with smaller datasets +make pgo-quick + +# Generate profiles only +make pgo-generate + +# Build with existing profiles +make build-pgo +``` + +### Using dtail-tools Directly +```bash +# Optimize all commands +dtail-tools pgo + +# Optimize specific commands +dtail-tools pgo dcat dgrep + +# Verbose mode with custom iterations +dtail-tools pgo -v -iterations 5 + +# Generate profiles only +dtail-tools pgo -profileonly +``` + +### Custom PGO Options +```bash +# Custom data size +dtail-tools pgo -datasize 5000000 + +# Custom profile directory +dtail-tools pgo -profiledir my-profiles + +# Custom output directory +dtail-tools pgo -outdir my-pgo-build +``` + +## Technical Considerations + +1. **Profile Quality**: The quality of PGO optimization depends on how representative the profiling workload is of real-world usage. + +2. **Binary Size**: PGO-optimized binaries may be slightly larger due to function cloning and inlining decisions. + +3. **Build Time**: Building with PGO takes longer than standard builds due to profile processing. + +4. **Go Version**: PGO requires Go 1.20 or later. + +## Integration with CI/CD + +To integrate PGO into your build pipeline: + +1. Generate profiles periodically with production-like workloads +2. Store profiles in version control or artifact repository +3. Use `make build-pgo` in your build process +4. Monitor performance metrics to validate improvements + +## Profile Files + +Profile files are stored in the `pgo-profiles/` directory: +- `dcat.pprof` - DCat CPU profile +- `dgrep.pprof` - DGrep CPU profile +- `dmap.pprof` - DMap CPU profile +- `dtail.pprof` - DTail CPU profile (may be empty for I/O-bound operations) +- `dserver.pprof` - DServer CPU profile + +## Troubleshooting + +### Empty Profiles +Some commands may generate empty profiles if they are I/O-bound. This is normal and the PGO workflow handles it gracefully. + +### Profile Merge Failures +If profile merging fails, check that: +- All profile files are valid +- Go tools are properly installed +- Sufficient disk space is available + +### Performance Not Improving +If PGO doesn't show improvement: +- Ensure profiles represent real workloads +- Check that the profile has sufficient samples +- Verify the correct profile is being used during build + +## Future Enhancements + +1. **Automated Profile Collection**: Collect profiles from production deployments +2. **Profile Versioning**: Track profile versions with code changes +3. **Multi-Architecture Support**: Generate architecture-specific profiles +4. **Continuous Profiling**: Regular profile updates based on usage patterns \ No newline at end of file diff --git a/doc/profiling.md b/doc/profiling.md new file mode 100644 index 0000000..7925fb3 --- /dev/null +++ b/doc/profiling.md @@ -0,0 +1,376 @@ +# DTail Profiling Framework + +This document describes the profiling framework for dtail commands (dcat, dgrep, dmap) to analyze CPU usage and memory allocations. + +## Overview + +The profiling framework provides: +- CPU profiling to identify performance bottlenecks +- Memory profiling to track allocations and detect leaks +- Integration with existing benchmarks +- Analysis tools for profile interpretation + +## Quick Start + +### 1. Build the Tools + +```bash +make build # Builds all tools including dprofile +``` + +### 2. Run Commands with Profiling + +Each command now supports profiling flags: + +```bash +# Profile dcat +./dcat -profile -profiledir profiles -plain -cfg none /path/to/file.log + +# Profile dgrep with specific profiling types +./dgrep -cpuprofile -memprofile -profiledir profiles -regex "error" /path/to/file.log + +# Profile dmap +./dmap -profile -query "select count(*) from data.csv" +``` + +### 3. Analyze Profiles + +Use dtail-tools for quick analysis: + +```bash +# List all profiles +./dtail-tools profile -mode list + +# Analyze a specific profile +./dtail-tools profile -mode analyze profiles/dcat_cpu_20240101_120000.prof + +# Open web browser with flame graph +./dtail-tools profile -mode analyze profiles/dcat_cpu_*.prof -web + +# You can also use go tool pprof directly: +go tool pprof profiles/dcat_cpu_20240101_120000.prof +``` + +## Profiling Options + +### Command-line Flags + +All dtail commands support these profiling flags: + +- `-cpuprofile`: Enable CPU profiling only +- `-memprofile`: Enable memory profiling only +- `-profile`: Enable both CPU and memory profiling +- `-profiledir `: Directory to store profiles (default: "profiles") + +### Profile Types + +1. **CPU Profile** (`*_cpu_*.prof`) + - Samples CPU usage during execution + - Identifies hot functions and code paths + - Useful for optimizing computational bottlenecks + +2. **Memory Profile** (`*_mem_*.prof`) + - Captures heap allocations at end of execution + - Shows memory usage by function + - Helps identify memory leaks + +3. **Allocation Profile** (`*_alloc_*.prof`) + - Tracks all allocations during execution + - More detailed than memory profile + - Useful for reducing allocation pressure + +## Using with Benchmarks + +### Automated Profiling + +Run profiling using dtail-tools: + +```bash +# Quick profiling with small datasets +./dtail-tools profile -mode quick + +# Full profiling suite +./dtail-tools profile -mode full + +# Profile dmap specifically (with MapReduce format) +./dtail-tools profile -mode dmap +``` + +This tool: +- Generates test data of various sizes +- Profiles dcat, dgrep, and dmap with different workloads +- Stores profiles in the `profiles` directory +- Provides immediate analysis of results + +### Using Make Targets + +```bash +# Quick profiling with immediate results +make profile-quick + +# Full profiling suite +make profile-all + +# Profile dmap specifically +make profile-dmap + +# List available profiles +make profile-list + +# Analyze a specific profile +make profile-analyze PROFILE=profiles/dcat_cpu_*.prof + +# Open web interface for profile +make profile-web PROFILE=profiles/dcat_cpu_*.prof +``` + +### Benchmark Integration + +Run profiling-enabled benchmarks: + +```bash +cd benchmarks +go test -bench="WithProfiling" -benchtime=1x +``` + +### Custom Profile Runner + +Use the profile runner in your benchmarks: + +```go +import "github.com/mimecast/dtail/benchmarks" + +func BenchmarkMyFeature(b *testing.B) { + benchmarks.ProfileBenchmark(b, "MyFeature", "dcat", + "--plain", "--cfg", "none", "testfile.log") +} +``` + +## Profile Analysis + +### Using go tool pprof + +For interactive analysis: + +```bash +# Interactive mode +go tool pprof profiles/dcat_cpu_*.prof + +# Common pprof commands: +# top - Show top functions +# list func - Show source code for function +# web - Generate SVG graph +# peek func - Show callers/callees of function +``` + +Generate visualizations: + +```bash +# Flame graph (requires graphviz) +go tool pprof -http=:8080 profiles/dcat_cpu_*.prof + +# Generate SVG +go tool pprof -svg profiles/dgrep_mem_*.prof > profile.svg + +# Generate text report +go tool pprof -text profiles/dmap_alloc_*.prof > report.txt +``` + +### Using dtail-tools profile + +The dtail-tools profile command provides quick summaries: + +```bash +# List all profiles +./dtail-tools profile -mode list + +# Analyze specific profile +./dtail-tools profile -mode analyze profiles/dcat_cpu_20240101_120000.prof + +# Get help +./dtail-tools profile -h +``` + +## Optimization Workflow + +1. **Baseline Performance** + ```bash + # Run benchmarks without profiling + cd benchmarks + go test -bench="BenchmarkDCat" -benchtime=10s + ``` + +2. **Profile Execution** + ```bash + # Run with profiling + ./dcat -profile -profiledir profiles large_file.log + ``` + +3. **Identify Bottlenecks** + ```bash + # Analyze CPU profile + ./dprofile -profile profiles/dcat_cpu_*.prof -top 10 + + # Check memory allocations + go tool pprof -alloc_space profiles/dcat_alloc_*.prof + ``` + +4. **Optimize Code** + - Focus on functions with high Flat% (direct CPU usage) + - Reduce allocations in hot paths + - Consider buffering and pooling + +5. **Verify Improvements** + ```bash + # Re-run benchmarks after optimization + go test -bench="BenchmarkDCat" -benchtime=10s + ``` + +## Common Performance Issues + +### CPU Bottlenecks + +Look for: +- Regex compilation in loops +- Excessive string operations +- Inefficient algorithms (O(n²) or worse) +- Unnecessary type conversions + +Example optimization: +```go +// Before: Regex compiled every time +for _, line := range lines { + if regexp.MustCompile(pattern).MatchString(line) { + // ... + } +} + +// After: Compile once +re := regexp.MustCompile(pattern) +for _, line := range lines { + if re.MatchString(line) { + // ... + } +} +``` + +### Memory Issues + +Common patterns: +- String concatenation in loops +- Large temporary slices +- Unclosed resources +- Excessive goroutines + +Example optimization: +```go +// Before: Many allocations +result := "" +for _, s := range strings { + result += s + "\n" +} + +// After: Single allocation +var buf strings.Builder +buf.Grow(estimatedSize) +for _, s := range strings { + buf.WriteString(s) + buf.WriteByte('\n') +} +result := buf.String() +``` + +## Tips and Best Practices + +1. **Profile Real Workloads** + - Use production-like data sizes + - Test with actual file formats + - Include network operations if relevant + +2. **Compare Profiles** + ```bash + # Compare before/after optimization + go tool pprof -diff_base=before.prof after.prof + ``` + +3. **Focus on Hot Paths** + - Optimize functions with >5% CPU usage first + - Small improvements in hot paths have big impact + +4. **Memory Profiling** + - Use `-alloc_space` for total allocations + - Use `-inuse_space` for current heap usage + - Check for growing heap over time + +5. **Benchmark Regularly** + - Add profiling to CI/CD pipeline + - Track performance over releases + - Set performance regression alerts + +## Troubleshooting + +### No profiles generated +- Check write permissions for profile directory +- Ensure command completes successfully +- Verify profiling flags are correct + +### Empty or small profiles +- Run command with larger workload +- Increase execution time +- Check if command exits too quickly + +### Analysis tools fail +- Ensure profile format is valid +- Check Go version compatibility +- Verify graphviz is installed for visualizations + +## Advanced Usage + +### Custom Profiling Points + +Add profiling snapshots in code: + +```go +import "github.com/mimecast/dtail/internal/profiling" + +func processLargeFile() { + profiler := profiling.GetProfiler() // Assumes global profiler + + // Take memory snapshot before processing + profiler.Snapshot("before_processing") + + // ... process file ... + + // Take snapshot after + profiler.Snapshot("after_processing") +} +``` + +### Continuous Profiling + +For long-running operations: + +```go +// Start periodic metrics logging +ticker := time.NewTicker(30 * time.Second) +go func() { + for range ticker.C { + profiler.LogMetrics("periodic") + } +}() +defer ticker.Stop() +``` + +## Contributing + +When adding new features: +1. Include benchmark tests +2. Run profiling before submitting PR +3. Document any performance implications +4. Add profiling examples for new commands + +## References + +- [Go Profiling Documentation](https://go.dev/blog/pprof) +- [pprof Tool Guide](https://github.com/google/pprof) +- [Go Performance Tips](https://go.dev/wiki/Performance) \ No newline at end of file diff --git a/doc/querylanguage.md b/doc/querylanguage.md index c3e567e..a405f35 100644 --- a/doc/querylanguage.md +++ b/doc/querylanguage.md @@ -52,7 +52,7 @@ STRINGOPERATOR := eq|ne|contains|ncontains|lacks|hasprefix|nhasprefix|hassuffix| ORDERFIELD := FIELD|AGGREGATION(FIELD) SET := $VARIABLE = FLOAT|STRING|FIELD|FUNCTION(FIELD) LOGFORMAT := default|generic|generickv|... -AGGREGATION := count|sum|min|max|avg|last|len +AGGREGATION := count|sum|min|max|avg|last|len|percentage|percentile FUNCTION := md5sum|maskdigits ``` @@ -61,3 +61,41 @@ FUNCTION := md5sum|maskdigits * `rorder` stands for reverse order. * `lacks` is an alias for `ncontains` (not contains). * Available fields (variables and barewords) vary from the log format used. Check out the [log format](./logformats.md) documentation for more information. +* `percentage(field)` returns the selected group's share of the total for that field across all groups. For non-negative inputs, the result is between 0 and 100; with mixed positive and negative values, it can fall outside that range. +* `percentile(field)` returns the percentile rank of the selected group's value among all grouped values for that field, also expressed as a value between 0 and 100. Equal values share the same rank. + +## Selecting the log format and dynamic fields + +Two things commonly trip people up when a `$field`-style reference "does not +resolve" while positional/built-in fields work. Both are by design: + +1. **Dynamic `key=value` fields are barewords, not `$`-variables.** A log line + like `...|service=web|bytes=100` exposes `service` and `bytes` as *barewords*. + Query them as `select service,sum(bytes)` — **not** `$service`/`$bytes`. The + `$` prefix is reserved for values DTail sets itself (e.g. `$time`, `$hostname`, + `$line`). A `$name` that is not one of those built-ins silently resolves to + the empty string, which is exactly what "did not resolve" looks like: + everything collapses into a single empty group. To catch this early, the + client prints a plan-time warning to stderr for every `$`-variable the + selected parser cannot populate, e.g. + `warning: $service is not a known variable for log format "default"; did you + mean bareword service?`. It is only a warning (resolution behaviour is + unchanged), and it is never emitted for barewords, for built-ins like + `$empty`, or for variables defined via a `set` clause. + +2. **The `from TABLE` clause selects the rich parser.** Although `from TABLE` is + written as optional in the grammar above, omitting it (and not passing an + explicit `logformat`) downgrades the query to the `generic` log format, which + exposes only the common variables (`$line`, `$hostname`, ...) and **no** + dynamic `key=value` fields and **no** default-format `$`-variables such as + `$time`. To query DTail's own default-format logs (lines containing + `MAPREDUCE:STATS`), use `from STATS`, for example: + + ```shell + % dmap --files /var/log/dserver/dserver.log \ + --query 'from STATS select $hostname,max($goroutines),lifetimeConnections group by $hostname' + ``` + + Alternatively, name the parser explicitly with the `logformat` keyword (e.g. + `logformat generickv`), which works regardless of the `from` clause. See the + [log formats](./logformats.md) documentation for details. diff --git a/doc/refactoring_guide.md b/doc/refactoring_guide.md new file mode 100644 index 0000000..88c77d5 --- /dev/null +++ b/doc/refactoring_guide.md @@ -0,0 +1,240 @@ +# Integration Tests Refactoring Guide + +## Overview + +This guide outlines the refactoring opportunities for the dtail integration tests to reduce code duplication and improve maintainability. + +## Key Benefits of Refactoring + +1. **Reduced Code Duplication**: ~40-50% reduction in test code +2. **Improved Maintainability**: Changes to common patterns only need to be made in one place +3. **Better Test Hygiene**: Automatic cleanup using `t.Cleanup()` +4. **Clearer Test Intent**: Helper functions make tests more readable +5. **Reduced Copy-Paste Errors**: Less boilerplate to copy incorrectly + +## Common Patterns Identified + +### 1. Test Skip Pattern +**Before:** +```go +if !config.Env("DTAIL_INTEGRATION_TEST_RUN_MODE") { + t.Log("Skipping") + return +} +``` + +**After:** +```go +skipIfNotIntegrationTest(t) +``` + +### 2. Server Setup Pattern +**Before:** +```go +port := getUniquePortNumber() +bindAddress := "localhost" +ctx, cancel := context.WithCancel(context.Background()) +defer cancel() + +_, _, _, err := startCommand(ctx, t, + "", "../dserver", + "--cfg", "none", + "--logger", "stdout", + "--logLevel", "error", + "--bindAddress", bindAddress, + "--port", fmt.Sprintf("%d", port), +) +if err != nil { + t.Error(err) + return +} +time.Sleep(500 * time.Millisecond) +``` + +**After:** +```go +server := NewTestServer(t) +if err := server.Start("error"); err != nil { + t.Error(err) + return +} +``` + +### 3. File Cleanup Pattern +**Before:** +```go +defer os.Remove(outFile) +defer os.Remove(csvFile) +defer os.Remove(queryFile) +``` + +**After:** +```go +cleanupFiles(t, outFile, csvFile, queryFile) +// or +fileSet := &TestFileSet{...} +fileSet.Cleanup(t) +``` + +### 4. Command Arguments Pattern +**Before:** +```go +args := []string{ + "--plain", "--cfg", "none", + "--servers", fmt.Sprintf("%s:%d", bindAddress, port), + "--trustAllHosts", "--noColor", + "--files", inFile, +} +``` + +**After:** +```go +args := NewCommandArgs() +args.Plain = true +args.Servers = []string{server.Address()} +args.TrustAllHosts = true +args.NoColor = true +args.Files = []string{inFile} +// args.ToSlice() produces the string array +``` + +### 5. Dual Mode Testing Pattern +**Before:** +```go +func TestX(t *testing.T) { + if !config.Env("DTAIL_INTEGRATION_TEST_RUN_MODE") { + t.Log("Skipping") + return + } + + t.Run("Serverless", func(t *testing.T) { + testXServerless(t) + }) + + t.Run("ServerMode", func(t *testing.T) { + testXWithServer(t) + }) +} +``` + +**After:** +```go +func TestX(t *testing.T) { + runDualModeTest(t, DualModeTest{ + Name: "TestX", + ServerlessTest: testXServerless, + ServerTest: testXWithServer, + }) +} +``` + +## Refactoring Strategy + +### Phase 1: Add Helper Functions +1. Add `testhelpers.go` with all common utilities +2. Ensure all tests still pass + +### Phase 2: Refactor Test by Test +1. Start with simpler tests (e.g., dcat_test.go) +2. Refactor one test function at a time +3. Run tests after each refactoring +4. Commit after each file is complete + +### Phase 3: Additional Improvements +1. Add table-driven tests where appropriate +2. Create test fixtures for common scenarios +3. Add more sophisticated helpers as patterns emerge + +## Example Refactoring Results + +### Before (TestDCat1WithServer): +```go +func testDCat1WithServer(t *testing.T, inFile string) error { + outFile := "dcat1.out" + port := getUniquePortNumber() + bindAddress := "localhost" + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + _, _, _, err := startCommand(ctx, t, + "", "../dserver", + "--cfg", "none", + "--logger", "stdout", + "--logLevel", "error", + "--bindAddress", bindAddress, + "--port", fmt.Sprintf("%d", port), + ) + if err != nil { + return err + } + + time.Sleep(500 * time.Millisecond) + + _, err = runCommand(ctx, t, outFile, + "../dcat", "--plain", "--cfg", "none", + "--servers", fmt.Sprintf("%s:%d", bindAddress, port), + "--files", inFile, + "--trustAllHosts", + "--noColor") + if err != nil { + return err + } + + cancel() + + if err := compareFiles(t, outFile, inFile); err != nil { + return err + } + + os.Remove(outFile) + return nil +} +``` + +### After: +```go +func testDCat1WithServer_Refactored(t *testing.T, inFile string) { + fileSet := &TestFileSet{ + InputFile: inFile, + OutputFile: "dcat1.out", + ExpectedFile: inFile, + } + fileSet.Cleanup(t) + + server := NewTestServer(t) + if err := server.Start("error"); err != nil { + t.Error(err) + return + } + + args := NewCommandArgs() + args.Plain = true + args.Servers = []string{server.Address()} + args.Files = []string{inFile} + args.TrustAllHosts = true + args.NoColor = true + + err := runCommandAndVerify(t, server.ctx, fileSet.OutputFile, fileSet.ExpectedFile, + "../dcat", args.ToSlice()...) + if err != nil { + t.Error(err) + } +} +``` + +## Metrics + +Based on the examples: +- **Lines of code reduction**: ~45% +- **Boilerplate elimination**: ~70% +- **Improved readability**: Subjective but significant +- **Error-prone patterns eliminated**: Port management, cleanup, context handling + +## Next Steps + +1. Review and approve the helper functions +2. Create a PR with `testhelpers.go` +3. Incrementally refactor tests in separate PRs +4. Document any new patterns that emerge +5. Consider creating a test generator for common scenarios \ No newline at end of file diff --git a/doc/turbo_performance_analysis.md b/doc/turbo_performance_analysis.md new file mode 100644 index 0000000..e3b04f0 --- /dev/null +++ b/doc/turbo_performance_analysis.md @@ -0,0 +1,104 @@ +# Turbo Mode Performance Analysis + +> **Historical note:** This is a point-in-time benchmark record (July 2025) +> comparing the pre-optimization v4.3.0 baseline against the then-new +> "turbo boost" path. The numbers below are preserved as measured. Since then the +> turbo path has become the single, default read/output path: there is no +> "turbo vs non-turbo" mode split, the `DTAIL_TURBOBOOST_DISABLE` environment +> variable and the `TurboBoostDisable` config field have been removed (the env var +> is now inert), and the config tuning knobs moved to the `Output*` namespace +> (see `internal/config/server.go`). Read the "Configuration" and +> "Recommendations" sections below in that historical light. + +## Overview + +This document presents a comprehensive performance analysis comparing DTail v4.3.0 (before turbo mode) with the current implementation that has turbo boost mode enabled by default. + +## Methodology + +### Benchmark Environment +- **CPU**: 11th Gen Intel(R) Core(TM) i7-1185G7 @ 3.00GHz +- **Architecture**: linux/amd64 +- **Date**: July 4, 2025 + +### Files Compared +1. **Baseline (v4.3.0)**: `benchmarks/baselines/baseline_20250626_103142_v4.3.0.txt` + - Git commit: 41ec9cf + - Date: June 26, 2025 + - Turbo mode: Not implemented + +2. **Current (Turbo-enabled)**: `benchmarks/baselines/baseline_20250704_130947_turbo-enabled.txt` + - Date: July 4, 2025 + - Turbo mode: Enabled by default + +### Benchmark Suite +The comparison uses the "BenchmarkQuick" suite which includes: +- DCat operations on 10MB files +- DGrep operations with varying hit rates (1%, 10%, 50%, 90%) +- DMap queries (count, sum/avg, min/max, multi-field) + +## Performance Results + +### DCat Performance +| Metric | v4.3.0 | Turbo-Enabled | Improvement | +|--------|--------|---------------|-------------| +| Throughput | 9.363 MB/sec | 246.8 MB/sec | **2,535%** | +| Lines/sec | 165,106 | 4,367,374 | **2,546%** | + +### DGrep Performance +| Hit Rate | v4.3.0 (MB/s) | Turbo (MB/s) | Improvement | +|----------|---------------|--------------|-------------| +| 1% | 25.38 | 363.9 | **1,334%** | +| 10% | 22.81 | 342.6 | **1,402%** | +| 50% | 16.14 | 265.1 | **1,543%** | +| 90% | 10.99 | 210.0 | **1,811%** | + +### DMap Performance +| Query Type | v4.3.0 (MB/s) | Turbo (MB/s) | Improvement | +|------------|---------------|--------------|-------------| +| Count | 17.09 | 21.77 | **27.4%** | +| Sum/Avg | 13.54 | 21.05 | **55.5%** | +| Min/Max | 17.46 | 21.80 | **24.9%** | +| Multi-field | 21.85 | 21.32 | -2.4% | + +## Technical Implementation + +### Turbo Mode Optimizations + +1. **Direct Output Operations (DCat/DGrep/DTail)** + - Bypasses channel-based communication + - Writes directly to output streams + - Eliminates goroutine coordination overhead + +2. **MapReduce Server Mode** + - Direct line processing without channels + - Batch processing to reduce lock contention + - Memory pooling to minimize GC pressure + - Channel recycling with proper draining + +3. **Configuration** + - Enabled by default + - Can be disabled via `DTAIL_TURBOBOOST_DISABLE=yes` + - Configurable via `TurboBoostDisable` in config file + +## Key Insights + +1. **Exceptional I/O Performance**: The most dramatic improvements are in I/O-bound operations (DCat and DGrep), with performance gains of 14-26x. + +2. **Scalable Hit Rate Performance**: DGrep performance improvements increase with higher hit rates, showing the efficiency of direct output handling. + +3. **Moderate MapReduce Gains**: While not as dramatic as I/O operations, MapReduce queries still show meaningful improvements of 25-55% for most query types. + +4. **Production Ready**: The consistent improvements across all workload types demonstrate that turbo mode is stable and ready for production use. + +## Recommendations + +1. **Keep Turbo Mode as Default**: The performance benefits far outweigh any complexity costs. + +2. **Monitor High-Concurrency Workloads**: While turbo mode shows excellent performance, monitor behavior under extreme concurrent load. + +3. **Consider Further Optimizations**: The success of turbo mode suggests that similar optimizations might benefit other code paths. + +## Conclusion + +The implementation of turbo boost mode represents a significant performance milestone for DTail, delivering order-of-magnitude improvements for common operations while maintaining compatibility and stability. \ No newline at end of file diff --git a/doc/turboboost_optimization.md b/doc/turboboost_optimization.md new file mode 100644 index 0000000..f8d6706 --- /dev/null +++ b/doc/turboboost_optimization.md @@ -0,0 +1,117 @@ +# DTail Channel-less Read/Output Path (formerly "Turbo Boost") + +## Overview + +This document describes DTail's channel-less read/output path. It was originally +introduced as an opt-out "turbo boost" optimization, but it is now the single, +default processing path for all read/output operations. It improves performance +by using channel-less processing and optimized I/O. The on/off toggles described +in early revisions of this document (`DTAIL_TURBOBOOST_DISABLE`, +`DTAIL_CHANNELLESS_GREP`, `DTAIL_OPTIMIZED_READER`) have been removed; the +channel-less path is now unconditional. + +## Problem Statement + +The original dgrep implementation used multiple channels in a pipeline: +- `rawLines chan *bytes.Buffer` (buffer: 100) - Raw lines read from file +- `lines chan *line.Line` (buffer: 100) - Filtered lines to send to client + +This created several performance issues: +1. Fixed channel buffer sizes causing blocking under high throughput +2. Context switching overhead between goroutines +3. Channel synchronization overhead +4. Memory allocations for channel operations + +## Solution + +The channel-less implementation replaces the channel pipeline with direct function calls using a `LineProcessor` interface. + +### Key Components + +1. **LineProcessor Interface** (`internal/io/line/processor.go`) + - Defines methods for processing lines without channels + - `ProcessLine()` - Handle a single line + - `Flush()` - Ensure buffered data is written + - `Close()` - Clean up resources + +2. **GrepLineProcessor** (`internal/server/handlers/lineprocessor.go`) + - Implements LineProcessor for grep operations + - Writes directly to the network connection + - Uses internal buffering for efficiency (64KB buffer) + - Thread-safe with mutex protection + +3. **Modified File Reading** (`internal/io/fs/readfile_processor.go`) + - `StartWithProcessor()` - Channel-less file reading + - Direct callbacks instead of channel sends + - Inline regex filtering without goroutines + +4. **Optimized File Reading** (`internal/io/fs/readfile_processor_optimized.go`) + - Uses buffered line reading instead of byte-by-byte + - Custom scanner with 256KB buffer + - Efficient handling of long lines + - Special optimization for tail mode + +### Feature Flags (historical — removed) + +Early revisions gated this work behind opt-in environment variables +(`DTAIL_CHANNELLESS_GREP`, `DTAIL_OPTIMIZED_READER`). These no longer exist: the +channel-less, optimized read path is always on and cannot be toggled. + +### Benefits + +1. **Reduced Latency**: No channel queuing delays +2. **Lower Memory Usage**: No channel buffers +3. **Better CPU Efficiency**: Fewer context switches +4. **Simpler Code Flow**: Direct processing without goroutine coordination +5. **Predictable Performance**: No channel blocking + +### Compatibility + +- The original channel-based implementation has since been removed; the + channel-less path is the only one. +- Same command-line interface +- Protocol compatibility maintained +- All integration tests pass + +### Performance Testing + +Use the provided script to compare performance: + +```bash +./test_channelless_performance.sh +``` + +This will test: +1. Original channel-based implementation +2. Channel-less implementation +3. Optimized channel-less implementation + +### Usage + +The channel-less path is always active; no environment variables are needed: + +```bash +# Run dgrep normally — the channel-less, optimized path is used automatically +dgrep -regex "pattern" file.log +``` + +### Future Improvements + +1. Extend channel-less approach to other commands (dcat, dtail) +2. Add configurable buffer sizes +3. Implement zero-copy optimizations +4. Add performance metrics collection +5. Consider using io_uring on Linux for async I/O + +## Summary + +The channel-less path is always on — there is no enable/disable switch. The +former `DTAIL_TURBOBOOST_DISABLE` environment variable and the +`Server.TurboBoostDisable` config field have been removed; +`DTAIL_TURBOBOOST_DISABLE` is now inert and an old config still carrying a +`TurboBoostDisable` key is silently ignored. + +The path provides: +- Channel-less processing for grep and cat operations +- Optimized buffered I/O reader (256KB buffer) +- Buffer pooling to reduce memory allocations -- cgit v1.2.3