search

helidon-io / helidon

Java libraries for writing microservices
https://helidon.io
Apache License 2.0
3.52k stars 565 forks source link

Metric tests intermittent failures #44

Closed barchetta closed 6 years ago

barchetta commented 6 years ago

Helidon Version: 0.10.0-SNAPSHOT

Occasionally in pipeline runs I get failures in some of the Metrics tests. This does not happen often, and a retry usually clears it up. You can see a failed run here: https://app.wercker.com/Helidon/helidon/runs/build/5b9ad0a98c38a200070cd426?step=5b9ad0dbf07af00007d84713

An excerpt

Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.032 sec - in io.helidon.metrics.HelidonTimerTest
Running io.helidon.metrics.HelidonHistogramTest
Tests run: 5, Failures: 3, Errors: 0, Skipped: 0, Time elapsed: 0.042 sec <<< FAILURE! - in io.helidon.metrics.HelidonHistogramTest
testJson  Time elapsed: 0.01 sec  <<< FAILURE!
org.opentest4j.AssertionFailedError: mean: expected: <50.6349>, but actual value was: <50.816667845774624>
    at io.helidon.metrics.HelidonHistogramTest.withTolerance(HelidonHistogramTest.java:189)
    at io.helidon.metrics.HelidonHistogramTest.testJson(HelidonHistogramTest.java:145)

testStatisticalValues  Time elapsed: 0.008 sec  <<< FAILURE!
org.opentest4j.MultipleFailuresError: 
Testing statistical values for integers (4 failures)
    median: expected: <48.0>, but actual value was: <49.0>
    75th percentile: expected: <75.0>, but actual value was: <76.0>
    99th percentile: expected: <98.0>, but actual value was: <99.0>
    mean: expected: <50.6>, but actual value was: <50.816667845774624>
    at io.helidon.metrics.HelidonHistogramTest.testSnapshot(HelidonHistogramTest.java:169)
    at io.helidon.metrics.HelidonHistogramTest.testStatisticalValues(HelidonHistogramTest.java:162)

testPrometheus  Time elapsed: 0.005 sec  <<< FAILURE!
java.lang.AssertionError: 

Expected: is "# TYPE application:file_sizes_mean_bytes gauge\napplication:file_sizes_mean_bytes 50634.99999999998\n# TYPE application:file_sizes_max_bytes gauge\napplication:file_sizes_max_bytes 99000\n# TYPE application:file_sizes_min_bytes gauge\napplication:file_sizes_min_bytes 0\n# TYPE application:file_sizes_stddev_bytes gauge\napplication:file_sizes_stddev_bytes 29438.949964290514\n# TYPE application:file_sizes_bytes summary\n# HELP application:file_sizes_bytes Users file size\napplication:file_sizes_bytes_count 200\napplication:file_sizes_bytes{quantile=\"0.5\"} 48000\napplication:file_sizes_bytes{quantile=\"0.75\"} 75000\napplication:file_sizes_bytes{quantile=\"0.95\"} 96000\napplication:file_sizes_bytes{quantile=\"0.98\"} 98000\napplication:file_sizes_bytes{quantile=\"0.99\"} 98000\napplication:file_sizes_bytes{quantile=\"0.999\"} 99000\n"
     but: was "# TYPE application:file_sizes_mean_bytes gauge\napplication:file_sizes_mean_bytes 50816.667845774624\n# TYPE application:file_sizes_max_bytes gauge\napplication:file_sizes_max_bytes 99000\n# TYPE application:file_sizes_min_bytes gauge\napplication:file_sizes_min_bytes 0\n# TYPE application:file_sizes_stddev_bytes gauge\napplication:file_sizes_stddev_bytes 29461.816543751112\n# TYPE application:file_sizes_bytes summary\n# HELP application:file_sizes_bytes Users file size\napplication:file_sizes_bytes_count 200\napplication:file_sizes_bytes{quantile=\"0.5\"} 49000\napplication:file_sizes_bytes{quantile=\"0.75\"} 76000\napplication:file_sizes_bytes{quantile=\"0.95\"} 96000\napplication:file_sizes_bytes{quantile=\"0.98\"} 98000\napplication:file_sizes_bytes{quantile=\"0.99\"} 99000\napplication:file_sizes_bytes{quantile=\"0.999\"} 99000\n"
    at io.helidon.metrics.HelidonHistogramTest.testPrometheus(HelidonHistogramTest.java:157)

Running io.helidon.metrics.HelidonMeterTest
Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.002 sec - in io.helidon.metrics.HelidonMeterTest

Results :

Failed tests: 
  HelidonHistogramTest.testJson:145->withTolerance:189 mean: expected: <50.6349>, but actual value was: <50.816667845774624>
  HelidonHistogramTest.testPrometheus:157 
Expected: is "# TYPE application:file_sizes_mean_bytes gauge\napplication:file_sizes_mean_bytes 50634.99999999998\n# TYPE application:file_sizes_max_bytes gauge\napplication:file_sizes_max_bytes 99000\n# TYPE application:file_sizes_min_bytes gauge\napplication:file_sizes_min_bytes 0\n# TYPE application:file_sizes_stddev_bytes gauge\napplication:file_sizes_stddev_bytes 29438.949964290514\n# TYPE application:file_sizes_bytes summary\n# HELP application:file_sizes_bytes Users file size\napplication:file_sizes_bytes_count 200\napplication:file_sizes_bytes{quantile=\"0.5\"} 48000\napplication:file_sizes_bytes{quantile=\"0.75\"} 75000\napplication:file_sizes_bytes{quantile=\"0.95\"} 96000\napplication:file_sizes_bytes{quantile=\"0.98\"} 98000\napplication:file_sizes_bytes{quantile=\"0.99\"} 98000\napplication:file_sizes_bytes{quantile=\"0.999\"} 99000\n"
     but: was "# TYPE application:file_sizes_mean_bytes gauge\napplication:file_sizes_mean_bytes 50816.667845774624\n# TYPE application:file_sizes_max_bytes gauge\napplication:file_sizes_max_bytes 99000\n# TYPE application:file_sizes_min_bytes gauge\napplication:file_sizes_min_bytes 0\n# TYPE application:file_sizes_stddev_bytes gauge\napplication:file_sizes_stddev_bytes 29461.816543751112\n# TYPE application:file_sizes_bytes summary\n# HELP application:file_sizes_bytes Users file size\napplication:file_sizes_bytes_count 200\napplication:file_sizes_bytes{quantile=\"0.5\"} 49000\napplication:file_sizes_bytes{quantile=\"0.75\"} 76000\napplication:file_sizes_bytes{quantile=\"0.95\"} 96000\napplication:file_sizes_bytes{quantile=\"0.98\"} 98000\napplication:file_sizes_bytes{quantile=\"0.99\"} 99000\napplication:file_sizes_bytes{quantile=\"0.999\"} 99000\n"
  HelidonHistogramTest.testStatisticalValues:162->testSnapshot:169 Testing statistical values for integers (4 failures)
    median: expected: <48.0>, but actual value was: <49.0>
    75th percentile: expected: <75.0>, but actual value was: <76.0>
    99th percentile: expected: <98.0>, but actual value was: <99.0>
    mean: expected: <50.6>, but actual value was: <50.816667845774624>

Tests run: 44, Failures: 3, Errors: 0, Skipped: 0
spericas commented 6 years ago

The issue is that a Histogram relies on an ExponentiallyDecayingReservoir where weighted sample data is stored. The weights are computed based on the time an item is added to the histogram. If the test does not add all the items within a second, the weights will differ and the test fails as shown above. This could easily happen on a slow machine or if artificial sleeps are introduced in the test while data is being added (with those added, the test fails every single time).

A potential workaround is to pass the timestamp for registration to ensure all data is registered at the same time, or at least pretend that to be the case. This is possible if histograms provide access to their underlying delegates and if some private access is changed to package private for testing purposes. A PR is on the way.