[client-v2] OP_SERIALIZATION metric reports the whole operation duration, not the serialization step

Start in Client.java around lines 1545-1608, where OP_DURATION and OP_SERIALIZATION are started and the POJO serialization loop runs, then read OperationMetrics.operationComplete() and StopWatch.stop(), which currently overwrites the serialization time. Run the existing InsertTests and MetricsRecorderTest to see the current assertions. Done when OP_SERIALIZATION stops after the serialization loop, OP_DURATION is unchanged, and a regression test with a slow server-side insert asserts that OP_SERIALIZATION is much smaller than OP_DURATION.

Description

For a POJO insert (Client.insert(String, List<?>, InsertSettings)), ClientMetrics.OP_SERIALIZATION (client.opSerialization) always has the same value as ClientMetrics.OP_DURATION (client.opDuration). The metric is documented as "Duration of the operation serialization step in milliseconds", but it measures the full operation, including the network round trip and the server-side processing.

Since the metrics SPI (#2975, #3082), this value is also exported to users as clickhouse.client.operation.serialization.duration (MetricsSupport.serializationDuration, MicrometerMetricsRecorder). So the wrong value is visible in user dashboards.

Steps to reproduce

1. Create a table where the server-side insert is slow and the client-side serialization is trivial (a Null table with a materialized view that sleeps 0.5 s per row).
2. Register a POJO and insert 2 rows with client.insert(table, rows, settings).
3. Compare OP_SERIALIZATION with OP_DURATION, with the real serialization time, and with system.query_log.query_duration_ms.

Error Log or Exception StackTrace

No exception. Output of the program below (client main at 4cbc76abe, server 26.9.1.1629):

=== opser_src (Null + MV sleepEachRow(0.5)), 2 rows
  wall clock around insert().get() :   1067.323 ms
  serialization upper bound        :     10.109 ms  (t0 -> last POJO getter call)
  server query_log duration        :       1055 ms
  OP_DURATION      (client.opDuration)      :   1066.026 ms  (getLong()=1066)
  OP_SERIALIZATION (client.opSerialization) :   1066.025 ms  (getLong()=1066)
  OP_DURATION - OP_SERIALIZATION            :       1527 ns
=== opser_plain (MergeTree), 1 row
  serialization upper bound        :      1.176 ms
  server query_log duration        :         67 ms
  OP_DURATION      (client.opDuration)      :     69.609 ms
  OP_SERIALIZATION (client.opSerialization) :     69.609 ms
  OP_DURATION - OP_SERIALIZATION            :        201 ns
=== opser_plain (MergeTree), 100000 rows
  serialization upper bound        :     81.544 ms
  server query_log duration        :        110 ms
  OP_DURATION      (client.opDuration)      :    154.323 ms
  OP_SERIALIZATION (client.opSerialization) :    154.324 ms
  OP_DURATION - OP_SERIALIZATION            :       -401 ns

The server reports 1055 ms for the first insert, and the POJO getters were all called within 10 ms of the insert() call. The client still reports 1066 ms of serialization. In every case the two metrics differ only by nanoseconds.

Expected Behaviour

OP_SERIALIZATION covers only the time to serialize the POJOs into the request body. It must be smaller than OP_DURATION by at least the server-side time. In the first case above that is about 10 ms, not 1066 ms.

Root cause

• Client.java:1545-1546 starts OP_DURATION and OP_SERIALIZATION at the same instant.
• No code stops OP_SERIALIZATION when the serialization loop in the request body writer ends (Client.java:1597-1608). ClientStatisticsHolder.stop(ClientMetrics) exists, but nothing calls it.
• The only stop is OperationMetrics.operationComplete() (OperationMetrics.java:65-70), called from completeOperation after the response arrives. It stops every stopwatch in the holder, so both metrics get the same end time.

Also, StopWatch.stop() is not idempotent: it sets elapsedNanoTime = System.nanoTime() - startNanoTime on each call. Thus a stop(OP_SERIALIZATION) call in the writer alone does not fix it, because operationComplete() stops the stopwatch again and replaces the value.

The existing tests only assert getMetric(ClientMetrics.OP_SERIALIZATION).getLong() > 0 (InsertTests.java:144, :866) and > 0 on the exported metric (MetricsRecorderTest.java:84). These pass because the value equals the operation duration.

Suggested fix

• In the POJO insert body writer, start OP_SERIALIZATION before the first row and stop it after the serialization loop, before out.close(). Starting it in the writer also makes a retried attempt report its own serialization time.
• Make operationComplete() leave an already-stopped stopwatch unchanged. For example, StopWatch can keep a "stopped" state, or operationComplete() can stop only OP_DURATION.
• Behavior to keep: OP_DURATION is unchanged. Operations that do not start OP_SERIALIZATION (queries, InputStream and writer-based inserts) continue to report no serialization metric (MetricsSupport.DURATION_UNKNOWN, see MetricsRecorderUnitTest#testQueryWithoutSerializationStepReportsNoSerializationDuration).
• Regression test: an integration insert where the server-side time is large (for example, the materialized view with sleepEachRow below). Assert that OP_SERIALIZATION is much smaller than OP_DURATION, not only that it is > 0.

Note: the writer streams into the request body, so this step also includes any time spent blocked on the socket write. That is expected for a streaming writer.

Code Example

// Tables:
//   CREATE TABLE opser_src (id UInt32, name String) ENGINE = Null;
//   CREATE TABLE opser_dst (id UInt32, s UInt8) ENGINE = Memory;
//   CREATE MATERIALIZED VIEW opser_mv TO opser_dst AS SELECT id, sleepEachRow(0.5) AS s FROM opser_src;
public static class Row {
    private long id; private String name;
    public Row() {}
    public Row(long id, String name) { this.id = id; this.name = name; }
    public long getId() { return id; }          public void setId(long id) { this.id = id; }
    public String getName() { return name; }    public void setName(String n) { this.name = n; }
}

client.register(Row.class, client.getTableSchema("opser_src"));
List<Row> rows = Arrays.asList(new Row(1, "a"), new Row(2, "b"));
try (InsertResponse resp = client.insert("opser_src", rows, new InsertSettings()).get(60, TimeUnit.SECONDS)) {
    OperationMetrics m = resp.getMetrics();
    long op  = ((StopWatch) m.getMetric(ClientMetrics.OP_DURATION)).getElapsedNanos();
    long ser = ((StopWatch) m.getMetric(ClientMetrics.OP_SERIALIZATION)).getElapsedNanos();
    System.out.println(op + " ns vs " + ser + " ns"); // ~1.06e9 vs ~1.06e9; expected ser << op
}

Configuration

Client Configuration

Client client = new Client.Builder()
        .addEndpoint("http://clickhouse:18123")
        .setUsername("default").setPassword("...")
        .build();

Environment

• Cloud
• Client version: client-v2 0.12.0-rc1-SNAPSHOT, built from main at 4cbc76abe
• Language version: Java 17
• OS: Linux (Docker)

ClickHouse Server

• ClickHouse Server version: 26.9.1.1629
• ClickHouse Server non-default settings, if any: none (the repo's test container config)
• CREATE TABLE statements for tables involved: in the code example above
• Sample data for all these tables: the rows in the code example

---

Found by automated analysis of the client (Polyglot AI) while working on the metrics SPI (#2975). Verified by the program above against a live server, not only by reading the code.