Example shows weird graph

[lindycoder]

Hi, this is for information rather than an issue, you can close this if it's irrelevant;

I'm very new to all theses system, i followed your example (start docker and generate example data) and i ended up with this graph :

I modified the nc command to show what it was sending and it looks nothing like it it was juste random numbers with no particular spike.

Here's an exert of the graph's json

[{"datapoints": [[45.1, 1538162030], [0.0, 1538162040], [49.1, 1538162050], [47.7, 1538162060], [0.0, 1538162070], [55.0, 1538162080], [57.0, 1538162090], [0.0, 1538162100], [42.3, 1538162110], [44.4, 1538162120], [0.0, 1538162130], [53.1, 1538162140], [57.8, 1538162150], [0.0, 1538162160], [45.1, 1538162170], [32.5, 1538162180], [0.0, 1538162190], [50.9, 1538162200], [60.5, 1538162210], [0.0, 1538162220], [39.0, 1538162230], [50.9, 1538162240], [0.0, 1538162250], [53.3, 1538162260], [53.0, 1538162270], [0.0, 1538162280], [40.3, 1538162290], [52.1, 1538162300], [0.0, 1538162310], [null, 1538162320]], "target": "stats.example", "tags": {"name": "stats.example"}}]

there are clear 0s in there...

Is this normal? am i not understanding something properly? do you have links to understand what is happening?

[deniszh]

Hi @lindycoder ,
Yes, I reproduced an issue. And no - I have no explanation for the issue. I checked hopsoft's image - problem is not present there. Will try to investigate...

[piotr1212]

The nc command from the readme sends data to statsd. Statsd aggregates counts into time buckets and then flushes the aggregated value. If no data is received in a timebucket it will send 0. So this is expected. If you don't want this behaviour you can set deleteIdleStats: true in the statsd config. Or use the graphite carbon protocol.

[zebulonj]

I've reproduced this with the latest image, and am convinced that it is not the expected behavior. I added the console backend and discovered that statds is double-flushing every 30 seconds (see the two flushes at 22:59:17 in the output below), despite the 10 second flush interval.

27/09/2019 22:59:07 :: [tagdb] Tagging carbon.agents.ea74e9ceba1b-a.cache.overflow
27/09/2019 22:59:07 :: [tagdb] Tagged carbon.agents.ea74e9ceba1b-a.cache.overflow in 0.0062713623046875
Flushing stats at  Fri Sep 27 2019 22:59:17 GMT+0000 (Coordinated Universal Time)
{ counters:
   { 'statsd.bad_lines_seen': 0,
     'statsd.packets_received': 14,
     'statsd.metrics_received': 14,
     example: 10,
     'response.200': 1 },
  timers:
   { 'view.graphite.tags.views.tagMultiSeries.POST': [ 2 ],
     'view.graphite.tags.views.POST': [ 2 ],
     'view.POST': [ 2 ] },
  gauges: { 'statsd.timestamp_lag': 0 },
  timer_data:
   { 'view.graphite.tags.views.tagMultiSeries.POST':
      { count_90: 1,
        mean_90: 2,
        upper_90: 2,
        sum_90: 2,
        sum_squares_90: 4,
        std: 0,
        upper: 2,
        lower: 2,
        count: 1,
        count_ps: 0.1,
        sum: 2,
        sum_squares: 4,
        mean: 2,
        median: 2 },
     'view.graphite.tags.views.POST':
      { count_90: 1,
        mean_90: 2,
        upper_90: 2,
        sum_90: 2,
        sum_squares_90: 4,
        std: 0,
        upper: 2,
        lower: 2,
        count: 1,
        count_ps: 0.1,
        sum: 2,
        sum_squares: 4,
        mean: 2,
        median: 2 },
     'view.POST':
      { count_90: 1,
        mean_90: 2,
        upper_90: 2,
        sum_90: 2,
        sum_squares_90: 4,
        std: 0,
        upper: 2,
        lower: 2,
        count: 1,
        count_ps: 0.1,
        sum: 2,
        sum_squares: 4,
        mean: 2,
        median: 2 } },
  counter_rates:
   { 'statsd.bad_lines_seen': 0,
     'statsd.packets_received': 1.4,
     'statsd.metrics_received': 1.4,
     example: 1,
     'response.200': 0.1 },
  sets: {},
  pctThreshold: [ 90 ] }
27/09/2019 22:59:16 :: [listener] MetricLineReceiver connection with 127.0.0.1:54372 established
27/09/2019 22:59:16 :: [listener] MetricLineReceiver connection with 127.0.0.1:54372 closed cleanly
Flushing stats at  Fri Sep 27 2019 22:59:17 GMT+0000 (Coordinated Universal Time)
{ counters:
   { 'statsd.bad_lines_seen': 0,
     'statsd.packets_received': 0,
     'statsd.metrics_received': 0,
     example: 0,
     'response.200': 0 },
  timers:
   { 'view.graphite.tags.views.tagMultiSeries.POST': [],
     'view.graphite.tags.views.POST': [],
     'view.POST': [] },
  gauges: { 'statsd.timestamp_lag': -10 },
  timer_data:
   { 'view.graphite.tags.views.tagMultiSeries.POST': { count_ps: 0, count: 0 },
     'view.graphite.tags.views.POST': { count_ps: 0, count: 0 },
     'view.POST': { count_ps: 0, count: 0 } },
  counter_rates:
   { 'statsd.bad_lines_seen': 0,
     'statsd.packets_received': 0,
     'statsd.metrics_received': 0,
     example: 0,
     'response.200': 0 },
  sets: {},
  pctThreshold: [ 90 ] }
27/09/2019 22:59:17 :: [listener] MetricLineReceiver connection with 127.0.0.1:54374 established
27/09/2019 22:59:17 :: [listener] MetricLineReceiver connection with 127.0.0.1:54374 closed cleanly

[zebulonj]

I think this is an upstream issue. I see exactly the same behavior in the standalone statsd image.

[deniszh]

TBH I still have an idea to migrate to something new and compatible-ish enough in next major release, e.g. to bruebeck or bioyino

[deniszh]

Sigh... OK, I upgraded Statd to latest release. but issue is still there. Will not migrate to other statsd implementation before 1.1.6 release, maybe will do that later

[zebulonj]

FWIW, I think @BlueHatbRit is digging into it.

[elliotblackburn]

Hey thanks for the tag @zebulonj, sorry to see that this is causing problems for this project as well. I'm not sure what the issue is but the double send does seem strange. I've not been able to recreate this outside of docker so far so I'm now taking a look at it inside of docker to see what's up. My hope is this is something reasonably simple as a result, but it could be the opposite.

[elliotblackburn]

Hi, I think we've got a fix for this now. Sorry it's taken so long, things got very busy! I'm leaving a long running test going over the next 24h to check there's no regressions from it. Once that's confirmed I'll make a new release with the fix and will update here.

[deniszh]

Cool, good to hear, @BlueHatbRit !
Please let me know, I'll include fixed version in next release.

[elliotblackburn]

Will do, the test so far is looking great and I've not seen any clock slips or double sends and it's been running for a few hours. Since people rely on statsd quite heavily I want to give it about 12-24h just to make sure we're stable as this has been a pesky one.

I'll ping here once there's been a release, or if there are any further issues.

[elliotblackburn]

The fix has now been released as part of statsd 0.8.6, thanks for your patience and let me know if you find any further issues 😄

[deniszh]

Great! Much appreciated for info and efforts, @BlueHatbRit !