fix: measure query time excluding formatting, show < 1 ms, add unit tests

- Move startTime after BeginBatch so elapsed time brackets DB execution
  only, excluding formatter setup/teardown overhead
- Show '< 1' instead of clamping sub-millisecond queries to 1ms
- Colon format shows actual 0 for sub-ms; rate calculations still use 1ms floor
- Add TestPrintStatisticsUnit with 7 subtests covering standard/colon format,
  sub-ms display, disabled mode, default packet size, and multi-batch math

Author: dlevy-msft-sql

pkg/sqlcmd/sqlcmd.go

@@ -425,7 +425,6 @@ func (s *Sqlcmd) getRunnableQuery(q string) string {
 // -102: Conversion error occurred when selecting return value
 func (s *Sqlcmd) runQuery(query string) (int, int64, error) {
 	retcode := -101
-	startTime := time.Now()
 	s.Format.BeginBatch(query, s.vars, s.GetOutput(), s.GetError())
 	ctx := context.Background()
 	timeout := s.vars.QueryTimeoutSeconds()
@@ -435,6 +434,7 @@ func (s *Sqlcmd) runQuery(query string) (int, int64, error) {
 		ctx = ct
 	}
 	retmsg := &sqlexp.ReturnMessage{}
+	startTime := time.Now()
 	rows, qe := s.db.QueryContext(ctx, query, retmsg)
 	if qe != nil {
 		s.Format.AddError(qe)
@@ -512,8 +512,8 @@ func (s *Sqlcmd) runQuery(query string) (int, int64, error) {
 			s.Format.EndResultSet()
 		}
 	}
-	s.Format.EndBatch()
 	elapsedMs := time.Since(startTime).Milliseconds()
+	s.Format.EndBatch()
 	return retcode, elapsedMs, qe
 }
 
@@ -602,22 +602,28 @@ func (s *Sqlcmd) printStatistics(elapsedMs int64, numBatches int, out io.Writer)
 		packetSize = 4096 // default packet size
 	}
 
-	// Ensure minimum 1ms for calculations
-	if elapsedMs < 1 {
-		elapsedMs = 1
+	// Ensure minimum 1ms for rate calculations, but display actual 0 as "< 1"
+	displayElapsedMs := elapsedMs
+	calcElapsedMs := elapsedMs
+	if calcElapsedMs < 1 {
+		calcElapsedMs = 1
 	}
 
-	avgTime := float64(elapsedMs) / float64(numBatches)
-	batchesPerSec := float64(numBatches) / (float64(elapsedMs) / 1000.0)
+	avgTime := float64(calcElapsedMs) / float64(numBatches)
+	batchesPerSec := float64(numBatches) / (float64(calcElapsedMs) / 1000.0)
 
 	if *s.PrintStatistics == 1 {
 		// Colon-separated format: n:x:t1:t2:t3
 		// packetSize:numBatches:totalTime:avgTime:batchesPerSec
-		_, _ = fmt.Fprintf(out, "\n%d:%d:%d:%.2f:%.2f\n", packetSize, numBatches, elapsedMs, avgTime, batchesPerSec)
+		_, _ = fmt.Fprintf(out, "\n%d:%d:%d:%.2f:%.2f\n", packetSize, numBatches, displayElapsedMs, avgTime, batchesPerSec)
 	} else {
 		// Standard format
 		_, _ = fmt.Fprintf(out, "\nNetwork packet size (bytes): %d\n", packetSize)
 		_, _ = fmt.Fprintf(out, "%d xact[s]:\n", numBatches)
-		_, _ = fmt.Fprintf(out, "Clock Time (ms.): total   %7d  avg   %.2f (%.2f xacts per sec.)\n", elapsedMs, avgTime, batchesPerSec)
+		if displayElapsedMs < 1 {
+			_, _ = fmt.Fprintf(out, "Clock Time (ms.): total     < 1  avg   %.2f (%.2f xacts per sec.)\n", avgTime, batchesPerSec)
+		} else {
+			_, _ = fmt.Fprintf(out, "Clock Time (ms.): total   %7d  avg   %.2f (%.2f xacts per sec.)\n", displayElapsedMs, avgTime, batchesPerSec)
+		}
 	}
 }

pkg/sqlcmd/sqlcmd_test.go

@@ -749,3 +749,73 @@ func TestPrintStatisticsDisabled(t *testing.T) {
 	assert.NotContains(t, output, "Network packet size", "Should not contain packet size when disabled")
 	assert.NotContains(t, output, "xact[s]:", "Should not contain xacts label when disabled")
 }
+
+func TestPrintStatisticsUnit(t *testing.T) {
+	newSqlcmd := func(format int, packetSize int) *Sqlcmd {
+		s := &Sqlcmd{Connect: &ConnectSettings{}}
+		s.PrintStatistics = &format
+		s.Connect.PacketSize = packetSize
+		return s
+	}
+
+	t.Run("standard format", func(t *testing.T) {
+		s := newSqlcmd(0, 4096)
+		var buf bytes.Buffer
+		s.printStatistics(150, 3, &buf)
+		out := buf.String()
+		assert.Contains(t, out, "Network packet size (bytes): 4096")
+		assert.Contains(t, out, "3 xact[s]:")
+		assert.Contains(t, out, "Clock Time (ms.): total       150")
+		assert.Contains(t, out, "xacts per sec.")
+	})
+
+	t.Run("colon format", func(t *testing.T) {
+		s := newSqlcmd(1, 8192)
+		var buf bytes.Buffer
+		s.printStatistics(200, 2, &buf)
+		out := buf.String()
+		assert.Contains(t, out, "8192:2:200:")
+	})
+
+	t.Run("sub-millisecond standard", func(t *testing.T) {
+		s := newSqlcmd(0, 4096)
+		var buf bytes.Buffer
+		s.printStatistics(0, 1, &buf)
+		out := buf.String()
+		assert.Contains(t, out, "total     < 1", "sub-ms should show < 1")
+	})
+
+	t.Run("sub-millisecond colon", func(t *testing.T) {
+		s := newSqlcmd(1, 4096)
+		var buf bytes.Buffer
+		s.printStatistics(0, 1, &buf)
+		out := buf.String()
+		assert.Contains(t, out, "4096:1:0:", "colon format should show 0 for sub-ms")
+	})
+
+	t.Run("disabled", func(t *testing.T) {
+		s := &Sqlcmd{Connect: &ConnectSettings{}}
+		var buf bytes.Buffer
+		s.printStatistics(100, 1, &buf)
+		assert.Empty(t, buf.String(), "should produce no output when disabled")
+	})
+
+	t.Run("default packet size", func(t *testing.T) {
+		s := newSqlcmd(0, 0)
+		var buf bytes.Buffer
+		s.printStatistics(50, 1, &buf)
+		out := buf.String()
+		assert.Contains(t, out, "Network packet size (bytes): 4096", "should default to 4096")
+	})
+
+	t.Run("multiple batches", func(t *testing.T) {
+		s := newSqlcmd(0, 4096)
+		var buf bytes.Buffer
+		s.printStatistics(1000, 10, &buf)
+		out := buf.String()
+		assert.Contains(t, out, "10 xact[s]:")
+		assert.Contains(t, out, "total      1000")
+		assert.Contains(t, out, "avg   100.00")
+		assert.Contains(t, out, "10.00 xacts per sec.")
+	})
+}