read.go (customer)

read.go

dle connections: why queries after an idle gap take ~2x longer.
//
// The clickhouse-go pool reuses one TCP connection for sequential queries:
// scenarios A and B below finish with dials=1 no matter how long the gaps
// are. Latency only doubles when the PEER (a load balancer, proxy, NAT box,
// or a server setting) closes connections that sit idle. Then every query
// finds a dead pooled connection and pays a reconnect - TCP handshake +
// protocol hello = 2 extra round trips (scenario C: dials == queries).
//
// The fix is in the environment, not the driver: find what closes idle
// connections between client and server and raise its timeout.
//
// Setup:
//
//	CREATE TABLE benchmark_test (id UInt64, value Array(Float64)) ENGINE = MergeTree ORDER BY id;
//
// Run:
//
//	go mod init repro && go get github.com/ClickHouse/clickhouse-go/v2 && go run .
package main

import (
	"context"
	"fmt"
	"log"
	"net"
	"sync/atomic"
	"time"

	"github.com/ClickHouse/clickhouse-go/v2"
	"github.com/ClickHouse/clickhouse-go/v2/lib/driver"
)

const (
	addr       = "127.0.0.1:9000"
	table      = "benchmark_test"
	numQueries = 5
	idleGap    = 2 * time.Second
)

// dials counts every TCP connection the driver opens. A healthy pool running
// sequential queries dials exactly once, no matter how many queries run.
var dials atomic.Int64

func connect(settings clickhouse.Settings) driver.Conn {
	conn, err := clickhouse.Open(&clickhouse.Options{
		Addr:     []string{addr},
		Settings: settings,
		DialContext: func(ctx context.Context, addr string) (net.Conn, error) {
			dials.Add(1)
			var d net.Dialer
			return d.DialContext(ctx, "tcp", addr)
		},
	})
	if err != nil {
		log.Fatal(err)
	}
	return conn
}

func runReads(label string, gap time.Duration, settings clickhouse.Settings) {
	fmt.Println(label)
	conn := connect(settings)
	defer conn.Close()

	before := dials.Load()
	var total time.Duration
	for i := 1; i <= numQueries; i++ {
		start := time.Now()
		var maxID uint64
		if err := conn.QueryRow(context.Background(), "SELECT max(id) FROM "+table).Scan(&maxID); err != nil {
			log.Fatal(err)
		}
		elapsed := time.Since(start)
		total += elapsed
		fmt.Printf("  query %d: %v\n", i, elapsed)
		if gap > 0 && i < numQueries {
			time.Sleep(gap)
		}
	}
	fmt.Printf("  => average %v, TCP dials %d\n\n", total/numQueries, dials.Load()-before)
}

func main() {
	runReads("A: back-to-back queries (baseline)", 0, nil)
	runReads("B: 2s idle gaps, healthy server (gaps alone are harmless)", idleGap, nil)

	// C simulates a hostile network path by asking the server to close OUR
	// connection after 1s idle. idle_connection_timeout is a user-level
	// setting, so no server restart is needed. Watch dials == queries.
	runReads("C: 2s idle gaps, peer kills idle connections (the problem)",
		idleGap, clickhouse.Settings{"idle_connection_timeout": 1})
}

$ go run cmd/read/main.go
A: back-to-back queries (baseline)
  query 1: 5.016496ms
  query 2: 2.613251ms
  query 3: 2.646245ms
  query 4: 3.103294ms
  query 5: 2.662835ms
  => average 3.208424ms, TCP dials 1

B: 2s idle gaps, healthy server (gaps alone are harmless)
  query 1: 3.258887ms
  query 2: 5.924132ms
  query 3: 5.081324ms
  query 4: 5.374939ms
  query 5: 5.892168ms
  => average 5.10629ms, TCP dials 1

C: 2s idle gaps, peer kills idle connections (the problem)
  query 1: 7.198363ms
  query 2: 6.930646ms
  query 3: 8.90471ms
  query 4: 8.52731ms
  query 5: 7.380556ms
  => average 7.788317ms, TCP dials 5

NOTE: The problem here is in case (C), every new query "established new connection" instead of using the existing one from the pool. TCP dials 5.

So every query is paying 2 RTT (Round Trip Time) for connection establishment + auth.