Incorrect StartTimeUnixNano for ExponentialHistogram with Delta Temporality after gRPC connection drop #3974

alexchowle · 2024-06-15T09:13:13Z

Describe your environment

OS: CentOS 7
Python version: 3.11.1
SDK version: 1.25.0
API version: 1.25.0

What happened?

As part of investigating #3971 I found that the loss and subsequent re-establishment of a gRPC connection to a Collector caused the next metric export to have a very old StartTimeUnixNano value

Steps to Reproduce

metrics_temporality = {
        Histogram: AggregationTemporality.DELTA
    }
otlp_metric_exporter = OTLPMetricExporter(endpoint=grpc_collector_address, insecure=True,
                                              preferred_temporality=metrics_temporality, timeout=30_000)
metric_reader = PeriodicExportingMetricReader(otlp_metric_exporter,
                                                  export_interval_millis=60_000))
meter_provider = MeterProvider(metric_readers=[metric_reader], resource=_create_resources(),
                                   views=[View(instrument_type=Histogram,
                                               aggregation=ExponentialBucketHistogramAggregation())])
metrics.set_meter_provider(meter_provider)

meter = metrics.get_meter(__name__)

h = meter.create_histogram(
        name='my_histogram', unit='s', description='just my histogram'
    )

h.record(1.0)
time.sleep(360)
h.record(2.0)

Have the OTel Collector drop the client's gRPC connection by setting the max_connection_age to 5m (as documented at https://github.com/open-telemetry/opentelemetry-collector/blob/main/config/configgrpc/README.md#server-configuration)

So the first recording happens, then within the 6-minute sleep the Collector drops the client's gRPC connection within 5 minutes, then the client sends a second observation after the 6 minutes has elapsed.

Expected Result

StartTimeUnixNano has a value that is within 60 seconds of the 2nd recording. This is how the Golang SDK works.

Actual Result

StartTimeUnixNano has the TimeUnixNano of observation # 1 i.e. about 6 minutes in the past.

Observation # 1
-----------------
Metric #0                                                                                                
Descriptor:                                                                                              
     -> Name: http.server.request.duration                                                               
     -> Description: Duration of HTTP server requests                                                    
     -> Unit: s                                                                                          
     -> DataType: ExponentialHistogram                                                                   
     -> AggregationTemporality: Delta                                                                    
ExponentialHistogramDataPoints #0                                                                        
Data point attributes:
     -> http.request.method: Str(POST)
     -> http.route: Str(/sources/raw)
     -> http.response.status_code: Int(202)
     -> url.scheme: Str(http)
StartTimestamp: 2024-06-14 06:25:40.301137322 +0000 UTC
Timestamp: 2024-06-14 06:25:53.980223433 +0000 UTC
Count: 1
Sum: 0.021235
Min: 0.021235
Max: 0.021235
Bucket [-1.000001, -1.000000), Count: 0
Bucket (0.021235, 0.021235], Count: 1


Observation #2
-----------------
Metric #0
Descriptor:
     -> Name: http.server.request.duration
     -> Description: Duration of HTTP server requests
     -> Unit: s
     -> DataType: ExponentialHistogram
     -> AggregationTemporality: Delta
ExponentialHistogramDataPoints #0
Data point attributes:
     -> http.request.method: Str(POST)
     -> http.route: Str(/sources/raw)
     -> http.response.status_code: Int(202)
     -> url.scheme: Str(http)
StartTimestamp: 2024-06-14 06:25:53.980223433 +0000 UTC
Timestamp: 2024-06-14 06:31:53.98886037 +0000 UTC
Count: 1
Sum: 0.018851
Min: 0.018851
Max: 0.018851
Bucket [-1.000001, -1.000000), Count: 0
Bucket (0.018851, 0.018851], Count: 1

Additional context

No response

Would you like to implement a fix?

None

The text was updated successfully, but these errors were encountered:

alexchowle · 2024-06-18T06:56:58Z

I've performed more testing and it seems the gRPC disconnection is irrelevant; the aged StartTimeUnixNano is used regardless.

xrmx · 2024-06-26T08:49:34Z

@alexchowle care to give #3978 a run?

alexchowle · 2024-06-26T19:01:11Z

@alexchowle care to give #3978 a run?

I've ran the reproduction scenario and am still seeing the same issue.

Observation # 1
-----------------
Metric #0                                                                                                
Descriptor:                                                                                              
     -> Name: http.server.request.duration                                                               
     -> Description: Duration of HTTP server requests                                                    
     -> Unit: s                                                                                          
     -> DataType: ExponentialHistogram                                                                   
     -> AggregationTemporality: Delta                                                                    
ExponentialHistogramDataPoints #0                                                                        
Data point attributes:
     -> http.request.method: Str(POST)
     -> http.route: Str(/sources/raw)
     -> http.response.status_code: Int(202)
     -> url.scheme: Str(http)
StartTimestamp: 2024-06-26 18:50:51.262250586 +0000 UTC
Timestamp: 2024-06-26 18:51:01.262261958 +0000 UTC
Count: 1
Sum: 1.000000
Min: 1.000000
Max: 1.000000
Bucket [-1.000001, -1.000000), Count: 0
Bucket (0.999999, 1.000000], Count: 1


Observation #2
-----------------
Metric #0
Descriptor:
     -> Name: http.server.request.duration
     -> Description: Duration of HTTP server requests
     -> Unit: s
     -> DataType: ExponentialHistogram
     -> AggregationTemporality: Delta
ExponentialHistogramDataPoints #0
Data point attributes:
     -> http.request.method: Str(POST)
     -> http.route: Str(/sources/raw)
     -> http.response.status_code: Int(202)
     -> url.scheme: Str(http)
StartTimestamp: 2024-06-26 18:51:01.226261958 +0000 UTC
Timestamp: 2024-06-26 18:56:51.263023031 +0000 UTC
Count: 1
Sum: 2.000000
Min: 2.000000
Max: 2.000000
Bucket [-1.000001, -1.000000), Count: 0
Bucket (1.999999, 2.000000], Count: 1

I'm pretty confident I'm using the correct whl files:

I'm picking up the new code:

I'm thinking I'm doing something wrong with my builds/imports of the wheels.

ocelotl · 2024-06-27T18:21:26Z

Observation # 1
-----------------
Metric #0                                                                                                
Descriptor:                                                                                              
     -> Name: http.server.request.duration                                                               
     -> Description: Duration of HTTP server requests                                                    
     -> Unit: s                                                                                          
     -> DataType: ExponentialHistogram                                                                   
     -> AggregationTemporality: Delta                                                                    
ExponentialHistogramDataPoints #0                                                                        
Data point attributes:
     -> http.request.method: Str(POST)
     -> http.route: Str(/sources/raw)
     -> http.response.status_code: Int(202)
     -> url.scheme: Str(http)
StartTimestamp: 2024-06-26 18:50:51.262250586 +0000 UTC
Timestamp: 2024-06-26 18:51:01.262261958 +0000 UTC
Count: 1
Sum: 1.000000
Min: 1.000000
Max: 1.000000
Bucket [-1.000001, -1.000000), Count: 0
Bucket (0.999999, 1.000000], Count: 1


Observation #2
-----------------
Metric #0
Descriptor:
     -> Name: http.server.request.duration
     -> Description: Duration of HTTP server requests
     -> Unit: s
     -> DataType: ExponentialHistogram
     -> AggregationTemporality: Delta
ExponentialHistogramDataPoints #0
Data point attributes:
     -> http.request.method: Str(POST)
     -> http.route: Str(/sources/raw)
     -> http.response.status_code: Int(202)
     -> url.scheme: Str(http)
StartTimestamp: 2024-06-26 18:51:01.226261958 +0000 UTC
Timestamp: 2024-06-26 18:56:51.263023031 +0000 UTC
Count: 1
Sum: 2.000000
Min: 2.000000
Max: 2.000000
Bucket [-1.000001, -1.000000), Count: 0
Bucket (1.999999, 2.000000], Count: 1

From the data above you are making 2 observations, with the following timestamps:

> Observation # 1
> -----------------
> ...
> StartTimestamp: 2024-06-26 18:50:51.262250586 +0000 UTC
> Timestamp: 2024-06-26 18:51:01.262261958 +0000 UTC
> ...
> Observation # 2
> -----------------
> ...
> StartTimestamp: 2024-06-26 18:51:01.226261958 +0000 UTC
> Timestamp: 2024-06-26 18:56:51.263023031 +0000 UTC
> ...

Observation # 1 Timestamp matches Observation # 2 StartTimestamp:
Timestamp: 2024-06-26 18:51:01.262261958 +0000 UTC == StartTimestamp: 2024-06-26 18:51:01.226261958 +0000 UTC.

This is expected, the start time of a DELTA temporality collected exponential histogram data point is the value of the collection time of the previous DELTA temporality collected exponential histogram data point.

For this behavior to change to match the Golang behavior the entire _ExponentialBucketHistogramAggregation would need to be reinstantiated after the first point is collected and before the second point is collected. I wonder if that is what Golang is doing, I imagine something like that happens when the gRPC connection drops, but I am not sure if that behavior is defined somewhere in the spec 🤷

I'll ask @jmacd for guidance here.

alexchowle · 2024-06-27T18:30:56Z

I only noticed this issue because my vendor backend uses StartTimeUnixNano as the observation timestamp. My service has a very low throughput.

ocelotl · 2024-06-27T18:32:49Z

Sorry, please disregard my previous answer I need to do more thinking about this issue, and consider the export interval of the periodic exporter, will comment here when I have a better answer ✌️

Fixes open-telemetry#3974

ocelotl · 2024-06-27T19:21:12Z

@alexchowle I have created a branch that I think should fix your issue: #4002

I am just adding a commit so that the previous collection time gets updated with every collection regardless of aggregate being called between collection cycles or not.

Please give it a try ✌️

jack-berg · 2024-06-28T22:09:18Z

This is expected, the start time of a DELTA temporality collected exponential histogram data point is the value of the collection time of the previous DELTA temporality collected exponential histogram data point.

I disagree. The supplementary guidelines has a delta example which I believe covers this situation. Notice how the start / end time of the 3rd export is (T2, T3] despite there being no measurements in the previous interval. If your interpretation was correct, we would see the 3rd export have a start / end time of (T1, T3].

ocelotl · 2024-06-28T23:50:57Z

This is expected, the start time of a DELTA temporality collected exponential histogram data point is the value of the collection time of the previous DELTA temporality collected exponential histogram data point.

I disagree. The supplementary guidelines has a delta example which I believe covers this situation. Notice how the start / end time of the 3rd export is (T2, T3] despite there being no measurements in the previous interval. If you're interpretation was correct, we would see the 3rd export have a start / end time of (T1, T3].

Please take a look here

alexchowle · 2024-06-29T10:17:37Z

@alexchowle I have created a branch that I think should fix your issue: #4002

I am just adding a commit so that the previous collection time gets updated with every collection regardless of aggregate being called between collection cycles or not.

Please give it a try ✌️

I've just tried it. This looks very promising:

Observation # 1

2024-06-29T10:12:33.955Z        info    ResourceMetrics #0
Resource SchemaURL: 
Resource attributes:
     -> telemetry.sdk.language: Str(python)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(1.26.0.dev0)
     -> service.name: Str(otelworkbench)
     -> service.version: Str(0.1.0)
ScopeMetrics #0
ScopeMetrics SchemaURL: 
InstrumentationScope __main__ 
Metric #0
Descriptor:
     -> Name: my_histogram
     -> Description: just a histogram
     -> Unit: s
     -> DataType: ExponentialHistogram
     -> AggregationTemporality: Delta
ExponentialHistogramDataPoints #0
StartTimestamp: 2024-06-29 10:11:33.902642238 +0000 UTC
Timestamp: 2024-06-29 10:12:33.897396523 +0000 UTC
Count: 1
Sum: 1.000000
Min: 1.000000
Max: 1.000000
Bucket [-1.000001, -1.000000), Count: 0
Bucket (0.999999, 1.000000], Count: 1
        {"kind": "exporter", "data_type": "metrics", "name": "debug"}

Observation # 2

2024-06-29T10:16:34.014Z        info    MetricsExporter {"kind": "exporter", "data_type": "metrics", "name": "debug", "resource metrics": 1, "metrics": 1, "data points": 1}
2024-06-29T10:16:34.014Z        info    ResourceMetrics #0
Resource SchemaURL: 
Resource attributes:
     -> telemetry.sdk.language: Str(python)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(1.26.0.dev0)
     -> service.name: Str(otelworkbench)
     -> service.version: Str(0.1.0)
ScopeMetrics #0
ScopeMetrics SchemaURL: 
InstrumentationScope __main__ 
Metric #0
Descriptor:
     -> Name: my_histogram
     -> Description: just a histogram
     -> Unit: s
     -> DataType: ExponentialHistogram
     -> AggregationTemporality: Delta
ExponentialHistogramDataPoints #0
StartTimestamp: 2024-06-29 10:16:33.904149745 +0000 UTC
Timestamp: 2024-06-29 10:16:34.00260972 +0000 UTC
Count: 1
Sum: 2.000000
Min: 2.000000
Max: 2.000000
Bucket [-1.000001, -1.000000), Count: 0
Bucket (1.999999, 2.000000], Count: 1
        {"kind": "exporter", "data_type": "metrics", "name": "debug"}

alexchowle added the bug Something isn't working label Jun 15, 2024

zhihali mentioned this issue Jun 18, 2024

Fix exponential histogram aggregation #3977

Closed

ocelotl self-assigned this Jun 18, 2024

ocelotl added a commit to ocelotl/opentelemetry-python that referenced this issue Jun 27, 2024

Try resetting previous_collection_start_nano

c424be3

Fixes open-telemetry#3974

This was referenced Jul 1, 2024

Incorrect StartTimeUnixNano for ExplicitBucketHistogram with Delta Temporality after empty collection #4008

Closed

Incorrect StartTimeUnixNano for SumAggregation with Delta Temporality after empty collection #4010

Closed

ocelotl mentioned this issue Jul 11, 2024

Fix ExponentialBucketHistogramAggregation #3978

Merged

ocelotl closed this as completed in #3978 Jul 18, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Incorrect StartTimeUnixNano for ExponentialHistogram with Delta Temporality after gRPC connection drop #3974

Incorrect StartTimeUnixNano for ExponentialHistogram with Delta Temporality after gRPC connection drop #3974

alexchowle commented Jun 15, 2024 •

edited

Loading

alexchowle commented Jun 18, 2024 •

edited

Loading

xrmx commented Jun 26, 2024 •

edited

Loading

alexchowle commented Jun 26, 2024 •

edited

Loading

ocelotl commented Jun 27, 2024

alexchowle commented Jun 27, 2024

ocelotl commented Jun 27, 2024

ocelotl commented Jun 27, 2024

jack-berg commented Jun 28, 2024 •

edited

Loading

ocelotl commented Jun 28, 2024

alexchowle commented Jun 29, 2024

Incorrect StartTimeUnixNano for ExponentialHistogram with Delta Temporality after gRPC connection drop #3974

Incorrect StartTimeUnixNano for ExponentialHistogram with Delta Temporality after gRPC connection drop #3974

Comments

alexchowle commented Jun 15, 2024 • edited Loading

Describe your environment

What happened?

Steps to Reproduce

Expected Result

Actual Result

Additional context

Would you like to implement a fix?

alexchowle commented Jun 18, 2024 • edited Loading

xrmx commented Jun 26, 2024 • edited Loading

alexchowle commented Jun 26, 2024 • edited Loading

ocelotl commented Jun 27, 2024

alexchowle commented Jun 27, 2024

ocelotl commented Jun 27, 2024

ocelotl commented Jun 27, 2024

jack-berg commented Jun 28, 2024 • edited Loading

ocelotl commented Jun 28, 2024

alexchowle commented Jun 29, 2024

Observation # 1

Observation # 2

alexchowle commented Jun 15, 2024 •

edited

Loading

alexchowle commented Jun 18, 2024 •

edited

Loading

xrmx commented Jun 26, 2024 •

edited

Loading

alexchowle commented Jun 26, 2024 •

edited

Loading

jack-berg commented Jun 28, 2024 •

edited

Loading