You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@skywalking.apache.org by wu...@apache.org on 2026/10/17 09:29:44 UTC
(skywalking) branch master updated: Fix Envoy ALS sidecar internal latencies dropping whole seconds (#14147)
This is an automated email from the ASF dual-hosted git repository.
wu-sheng pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/skywalking.git
The following commit(s) were added to refs/heads/master by this push:
new f784f81944 Fix Envoy ALS sidecar internal latencies dropping whole seconds (#14147)
f784f81944 is described below
commit f784f81944e9f9eb0c355a356a56f622573761dd
Author: Leo Camus <le...@gmail.com>
AuthorDate: Sat Oct 17 11:29:39 2026 +0200
Fix Envoy ALS sidecar internal latencies dropping whole seconds (#14147)
* Fix Envoy ALS sidecar internal latencies dropping whole seconds
The internal request and response latencies were computed from
Duration.getNanos(), which is only the sub-second part of a protobuf
Duration. Convert the whole duration to nanoseconds instead, in both the
HTTP and TCP adapters.
* Report no Envoy ALS internal response latency when a timing is missing
Envoy leaves a timing out of the access log when it never happened, such
as the first upstream response byte when it answers an upstream timeout
with its own 504, and an absent Duration reads as zero. With the whole
Duration converted, the subtraction reported the whole wait or a negative
value. Report 0 unless both timings are present.
---
docs/en/changes/changes.md | 1 +
.../envoy/als/LogEntry2MetricsAdapter.java | 15 ++-
.../envoy/als/tcp/TCPLogEntry2MetricsAdapter.java | 10 +-
.../envoy/als/LogEntry2MetricsAdapterTest.java | 109 +++++++++++++++++++++
4 files changed, 129 insertions(+), 6 deletions(-)
diff --git a/docs/en/changes/changes.md b/docs/en/changes/changes.md
index 323e561fab..4f6e81d7e1 100644
--- a/docs/en/changes/changes.md
+++ b/docs/en/changes/changes.md
@@ -50,6 +50,7 @@
* Build the dated Elasticsearch index names in one place, `IndexNames`, with the day step decided once per physical table from its models, replacing `TimeSeriesUtils` and `TimeRangeIndexNameGenerator`. Apart from the fixes above, index names are unchanged.
* Fix a service instance dropping out of the instance list queried with a time range when a record carrying an older minute updates it, such as the segment of a request that started minutes earlier arriving after the instance's heartbeat. `InstanceTraffic` took the `last_ping` of the last record written instead of keeping the latest one, as `EndpointTraffic` now does.
* Fix eBPF access-log timestamps losing all sub-second precision. `NodeInfo.parseTimestamp` truncated the nanosecond-since-boot offset to whole seconds and also dropped `bootTime.nanos` before converting to millis, so short mesh HTTP latency (`end - start`) was quantized to 0 or 1000ms depending on whether the request crossed a whole-second boundary, and minute buckets could land in the wrong minute near minute boundaries. The conversion is now `Instant.ofEpochSecond(bootSeconds, bootNan [...]
+* Fix the Envoy ALS sidecar internal request and response latencies dropping whole seconds: only the `nanos` part of each protobuf `Duration` was read. The internal response latency is now `0` when the access log lacks the upstream or downstream timing it is computed from, such as when Envoy answers an upstream timeout with its own 504, instead of counting the whole wait or going negative.
#### UI
* Add a Virtual GenAI evaluation-record page and evaluation-score chart in Horizon UI, so operators can inspect evaluation result, level, reason, judge model, timestamp, trace linkage, and the `gen_ai_model_evaluation_score_ppm` trend for evaluated records.
diff --git a/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapter.java b/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapter.java
index 5795c9d9c0..0644b3cf32 100644
--- a/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapter.java
+++ b/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapter.java
@@ -28,6 +28,7 @@ import io.envoyproxy.envoy.data.accesslog.v3.TLSProperties;
import java.time.Instant;
import java.util.List;
import java.util.Optional;
+import java.util.concurrent.TimeUnit;
import lombok.RequiredArgsConstructor;
import org.apache.skywalking.apm.network.common.v3.DetectPoint;
import org.apache.skywalking.apm.network.common.v3.KeyStringValuePair;
@@ -103,10 +104,14 @@ public class LogEntry2MetricsAdapter {
final Protocol protocol = requestProtocol(entry.getRequest());
final String tlsMode = parseTLS(properties.getTlsProperties());
final String internalErrorCode = parseInternalErrorCode(properties.getResponseFlags());
- final long internalRequestLatencyNanos = properties.getTimeToFirstUpstreamTxByte().getNanos();
+ final long internalRequestLatencyNanos = toNanos(properties.getTimeToFirstUpstreamTxByte());
+ // Envoy leaves out a timing that never happened, and an absent Duration reads as zero, so the
+ // difference would be the whole wait or negative.
final long internalResponseLatencyNanos =
- properties.getTimeToFirstDownstreamTxByte().getNanos()
- - properties.getTimeToFirstUpstreamRxByte().getNanos();
+ properties.hasTimeToFirstUpstreamRxByte() && properties.hasTimeToFirstDownstreamTxByte()
+ ? toNanos(properties.getTimeToFirstDownstreamTxByte())
+ - toNanos(properties.getTimeToFirstUpstreamRxByte())
+ : 0;
final HTTPServiceMeshMetric.Builder builder =
HTTPServiceMeshMetric
@@ -173,6 +178,10 @@ public class LogEntry2MetricsAdapter {
return Instant.ofEpochSecond(duration.getSeconds(), duration.getNanos()).toEpochMilli();
}
+ public static long toNanos(final Duration duration) {
+ return TimeUnit.SECONDS.toNanos(duration.getSeconds()) + duration.getNanos();
+ }
+
public static Protocol requestProtocol(final HTTPRequestProperties request) {
if (request == null) {
return Protocol.HTTP;
diff --git a/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/tcp/TCPLogEntry2MetricsAdapter.java b/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/tcp/TCPLogEntry2MetricsAdapter.java
index 8c4963eb86..0dd5465ebb 100644
--- a/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/tcp/TCPLogEntry2MetricsAdapter.java
+++ b/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/tcp/TCPLogEntry2MetricsAdapter.java
@@ -32,6 +32,7 @@ import org.apache.skywalking.oap.server.receiver.envoy.als.ServiceMetaInfo;
import static org.apache.skywalking.oap.server.receiver.envoy.als.LogEntry2MetricsAdapter.formatAsLong;
import static org.apache.skywalking.oap.server.receiver.envoy.als.LogEntry2MetricsAdapter.parseInternalErrorCode;
import static org.apache.skywalking.oap.server.receiver.envoy.als.LogEntry2MetricsAdapter.parseTLS;
+import static org.apache.skywalking.oap.server.receiver.envoy.als.LogEntry2MetricsAdapter.toNanos;
/**
* Adapt {@link HTTPAccessLogEntry} objects to {@link TCPServiceMeshMetric} builders.
@@ -86,10 +87,13 @@ public class TCPLogEntry2MetricsAdapter {
final ConnectionProperties connectionProperties = entry.getConnectionProperties();
final String tlsMode = parseTLS(properties.getTlsProperties());
final String internalErrorCode = parseInternalErrorCode(properties.getResponseFlags());
- final long internalRequestLatencyNanos = properties.getTimeToFirstUpstreamTxByte().getNanos();
+ final long internalRequestLatencyNanos = toNanos(properties.getTimeToFirstUpstreamTxByte());
+ // An absent timing reads as zero, see LogEntry2MetricsAdapter#adaptCommonPart.
final long internalResponseLatencyNanos =
- properties.getTimeToLastDownstreamTxByte().getNanos()
- - properties.getTimeToFirstUpstreamRxByte().getNanos();
+ properties.hasTimeToFirstUpstreamRxByte() && properties.hasTimeToLastDownstreamTxByte()
+ ? toNanos(properties.getTimeToLastDownstreamTxByte())
+ - toNanos(properties.getTimeToFirstUpstreamRxByte())
+ : 0;
final TCPServiceMeshMetric.Builder builder =
TCPServiceMeshMetric
diff --git a/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/test/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapterTest.java b/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/test/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapterTest.java
new file mode 100644
index 0000000000..30f6dd107b
--- /dev/null
+++ b/oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/test/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapterTest.java
@@ -0,0 +1,109 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ */
+
+package org.apache.skywalking.oap.server.receiver.envoy.als;
+
+import com.google.protobuf.Duration;
+import com.google.protobuf.Timestamp;
+import io.envoyproxy.envoy.data.accesslog.v3.AccessLogCommon;
+import io.envoyproxy.envoy.data.accesslog.v3.HTTPAccessLogEntry;
+import io.envoyproxy.envoy.data.accesslog.v3.TCPAccessLogEntry;
+import org.apache.skywalking.apm.network.servicemesh.v3.HTTPServiceMeshMetric;
+import org.apache.skywalking.apm.network.servicemesh.v3.TCPServiceMeshMetric;
+import org.apache.skywalking.oap.server.receiver.envoy.als.tcp.TCPLogEntry2MetricsAdapter;
+import org.junit.jupiter.api.Test;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+
+public class LogEntry2MetricsAdapterTest {
+ // 1.5s to send upstream, first response byte at 2.9s, first and last byte sent back at 3.1s.
+ private static final AccessLogCommon COMMON = AccessLogCommon.newBuilder()
+ .setStartTime(Timestamp.newBuilder().setSeconds(1700000000))
+ .setTimeToFirstUpstreamTxByte(Duration.newBuilder().setSeconds(1).setNanos(500_000_000))
+ .setTimeToLastUpstreamRxByte(Duration.newBuilder().setSeconds(3))
+ .setTimeToFirstUpstreamRxByte(Duration.newBuilder().setSeconds(2).setNanos(900_000_000))
+ .setTimeToFirstDownstreamTxByte(Duration.newBuilder().setSeconds(3).setNanos(100_000_000))
+ .setTimeToLastDownstreamTxByte(Duration.newBuilder().setSeconds(3).setNanos(100_000_000))
+ .build();
+
+ // An upstream timeout: the request went upstream at 2ms, no response came back, and Envoy sent its own 504 at 15s.
+ private static final AccessLogCommon UPSTREAM_TIMEOUT = AccessLogCommon.newBuilder()
+ .setStartTime(Timestamp.newBuilder().setSeconds(1700000000))
+ .setTimeToFirstUpstreamTxByte(Duration.newBuilder().setNanos(2_000_000))
+ .setTimeToFirstDownstreamTxByte(Duration.newBuilder().setSeconds(15).setNanos(2_000_000))
+ .setTimeToLastDownstreamTxByte(Duration.newBuilder().setSeconds(15).setNanos(2_000_000))
+ .build();
+
+ // The upstream answered at 2.9s and nothing has been sent back yet, as in the log Envoy flushes once an HTTP tunnel
+ // is established, and in TCP proxy logs, which carry no downstream byte timings.
+ private static final AccessLogCommon NO_DOWNSTREAM_TX = AccessLogCommon.newBuilder()
+ .setStartTime(Timestamp.newBuilder().setSeconds(1700000000))
+ .setTimeToFirstUpstreamTxByte(Duration.newBuilder().setSeconds(1).setNanos(500_000_000))
+ .setTimeToFirstUpstreamRxByte(Duration.newBuilder().setSeconds(2).setNanos(900_000_000))
+ .build();
+
+ @Test
+ public void testHTTPInternalLatencyCountsWholeSeconds() {
+ final HTTPAccessLogEntry entry = HTTPAccessLogEntry.newBuilder().setCommonProperties(COMMON).build();
+ final HTTPServiceMeshMetric.Builder metrics =
+ new LogEntry2MetricsAdapter(entry, null, null).adaptToDownstreamMetrics();
+
+ assertEquals(1_500_000_000L, metrics.getInternalRequestLatencyNanos());
+ assertEquals(200_000_000L, metrics.getInternalResponseLatencyNanos());
+ }
+
+ @Test
+ public void testHTTPInternalResponseLatencyWithoutUpstreamResponse() {
+ final HTTPAccessLogEntry entry = HTTPAccessLogEntry.newBuilder().setCommonProperties(UPSTREAM_TIMEOUT).build();
+ final HTTPServiceMeshMetric.Builder metrics =
+ new LogEntry2MetricsAdapter(entry, null, null).adaptToDownstreamMetrics();
+
+ assertEquals(2_000_000L, metrics.getInternalRequestLatencyNanos());
+ assertEquals(0L, metrics.getInternalResponseLatencyNanos());
+ }
+
+ @Test
+ public void testHTTPInternalResponseLatencyWithoutDownstreamResponse() {
+ final HTTPAccessLogEntry entry = HTTPAccessLogEntry.newBuilder().setCommonProperties(NO_DOWNSTREAM_TX).build();
+ final HTTPServiceMeshMetric.Builder metrics =
+ new LogEntry2MetricsAdapter(entry, null, null).adaptToDownstreamMetrics();
+
+ assertEquals(1_500_000_000L, metrics.getInternalRequestLatencyNanos());
+ assertEquals(0L, metrics.getInternalResponseLatencyNanos());
+ }
+
+ @Test
+ public void testTCPInternalLatencyCountsWholeSeconds() {
+ final TCPAccessLogEntry entry = TCPAccessLogEntry.newBuilder().setCommonProperties(COMMON).build();
+ final TCPServiceMeshMetric.Builder metrics =
+ new TCPLogEntry2MetricsAdapter(entry, null, null).adaptToDownstreamMetrics();
+
+ assertEquals(1_500_000_000L, metrics.getInternalRequestLatencyNanos());
+ assertEquals(200_000_000L, metrics.getInternalResponseLatencyNanos());
+ }
+
+ @Test
+ public void testTCPInternalResponseLatencyWithoutDownstreamResponse() {
+ final TCPAccessLogEntry entry = TCPAccessLogEntry.newBuilder().setCommonProperties(NO_DOWNSTREAM_TX).build();
+ final TCPServiceMeshMetric.Builder metrics =
+ new TCPLogEntry2MetricsAdapter(entry, null, null).adaptToDownstreamMetrics();
+
+ assertEquals(1_500_000_000L, metrics.getInternalRequestLatencyNanos());
+ assertEquals(0L, metrics.getInternalResponseLatencyNanos());
+ }
+}