perf: guard loggerExternal.entering/exiting with isLoggable in SQLServerResultSet

[saurabh500]

Summary

Guards 396 unguarded loggerExternal.entering(...) / loggerExternal.exiting(...) calls in SQLServerResultSet with isLoggable(Level.FINER) checks.

When logging is disabled (the common production case), the unguarded variants still incur:

• Autoboxing of every primitive arg (int → Integer) for the varargs Object... parameter
• Object[] array allocation on every call site that passes >1 arg
• getClassNameLogging() invocation overhead

After this change, the guard short-circuits all of that when the logger level is above FINER (the default).

Change

Single file: src/main/java/com/microsoft/sqlserver/jdbc/SQLServerResultSet.java. Every existing loggerExternal.entering(...) / loggerExternal.exiting(...) is now wrapped in if (loggerExternal.isLoggable(Level.FINER)) { ... }. No behavioral change; logging output is identical when FINER is enabled.

Benchmarks

Real benchmarks against SQL Server 2022 using JMH (org.openjdk.jmh:jmh-core:1.37).

Hardware / software

CPU	AMD EPYC 7763 (16 cores / 32 threads visible)
RAM	62 GiB
OS	Ubuntu 22.04.3 LTS on WSL2 (kernel 6.6.87.2-microsoft-standard)
JDK	OpenJDK 17.0.18 (Ubuntu build)
SQL Server	mcr.microsoft.com/mssql/server:2022-latest (16.0.4250.1, Developer Edition on Ubuntu) running in Docker on localhost:1433
Driver build	mvn -Pjre17 -DskipTests -Dmaven.javadoc.skip=true -Dgpg.skip=true package from this branch (AFTER) and from the parent commit (BEFORE)
JMH	-Xms6g -Xmx6g, mode AverageTime, single client process

Benchmark 1 — narrow result set, mixed types ✅ clear win

10 columns (4× INT, 3× NVARCHAR(50), DATETIME2, BIGINT, FLOAT) × 100 K rows. Table populated once, read once per @Benchmark op.

CREATE TABLE dbo.bench_rs (id INT NOT NULL, i1 INT, i2 INT, i3 INT,
    s1 NVARCHAR(50), s2 NVARCHAR(50), s3 NVARCHAR(50),
    d1 DATETIME2, b1 BIGINT, f1 FLOAT);

WITH n AS (SELECT TOP (100000) ROW_NUMBER() OVER (ORDER BY (SELECT NULL)) AS r
           FROM sys.all_objects a CROSS JOIN sys.all_objects b)
INSERT INTO dbo.bench_rs SELECT r, r*2, r*3, r*5,
    CONCAT('str-',r), CONCAT('hello-world-',r), CONCAT('value-',r),
    SYSDATETIME(), CAST(r AS BIGINT)*100000, CAST(r AS FLOAT)/3.14
FROM n;

-- read loop in benchmark:
SELECT id, i1, i2, i3, s1, s2, s3, d1, b1, f1 FROM dbo.bench_rs;

JMH: 2 forks × (3 × 3 s warmup + 5 × 5 s measurement).

Version	Avg time	99.9% CI
BEFORE	242.428 ms/op	± 73.270
AFTER	133.387 ms/op	± 29.910

~1.82× faster (−45 %) — this is the realistic OLTP/reporting workload the patch was designed for. Mixed types with a few cols/row maximizes the relative weight of per-getter overhead.

Benchmark 2 — very wide result set, on-the-fly cross join (server-CPU-bound)

1000 INT columns × 1 M rows generated entirely from sys.all_columns × sys.all_columns with no table load:

SELECT TOP (1000000) a.column_id AS id,
       a.column_id AS c1, a.column_id AS c2, ..., a.column_id AS c1000
FROM sys.all_columns a CROSS JOIN sys.all_columns b;

JMH: 1 fork × (1 warmup + 3 measurement).

Version	Avg time	min / max
BEFORE	110.087 s/op	109.4 / 110.5
AFTER	105.260 s/op	98.2 / 110.0

Server-side row-construction dominates, total time stays ~110 s. Δ within noise.

Benchmark 3 — very wide result set, persisted table (pure I/O pull)

Same shape as Benchmark 2 but pre-loaded into a real table, so each iteration is essentially a TDS stream of pre-built rows:

CREATE TABLE dbo.bench_wide (id INT NOT NULL,
    c1 INT, c2 INT, ..., c1000 INT);

-- one-time load using the cross-join of sys.all_columns
WITH n AS (SELECT TOP (1000000) ROW_NUMBER() OVER (ORDER BY (SELECT NULL)) AS r
           FROM sys.all_columns a CROSS JOIN sys.all_columns b)
INSERT INTO dbo.bench_wide (id, c1, c2, ..., c1000)
SELECT r, r+1, r+2, ..., r+1000 FROM n OPTION (MAXDOP 0);

-- read in benchmark
SELECT id, c1, c2, ..., c1000 FROM dbo.bench_wide;

One-time load: ~40 s. Per-iteration read drops from ~110 s (cross-join) to ~65 s, confirming the cross-join was server-CPU-bound.

JMH: 1 fork × (2 warmup + 6 measurement). Same connection re-used between forks (BEFORE run reuses the table created by AFTER run).

Version	Avg time	min / max	99.9% CI	Stdev
BEFORE	65.619 s/op	64.6 / 67.4	[62.3, 68.9]	1.18
AFTER	65.009 s/op	63.2 / 68.4	[59.1, 71.0]	2.12

Δ ≈ 0.6 s on a 65 s mean (~0.9 %); CIs overlap heavily → statistically indistinguishable.

Interpretation

• The patch is unambiguously a win for the realistic mixed-type narrow-row case (Benchmark 1: ~1.82×).
• For pathologically wide all-INT result sets (~10⁹ getter calls), the per-getInt work in TDS column parsing / value materialization plus on-the-wire bytes completely dominate. The Integer.valueOf + Object[] allocation removed by the guard is real GC pressure but small relative to that floor (Benchmarks 2 & 3).
• No measured regression in any tested workload.
• The patch also reduces allocation pressure in the hot path (every getter currently allocates 2 boxed Integers + 1 Object[]), which is an additional benefit not captured by wall-clock here but visible under allocation-rate profiling (see the standalone reproducer benchmark/LoggerGuardBenchmark.java introduced in commit 6e7d5d5b — ~2× faster per call, ~zero allocation guarded).

Reproducer

javac benchmark/LoggerGuardBenchmark.java && java -cp benchmark LoggerGuardBenchmark
# Unguarded: ~47.4 ms / 10M iters    Guarded: ~24.2 ms / 10M iters    (~2× faster per call)

The full JMH project used for the SQL Server runs (pom + 2 benchmark classes + log/JSON outputs) lives at /tmp/jdbc-bench/ on the build machine; happy to upstream it on request.

Risk

• No public API change.
• Logging output is unchanged when FINER is enabled (the guard's predicate is exactly the level threshold the JUL handler would check anyway).
• Mechanical change limited to one file.