OpenFlare/openflare-server/cmd/accesslogbench/main.go

package main

import (
	"flag"
	"fmt"
	"log"
	"os"
	"path/filepath"
	"runtime"
	"sort"
	"strings"
	"time"

	"github.com/rain-kl/openflare/openflare-server/internal/common"
	"github.com/rain-kl/openflare/openflare-server/internal/model"
)

const retentionDays = 90

func main() {
	dsn := flag.String("dsn", envOr("DSN", "postgres://openflare:replace-with-strong-password@192.168.107.2:5432/openflare?sslmode=disable"), "PostgreSQL DSN")
	records := flag.Int("records", 1_000_000, "number of access log rows to seed (0 = skip seeding)")
	seedNode := flag.String("node-id", "bench-node", "node_id used for seeded rows")
	iterations := flag.Int("iterations", 10, "benchmark iterations per scenario")
	warmup := flag.Int("warmup", 2, "warmup iterations per scenario")
	page := flag.Int("page", 0, "page index for list benchmark")
	pageSize := flag.Int("page-size", 20, "page size for list benchmark")
	reset := flag.Bool("reset", false, "truncate node_access_logs shard tables before seeding")
	legacyIterations := flag.Int("legacy-iterations", 1, "iterations for legacy full-scan scenario (can be very slow)")
	skipLegacy := flag.Bool("skip-legacy", false, "skip legacy full-scan scenario")
	verifyOnly := flag.Bool("verify-only", false, "verify query correctness and exit")
	flag.Parse()

	common.SQLDSN = *dsn
	common.SQLitePath = filepath.Join(os.TempDir(), "openflare-accesslogbench-missing.sqlite")
	if err := initBenchDB(*dsn); err != nil {
		log.Fatalf("init db: %v", err)
	}

	fmt.Println("=== OpenFlare node_access_logs benchmark (PostgreSQL) ===")
	fmt.Printf("DSN: %s\n", redactDSN(*dsn))
	fmt.Printf("GOMAXPROCS=%d\n", runtime.GOMAXPROCS(0))

	if *reset {
		if err := truncateAccessLogs(); err != nil {
			log.Fatalf("truncate access logs: %v", err)
		}
		fmt.Println("truncated node_access_logs shard tables")
	}

	if *records > 0 {
		existing, err := countAllAccessLogs()
		if err != nil {
			log.Fatalf("count existing rows: %v", err)
		}
		if existing >= int64(*records) {
			fmt.Printf("existing rows=%d >= target=%d, skip seeding\n", existing, *records)
		} else {
			missing := *records - int(existing)
			fmt.Printf("seeding %d rows (existing=%d)...\n", missing, existing)
			if err := seedAccessLogs(*seedNode, missing); err != nil {
				log.Fatalf("seed access logs: %v", err)
			}
		}
	}

	total, err := countAllAccessLogs()
	if err != nil {
		log.Fatalf("count rows after seed: %v", err)
	}
	fmt.Printf("total rows across shards: %d\n\n", total)

	since := time.Now().UTC().Add(-retentionDays * 24 * time.Hour)
	if err := verifyQueryCorrectness(since, total); err != nil {
		log.Fatalf("correctness verification failed: %v", err)
	}
	fmt.Println("correctness verification: PASS")
	if *verifyOnly {
		return
	}

	query := model.NodeAccessLogQuery{
		Since:     since,
		Page:      *page,
		PageSize:  *pageSize,
		SortBy:    "logged_at",
		SortOrder: "desc",
	}

	scenarios := []scenario{
		{
			name: "paginated_list",
			run: func() error {
				_, err := model.ListNodeAccessLogs(query)
				return err
			},
		},
		{
			name: "sql_count",
			run: func() error {
				_, _, err := model.CountNodeAccessLogs(query)
				return err
			},
		},
		{
			name: "api_list+count",
			run: func() error {
				if _, err := model.ListNodeAccessLogs(query); err != nil {
					return err
				}
				_, _, err := model.CountNodeAccessLogs(query)
				return err
			},
		},
		{
			name: "fullscan_list_legacy",
			run: func() error {
				_, err := fullScanList(query)
				return err
			},
		},
	}

	if err := printExplainPlans(since); err != nil {
		log.Printf("warn: explain analyze failed: %v", err)
	}

	for _, item := range scenarios {
		if item.name == "fullscan_list_legacy" && *skipLegacy {
			fmt.Println("[fullscan_list_legacy] skipped")
			continue
		}
		iterationCount := *iterations
		if item.name == "fullscan_list_legacy" {
			iterationCount = *legacyIterations
		}
		result, err := runScenario(item, *warmup, iterationCount)
		if err != nil {
			log.Fatalf("scenario %s failed: %v", item.name, err)
		}
		printResult(result)
	}
}

type scenario struct {
	name string
	run  func() error
}

type benchResult struct {
	name         string
	iterations   int
	latencies    []time.Duration
	allocBytes   []uint64
	heapInUse    []uint64
	maxHeapInUse uint64
}

func runScenario(item scenario, warmup int, iterations int) (*benchResult, error) {
	for range warmup {
		if err := item.run(); err != nil {
			return nil, err
		}
	}

	result := &benchResult{
		name:       item.name,
		iterations: iterations,
	}
	var peakHeap uint64

	for range iterations {
		runtime.GC()
		var before, after runtime.MemStats
		runtime.ReadMemStats(&before)

		start := time.Now()
		if err := item.run(); err != nil {
			return nil, err
		}
		elapsed := time.Since(start)

		runtime.ReadMemStats(&after)
		result.latencies = append(result.latencies, elapsed)
		result.allocBytes = append(result.allocBytes, after.TotalAlloc-before.TotalAlloc)
		result.heapInUse = append(result.heapInUse, after.HeapInuse)
		if after.HeapInuse > peakHeap {
			peakHeap = after.HeapInuse
		}
	}
	result.maxHeapInUse = peakHeap
	return result, nil
}

func printResult(result *benchResult) {
	latencies := append([]time.Duration(nil), result.latencies...)
	sort.Slice(latencies, func(i, j int) bool { return latencies[i] < latencies[j] })

	var allocSum uint64
	var heapSum uint64
	for index := range result.allocBytes {
		allocSum += result.allocBytes[index]
		heapSum += result.heapInUse[index]
	}

	fmt.Printf("[%s] iterations=%d\n", result.name, result.iterations)
	fmt.Printf("  latency: min=%s avg=%s p50=%s p95=%s max=%s\n",
		minDuration(latencies),
		avgDuration(latencies),
		percentile(latencies, 50),
		percentile(latencies, 95),
		maxDuration(latencies),
	)
	fmt.Printf("  alloc/op: avg=%s peak_heap=%s\n",
		humanBytes(allocSum/uint64(len(result.allocBytes))),
		humanBytes(result.maxHeapInUse),
	)
	fmt.Printf("  heap_inuse/op: avg=%s\n\n", humanBytes(heapSum/uint64(len(result.heapInUse))))
}

func seedAccessLogs(nodeID string, total int) error {
	started := time.Now()
	perShard := total / 10
	remainder := total % 10
	seeded := 0
	now := time.Now().UTC()

	for shard := range 10 {
		rows := perShard
		if shard < remainder {
			rows++
		}
		if rows == 0 {
			continue
		}
		table := fmt.Sprintf("node_access_logs_%02d", shard)
		sql := fmt.Sprintf(`
INSERT INTO %s (id, node_id, logged_at, remote_addr, region, host, path, status_code, created_at)
SELECT
	(gs * 10 + %d)::bigint AS id,
	$1 AS node_id,
	$2::timestamptz - (gs || ' minutes')::interval AS logged_at,
	('203.0.' || ((gs / 256) %% 256)::text || '.' || (gs %% 256)::text) AS remote_addr,
	'Benchland' AS region,
	('host-' || (gs %% 200)::text || '.example.com') AS host,
	('/api/v1/resource/' || gs::text) AS path,
	(200 + (gs %% 4))::bigint AS status_code,
	$2::timestamptz AS created_at
FROM generate_series(0, $3 - 1) AS gs
`, table, shard)
		if err := model.DB.Exec(sql, nodeID, now, rows).Error; err != nil {
			return err
		}
		seeded += rows
		elapsed := time.Since(started)
		rate := float64(seeded) / elapsed.Seconds()
		fmt.Printf("  seeded %d/%d rows (%.0f rows/s, elapsed %s)\n", seeded, total, rate, elapsed.Round(time.Millisecond))
	}
	return nil
}

func truncateAccessLogs() error {
	for _, table := range observabilityShardTables() {
		if err := model.DB.Exec("TRUNCATE TABLE " + table).Error; err != nil {
			return err
		}
	}
	return nil
}

func countAllAccessLogs() (int64, error) {
	var total int64
	for _, table := range observabilityShardTables() {
		var count int64
		if err := model.DB.Table(table).Count(&count).Error; err != nil {
			return 0, err
		}
		total += count
	}
	return total, nil
}

func observabilityShardTables() []string {
	tables := make([]string, 0, 10)
	for index := range 10 {
		tables = append(tables, fmt.Sprintf("node_access_logs_%02d", index))
	}
	return tables
}

func verifyQueryCorrectness(since time.Time, tableTotal int64) error {
	fmt.Println("=== correctness verification ===")
	baseQuery := model.NodeAccessLogQuery{
		Since:     since,
		SortBy:    "logged_at",
		SortOrder: "desc",
	}

	reference, err := fullScanList(baseQuery)
	if err != nil {
		return fmt.Errorf("reference full scan failed: %w", err)
	}
	if int64(len(reference)) != tableTotal {
		return fmt.Errorf("reference row count %d != table total %d", len(reference), tableTotal)
	}
	fmt.Printf("  reference rows in retention window: %d\n", len(reference))

	totalRecords, totalIPs, err := model.CountNodeAccessLogs(baseQuery)
	if err != nil {
		return fmt.Errorf("CountNodeAccessLogs failed: %w", err)
	}
	if totalRecords != int64(len(reference)) {
		return fmt.Errorf("total_records=%d want reference=%d", totalRecords, len(reference))
	}
	referenceIPs := countUniqueIPs(reference)
	if totalIPs != referenceIPs {
		return fmt.Errorf("total_ip=%d want reference=%d", totalIPs, referenceIPs)
	}
	fmt.Printf("  count totals: total_record=%d total_ip=%d\n", totalRecords, totalIPs)

	pages := []struct {
		page     int
		pageSize int
	}{
		{0, 20},
		{1, 20},
		{49, 20},
		{100, 50},
	}
	for _, item := range pages {
		query := baseQuery
		query.Page = item.page
		query.PageSize = item.pageSize
		got, err := model.ListNodeAccessLogs(query)
		if err != nil {
			return fmt.Errorf("ListNodeAccessLogs page=%d size=%d failed: %w", item.page, item.pageSize, err)
		}
		start := item.page * item.pageSize
		end := start + item.pageSize
		if start >= len(reference) {
			if len(got) != 0 {
				return fmt.Errorf("page=%d size=%d expected empty got %d", item.page, item.pageSize, len(got))
			}
			continue
		}
		if end > len(reference) {
			end = len(reference)
		}
		want := reference[start:end]
		if !accessLogsEqual(got, want) {
			return fmt.Errorf("page=%d size=%d content mismatch (got %d want %d rows)", item.page, item.pageSize, len(got), len(want))
		}
		fmt.Printf("  page=%d size=%d: %d rows match reference\n", item.page, item.pageSize, len(got))
	}

	filtered := model.NodeAccessLogQuery{
		NodeID:    "bench-node",
		Since:     since,
		SortBy:    "status_code",
		SortOrder: "asc",
		Page:      2,
		PageSize:  15,
	}
	filteredReference, err := fullScanList(filtered)
	if err != nil {
		return fmt.Errorf("filtered reference failed: %w", err)
	}
	filteredRows, err := model.ListNodeAccessLogs(filtered)
	if err != nil {
		return fmt.Errorf("filtered ListNodeAccessLogs failed: %w", err)
	}
	start := filtered.Page * filtered.PageSize
	end := start + filtered.PageSize
	if end > len(filteredReference) {
		end = len(filteredReference)
	}
	if start >= len(filteredReference) {
		start = len(filteredReference)
	}
	if !accessLogsEqual(filteredRows, filteredReference[start:end]) {
		return fmt.Errorf("filtered page content mismatch")
	}
	filteredTotal, filteredIPs, err := model.CountNodeAccessLogs(filtered)
	if err != nil {
		return fmt.Errorf("filtered CountNodeAccessLogs failed: %w", err)
	}
	if filteredTotal != int64(len(filteredReference)) {
		return fmt.Errorf("filtered total_records=%d want %d", filteredTotal, len(filteredReference))
	}
	if filteredIPs != countUniqueIPs(filteredReference) {
		return fmt.Errorf("filtered total_ip=%d want %d", filteredIPs, countUniqueIPs(filteredReference))
	}
	fmt.Printf("  filtered node_id=bench-node page=2 size=15: match (total_record=%d total_ip=%d)\n", filteredTotal, filteredIPs)
	return nil
}

func countUniqueIPs(logs []*model.NodeAccessLog) int64 {
	ips := make(map[string]struct{})
	for _, item := range logs {
		if item == nil {
			continue
		}
		if trimmed := strings.TrimSpace(item.RemoteAddr); trimmed != "" {
			ips[trimmed] = struct{}{}
		}
	}
	return int64(len(ips))
}

func accessLogsEqual(left []*model.NodeAccessLog, right []*model.NodeAccessLog) bool {
	if len(left) != len(right) {
		return false
	}
	for index := range left {
		if left[index] == nil || right[index] == nil {
			if left[index] != right[index] {
				return false
			}
			continue
		}
		if left[index].ID != right[index].ID ||
			left[index].NodeID != right[index].NodeID ||
			!left[index].LoggedAt.Equal(right[index].LoggedAt) ||
			left[index].RemoteAddr != right[index].RemoteAddr ||
			left[index].Host != right[index].Host ||
			left[index].Path != right[index].Path ||
			left[index].StatusCode != right[index].StatusCode {
			return false
		}
	}
	return true
}

func printExplainPlans(since time.Time) error {
	fmt.Println("=== PostgreSQL EXPLAIN (one shard sample: node_access_logs_00) ===")
	queries := []struct {
		name string
		sql  string
	}{
		{
			name: "paginated_list",
			sql:  "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM node_access_logs_00 WHERE logged_at >= $1 ORDER BY logged_at DESC, id DESC LIMIT 20",
		},
		{
			name: "count_rows",
			sql:  "EXPLAIN (ANALYZE, BUFFERS) SELECT COUNT(*) FROM node_access_logs_00 WHERE logged_at >= $1",
		},
		{
			name: "distinct_ip_union_all",
			sql: `EXPLAIN (ANALYZE, BUFFERS) SELECT COUNT(*) FROM (
SELECT remote_addr FROM (
SELECT TRIM(remote_addr) AS remote_addr FROM node_access_logs_00 WHERE logged_at >= $1 AND remote_addr <> ''
UNION ALL
SELECT TRIM(remote_addr) AS remote_addr FROM node_access_logs_01 WHERE logged_at >= $1 AND remote_addr <> ''
) AS all_ips GROUP BY remote_addr
) AS ips`,
		},
	}
	for _, item := range queries {
		rows, err := model.DB.Raw(item.sql, since).Rows()
		if err != nil {
			return err
		}
		fmt.Printf("-- %s\n", item.name)
		for rows.Next() {
			var line string
			if err := rows.Scan(&line); err != nil {
				rows.Close()
				return err
			}
			fmt.Println(line)
		}
		rows.Close()
		fmt.Println()
	}
	return nil
}

func fullScanList(query model.NodeAccessLogQuery) ([]*model.NodeAccessLog, error) {
	legacy := query
	legacy.PageSize = 0
	return model.ListNodeAccessLogs(legacy)
}

func initBenchDB(dsn string) error {
	return model.InitBenchmarkDB(dsn)
}

func envOr(key string, fallback string) string {
	if value := strings.TrimSpace(os.Getenv(key)); value != "" {
		return value
	}
	return fallback
}

func redactDSN(dsn string) string {
	if at := strings.Index(dsn, "@"); at > 0 {
		schemeEnd := strings.Index(dsn, "://")
		if schemeEnd >= 0 {
			return dsn[:schemeEnd+3] + "***@" + dsn[at+1:]
		}
	}
	return dsn
}

func minDuration(values []time.Duration) time.Duration {
	if len(values) == 0 {
		return 0
	}
	return values[0]
}

func maxDuration(values []time.Duration) time.Duration {
	if len(values) == 0 {
		return 0
	}
	return values[len(values)-1]
}

func avgDuration(values []time.Duration) time.Duration {
	if len(values) == 0 {
		return 0
	}
	var sum time.Duration
	for _, value := range values {
		sum += value
	}
	return sum / time.Duration(len(values))
}

func percentile(values []time.Duration, p int) time.Duration {
	if len(values) == 0 {
		return 0
	}
	if p <= 0 {
		return values[0]
	}
	if p >= 100 {
		return values[len(values)-1]
	}
	index := (len(values)*p + 99) / 100
	if index <= 0 {
		index = 1
	}
	if index > len(values) {
		index = len(values)
	}
	return values[index-1]
}

func humanBytes(value uint64) string {
	const unit = 1024
	if value < unit {
		return fmt.Sprintf("%d B", value)
	}
	div, exp := uint64(unit), 0
	for n := value / unit; n >= unit; n /= unit {
		div *= unit
		exp++
	}
	return fmt.Sprintf("%.1f %ciB", float64(value)/float64(div), "KMGTPE"[exp])
}