performance improvements part 2

baseline-results.csv

@@ -0,0 +1,16 @@
+command,mean,stddev,median,user,system,min,max
+01-passthrough-tsv,0.66335433384,0.01682146201750171,0.66601856204,0.5140556199999999,0.14985426,0.64621943104,0.68657031004
+02-passthrough-json,1.32866054724,0.03433318243449869,1.32225606504,1.01681782,0.31346366,1.2809032550400001,1.36213361704
+03-line-filter-tsv,1.9981326990400003,0.022830074964112598,1.99742874204,1.84471542,0.15384405999999998,1.97727274404,2.03358676504
+04-line-filter-json,4.60715976144,0.1819041054682861,4.61132453404,4.05177522,0.55677266,4.35345054604,4.788800295040001
+05-at-column-filter-tsv,1.7714589674400003,0.00904163024753627,1.77316088004,1.56909762,0.20349725999999996,1.75959619604,1.78390190004
+06-at-column-filter-json,9.176219561439998,0.12270907337465913,9.21773630004,8.385497619999999,0.77066646,8.969152809039999,9.293088575039999
+07-atat-column-filter-tsv,2.11805135724,0.023085245503879803,2.12826743904,1.92706882,0.19230966,2.08036520804,2.13831083404
+08-atat-column-filter-json,9.328013240239999,0.24676947367829533,9.414504064039999,8.55142022,0.77987606,8.905050726039999,9.53294901204
+09-mutator-tsv,6.018914668906667,0.1338733140062458,6.08180925124,5.800859113333334,0.21936123333333332,5.86517564524,6.10975911024
+10-mutator-json,22.98265302388667,0.3160655408217702,22.84062220122,22.511812719999998,0.4732879266666667,22.76251922922,23.34481764122
+11-mutator-filter-tsv,3.8698376845533335,0.06932762152645182,3.8913622022200003,3.6719947199999994,0.19787892666666665,3.79230087622,3.9258499752200002
+12-mutator-filter-json,18.705930759886666,0.1697635546411535,18.78274739422,18.00068872,0.70838526,18.51133643822,18.82370844722
+13-format-zeek-to-json,24.628451007886667,0.15874012321473524,24.56034414322,24.373273386666668,0.25756992666666667,24.515129008219997,24.809879872219998
+14-format-json-to-zeek,9.503400084219999,0.2628510924230409,9.58666781522,8.847611053333331,0.65929826,9.20900039722,9.71453204022
+

bench.lisp

@@ -0,0 +1,149 @@
+(asdf:load-system :cleek)
+
+(in-package :cleek)
+
+(require :sb-sprof)
+
+(defparameter *bench-zeek-input*
+  (asdf:system-relative-pathname "cleek" "data/test-input/homenet-uncompressed.zeek.log"))
+
+(defparameter *bench-json-input*
+  (asdf:system-relative-pathname "cleek" "data/test-input/homenet-uncompressed.json.log"))
+
+;;; --- Timing infrastructure (mirrors perf.lisp:my-time) ---
+
+(defmacro bench-time (&body body)
+  "Execute BODY and return (values result seconds bytes-consed)."
+  `(let ((start-bytes (sb-ext:get-bytes-consed))
+         (start-time (get-internal-real-time)))
+     (let ((result (progn ,@body)))
+       (let ((elapsed-seconds (/ (- (get-internal-real-time) start-time)
+                                 (float internal-time-units-per-second 1.0d0)))
+             (bytes (- (sb-ext:get-bytes-consed) start-bytes)))
+         (values result elapsed-seconds bytes)))))
+
+(defun run-bench (name n thunk)
+  "Run THUNK N times, report timing as CSV row to *standard-output*."
+  (sb-ext:gc :full t)
+  (multiple-value-bind (_result elapsed bytes)
+      (bench-time (dotimes (_ n) (funcall thunk)))
+    (declare (ignore _result))
+    (format t "~a,~a,~,6f,~d,~,6f~%"
+            name n elapsed bytes (/ elapsed n))))
+
+;;; --- Function-level benchmarks ---
+
+(defun bench-ensure-row-strings (&optional (n 3))
+  (with-zeek-log (log *bench-zeek-input* '(:proto))
+    (run-bench "ensure-row-strings" n
+               (lambda ()
+                 (loop while (zeek-line log)
+                       do (setf (zeek-status log) :unparsed)
+                          (ensure-row-strings log)
+                          (next-record log))))))
+
+(defun bench-parse-zeek-type (&optional (n 100000))
+  (run-bench "parse-zeek-type" n
+             (lambda ()
+               (parse-zeek-type "1623187704.078114" :time)
+               (parse-zeek-type "48610" :port)
+               (parse-zeek-type "140.249.20.119" :addr)
+               (parse-zeek-type "tcp" :enum)
+               (parse-zeek-type "12345" :count))))
+
+(defun bench-ensure-map-zeek (&optional (n 3))
+  (with-zeek-log (log *bench-zeek-input* '(:proto))
+    (run-bench "ensure-map-zeek" n
+               (lambda ()
+                 (loop while (zeek-line log)
+                       do (setf (zeek-status log) :unparsed)
+                          (clrhash (zeek-map log))
+                          (ensure-map log)
+                          (next-record log))))))
+
+(defun bench-ensure-map-json (&optional (n 3))
+  (with-zeek-log (log *bench-json-input* '(:proto))
+    (run-bench "ensure-map-json" n
+               (lambda ()
+                 (loop while (zeek-line log)
+                       do (setf (zeek-status log) :unparsed)
+                          (clrhash (zeek-map log))
+                          (ensure-map log)
+                          (next-record log))))))
+
+(defun bench-write-zeek-log-line (&optional (n 3))
+  (with-zeek-log (log *bench-zeek-input* '(:proto))
+    (with-open-file (out "/dev/null" :direction :output :if-exists :supersede)
+      (run-bench "write-zeek-log-line" n
+                 (lambda ()
+                   (loop while (zeek-line log)
+                         do (write-zeek-log-line log out :zeek)
+                            (next-record log)))))))
+
+(defun bench-next-record (&optional (n 3))
+  (with-zeek-log (log *bench-zeek-input*)
+    (run-bench "next-record" n
+               (lambda ()
+                 (loop while (zeek-line log) do (next-record log))))))
+
+(defun run-all-function-benchmarks (&optional (output-path "bench-results.csv"))
+  "Run all function-level benchmarks and write CSV to OUTPUT-PATH."
+  (with-open-file (*standard-output* output-path :direction :output :if-exists :supersede)
+    (format t "benchmark,iterations,total_seconds,bytes_consed,seconds_per_iteration~%")
+    (bench-ensure-row-strings)
+    (bench-parse-zeek-type)
+    (bench-ensure-map-zeek)
+    (bench-ensure-map-json)
+    (bench-write-zeek-log-line)
+    (bench-next-record))
+  (format *error-output* "Function benchmarks written to ~a~%" output-path))
+
+;;; --- sb-sprof profiling ---
+
+(defun profile-function (name thunk)
+  "Profile THUNK with sb-sprof. NAME is for display only."
+  (format t "~%=== Profiling: ~a ===~%" name)
+  (sb-sprof:with-profiling (:report :graph :sample-interval 0.001)
+    (funcall thunk)))
+
+(defun profile-passthrough-zeek ()
+  (profile-function "passthrough-zeek"
+    (lambda () (cat-logs-string #P"/dev/null" :zeek nil nil *bench-zeek-input*))))
+
+(defun profile-passthrough-json ()
+  (profile-function "passthrough-json"
+    (lambda () (cat-logs-string #P"/dev/null" :json nil nil *bench-json-input*))))
+
+(defun profile-filter-zeek ()
+  (profile-function "filter-@@-zeek"
+    (lambda () (cat-logs-string #P"/dev/null" :zeek nil
+                                "(and (plusp @@orig_bytes) (plusp @@resp_bytes))"
+                                *bench-zeek-input*))))
+
+(defun profile-filter-json ()
+  (profile-function "filter-@@-json"
+    (lambda () (cat-logs-string #P"/dev/null" :json nil
+                                "(and (plusp @@orig_bytes) (plusp @@resp_bytes))"
+                                *bench-json-input*))))
+
+(defun profile-mutator-zeek ()
+  (profile-function "mutator-zeek"
+    (lambda () (cat-logs-string #P"/dev/null" :zeek
+                                "(anonip! @id.orig_h @id.resp_h)" nil
+                                *bench-zeek-input*))))
+
+(defun profile-format-conversion ()
+  (profile-function "zeek->json"
+    (lambda () (cat-logs-string #P"/dev/null" :json nil nil *bench-zeek-input*))))
+
+(defun run-all-profiles ()
+  "Run sb-sprof profiling on key scenarios."
+  (profile-passthrough-zeek)
+  (sb-ext:gc :full t)
+  (profile-passthrough-json)
+  (sb-ext:gc :full t)
+  (profile-filter-zeek)
+  (sb-ext:gc :full t)
+  (profile-mutator-zeek)
+  (sb-ext:gc :full t)
+  (profile-format-conversion))

benchmark.sh

@@ -0,0 +1,116 @@
+#!/bin/bash
+# A/B benchmark suite for comparing two cleek binaries using hyperfine.
+#
+# Usage: bash benchmark.sh [CLEEK_A] [CLEEK_B]
+#
+# Defaults:
+#   CLEEK_A = bin/cleek
+#   CLEEK_B = bin/cleek.old
+#
+# Prerequisites:
+#   - hyperfine installed (https://github.com/sharkdp/hyperfine)
+#   - Both binaries built
+#   - data/test-input/homenet-uncompressed.{zeek,json}.log present
+
+set -euo pipefail
+
+SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)"
+CLEEK_A="${1:-${SCRIPT_DIR}/bin/cleek}"
+CLEEK_B="${2:-${SCRIPT_DIR}/bin/cleek.old}"
+ZEEK_INPUT="${SCRIPT_DIR}/data/test-input/homenet-uncompressed.zeek.log"
+JSON_INPUT="${SCRIPT_DIR}/data/test-input/homenet-uncompressed.json.log"
+
+# --- Preflight checks ---
+if ! command -v hyperfine &>/dev/null; then
+    echo "ERROR: hyperfine not found. Install from https://github.com/sharkdp/hyperfine" >&2
+    exit 1
+fi
+
+for bin in "${CLEEK_A}" "${CLEEK_B}"; do
+    if [[ ! -x "${bin}" ]]; then
+        echo "ERROR: ${bin} not found or not executable." >&2
+        exit 1
+    fi
+done
+
+for f in "${ZEEK_INPUT}" "${JSON_INPUT}"; do
+    if [[ ! -f "${f}" ]]; then
+        echo "ERROR: Input file not found: ${f}" >&2
+        exit 1
+    fi
+done
+
+LABEL_A="$(basename "${CLEEK_A}")"
+LABEL_B="$(basename "${CLEEK_B}")"
+
+# Disambiguate labels when basenames collide (e.g. both are "cleek")
+if [[ "${LABEL_A}" == "${LABEL_B}" ]]; then
+    LABEL_A="${CLEEK_A}"
+    LABEL_B="${CLEEK_B}"
+fi
+
+echo "=== cleek A/B Benchmark Suite ==="
+echo "Binary A: ${CLEEK_A}"
+echo "Binary B: ${CLEEK_B}"
+echo "Zeek input: ${ZEEK_INPUT}"
+echo "JSON input: ${JSON_INPUT}"
+echo ""
+
+run_bench() {
+    local name="$1"
+    local args="$2"
+
+    echo "--- ${name} ---"
+    hyperfine \
+        --warmup 1 \
+        --min-runs 5 \
+        --command-name "${LABEL_A}" \
+            "${CLEEK_A} ${args}" \
+        --command-name "${LABEL_B}" \
+            "${CLEEK_B} ${args}"
+    echo ""
+}
+
+run_bench "01-passthrough-tsv" \
+    "${ZEEK_INPUT} > /dev/null"
+
+run_bench "02-passthrough-json" \
+    "${JSON_INPUT} > /dev/null"
+
+run_bench "03-line-filter-tsv" \
+    "-x '(~ \"tcp\" LINE)' ${ZEEK_INPUT} > /dev/null"
+
+run_bench "04-line-filter-json" \
+    "-x '(~ \"tcp\" LINE)' ${JSON_INPUT} > /dev/null"
+
+run_bench "05-at-column-filter-tsv" \
+    "-x '(string= @proto \"tcp\")' ${ZEEK_INPUT} > /dev/null"
+
+run_bench "06-at-column-filter-json" \
+    "-x '(string= @proto \"tcp\")' ${JSON_INPUT} > /dev/null"
+
+run_bench "07-atat-column-filter-tsv" \
+    "-x '(and (plusp @@orig_bytes) (plusp @@resp_bytes))' ${ZEEK_INPUT} > /dev/null"
+
+run_bench "08-atat-column-filter-json" \
+    "-x '(and (plusp @@orig_bytes) (plusp @@resp_bytes))' ${JSON_INPUT} > /dev/null"
+
+run_bench "09-mutator-tsv" \
+    "-m '(anonip! @id.orig_h @id.resp_h)' ${ZEEK_INPUT} > /dev/null"
+
+run_bench "10-mutator-json" \
+    "-m '(anonip! @id.orig_h @id.resp_h)' ${JSON_INPUT} > /dev/null"
+
+run_bench "11-mutator-filter-tsv" \
+    "-m '(setf @total_bytes (+ @@orig_bytes @@resp_bytes))' -x '(plusp @total_bytes)' ${ZEEK_INPUT} > /dev/null"
+
+run_bench "12-mutator-filter-json" \
+    "-m '(setf @total_bytes (+ @@orig_bytes @@resp_bytes))' -x '(plusp @total_bytes)' ${JSON_INPUT} > /dev/null"
+
+run_bench "13-format-zeek-to-json" \
+    "-f json ${ZEEK_INPUT} > /dev/null"
+
+run_bench "14-format-json-to-zeek" \
+    "-f zeek ${JSON_INPUT} > /dev/null"
+
+echo "=== Benchmark complete ==="

helpers.lisp

@@ -90,25 +90,38 @@
   (:method ((field t))
     (sha256-string (format nil "~a" field))))
 
+;; TODO: You should rewrite this so you can provide a seed so the same binary doesn't always generate the same
+;; permutation (but a single run would).
 (let* ((v6-permutors (loop repeat 16 collect (ax:shuffle (coerce (loop for x upto 255 collect x) 'vector))))
        (v4-permutors (nthcdr 12 v6-permutors))
        (v4-string-permutors (loop for p in v4-permutors collect (map 'vector #'write-to-string p))))
-  (defgeneric anonip (ip)
-    (:documentation "Anonymize an IP address by permuting each byte with a fixed set of permutations for each byte.")
-    (:method ((ip string))
+  (defgeneric anonip (ip &optional num-octets)
+    (:documentation "Anonymize an IP address by permuting each byte with a fixed set of permutations for each byte. Optionally, only anonymize the first NUM-OCTETS starting with the most significant. Defaults to anonymizing all of them.")
+    (:method ((ip string) &optional num-octets)
+      (unless num-octets
+        (setf num-octets (if (na::ipv4-str? ip) 4 16)))
       (if (na::ipv4-str? ip)
           (let ((quads (split-sequence #\. ip)))
-            (setf (first quads) (aref (first v4-string-permutors) (parse-integer (first quads)))
-                  (second quads) (aref (second v4-string-permutors) (parse-integer (second quads)))
-                  (third quads) (aref (third v4-string-permutors) (parse-integer (third quads)))
-                  (fourth quads) (aref (fourth v4-string-permutors) (parse-integer (fourth quads))))
+            (setf (first quads) (if (>= num-octets 1)
+                                    (aref (first v4-string-permutors) (parse-integer (first quads)))
+                                    (first quads))
+                  (second quads) (if (>= num-octets 2)
+                                     (aref (second v4-string-permutors) (parse-integer (second quads)))
+                                     (second quads))
+                  (third quads) (if (>= num-octets 3)
+                                    (aref (third v4-string-permutors) (parse-integer (third quads)))
+                                    (third quads))
+                  (fourth quads) (if (>= num-octets 4)
+                                     (aref (fourth v4-string-permutors) (parse-integer (fourth quads)))
+                                     (fourth quads)))
             (str:join "." quads))
-          (str:downcase (na:str (anonip (na:make-ip-address ip))))))
-    (:method ((ip na::ip-address))
+          (str:downcase (na:str (anonip (na:make-ip-address ip) num-octets)))))
+    (:method ((ip na::ip-address) &optional num-octets)
       (let ((version (na:version ip))
             (ip (na:make-ip-address (na:int ip))))
         (loop for offset from (if (= version 4) 24 120) downto 0 by 8
               for permutor in (if (= version 4) v4-permutors v6-permutors)
+              repeat (or num-octets 16) ; default is always sufficient for IPv6/IPv4.
               do (setf (ldb (byte 8 offset) (slot-value ip 'netaddr::int))
                        (aref permutor (ldb (byte 8 offset) (slot-value ip 'netaddr::int)))))
         (setf (slot-value ip 'netaddr:str) (na::ip-int-to-str (na:int ip) version))
@@ -127,6 +140,12 @@
 (defalias private? #'na:private? "Alias for NETADDR:PRIVATE? which returns T if the IP address is privately routable. Requires a NETADDR::IP-LIKE (so fully parse with @@).")
 (defalias reserved? #'na:reserved? "Alias for NETADDR:RESERVED? which returns T if the IP address is reserved. Requires a NETADDR::IP-LIKE (so fully parse with @@).")
 
+(defun routes (ip-like)
+  (cond ((private? ip-like) "private")
+        ((public? ip-like) "public")
+        ((reserved? ip-like) "reserved")
+        (t "other")))
+
 ;; is there a reasonable way to anonymize domains?
 
 (defmacro ~ (regex field)