Failed process

[github-vincent-miszczak]

Hello,

I'm running Biggraphite 0.11 and got weird behavior recently:
One of the bg-carbon-cache stopped reporting metrics. Then, it leaked memory until system OOM killer killed it after some hours. I cannot tell if it continued to write data points during this time. Log file does not have anything particular.

I'm running with PyPy 6.0.0 for Python 2.7, BG_CACHE = memory.
The system is receiving ~150K points/s.

Other processes on the same and other machines didn't have any issue, Cassandra was OK.

Any help fixing this kind of issue would be appreciated.

May 24 04:50:18 biggraphite-2 kernel: [131633.221088] Killed process 14650 (bg-carbon-cache) total-vm:13337580kB, anon-rss:12265424kB, file-rss:0kB, shmem-rss:0kB

[iksaif]

I think we can blame the bug fixed by edf2c6e

I'll try to do a release soon.

[github-vincent-miszczak]

Thank you for the quick answer, I'll make a try with master branch.

[github-vincent-miszczak]

Hello,
I'm now running with a timeout (I patched the line from 0.11 directly rather than running master).

I have some thoughts about the code/patch :
Is this patch ok? Won't it leak memory if the timeout is triggered multiple times and async functions never returns?

[iksaif]

We haven't been able to reproduce this bug with pypy which we use, so I don't really know.
You might end up leaking some memory on missed timeouts, it would be interesting to add a metric for these events to know if they really happen a lot or not

[github-vincent-miszczak]

Ok, I'll try to trace those events.
I'm discovering the code and I was also wondering the purpose of _wait_async_call function.
Generally speaking you don't want to wait for async functions, you pass a callback if some work needs to be done on completion or block on a event in another thread. Without explanation it look like a complicated way to just call a function.

Can you give me some clues about the rational behind it?

[iksaif]

This was original written by @unbrice . I think the idea was that we had async functions and that in some cases we wanted a sync versions of these.

We want synchronous versions of functions like insert_points() to have some (minimal) backpressure mechanism (when cassandra becomes slow, we slow down too).

This is being used here: https://github.com/criteo/biggraphite/blob/master/biggraphite/plugins/carbon.py#L61

[github-vincent-miszczak]

Thank you for the explanation.

I added 2 metrics to track the issue :

https://github.com/hjdr4/biggraphite/blob/track-event-timeouts/biggraphite/accessor.py#L81-L106

The timeout is regularly triggered so it seems that synchronous writes throttling won't be as efficient as before.

[iksaif]

Which python version are you using ?

I starting to think that there must be something quite wrong in

biggraphite/biggraphite/drivers/cassandra.py

Line 1565 in f2f3558

def insert_downsampled_points_async(self, metric, datapoints, on_done=None):

but it would be great to be able to reproduce it in a unit test.

Could you try running with pypy to validate that this affects only CPython (which is the current theory)?

[github-vincent-miszczak]

Hello,
As I posted in my first comment, I'm running PyPy 6.0.0 for Python 2.7 already.

Over the weekend, the values stabilized after one Cassandra node stopped consuming 100%CPU. This is not related to the original issue, Cassandra was ok at this time.

For the last graph, the timeouts occurred because I put too much load importing production datapoints and one node Cassandra took hours to stabilize resource usage after the flow was shutdown. But that shows that timeouts can occur when Cassandra is loaded, and having a hard-coded timeout can reduce throttling efficiency.
Looking at PENDING_EVENTS, it looks like I got no race during the weekend, ratio kept between 0 and 1 (meaning every async call returned).

Just to recap:

• Using PyPy 6.0.0, a race can occur if no timeout is provided for event.wait()
• When a timeout is set, we can mitigate the race by not blocking the whole application but this may reduce throttling efficiency when Cassandra is loaded.

Now in real life, I will be ok with this workaround.
For now, I will try to add some metrics to graph the synchronous call time.

[unbrice]

I think @vmiszczak-teads is right:

Is this patch ok? Won't it leak memory if the timeout is triggered multiple times and async functions never returns?

Indeed, edf2c6e only displaces the leak. It does so at the expense of removing error propagation, limiting back pressure and introducing a race condition

To understand the problem, see that these are two work queues. One of the Cassandra Driver "cQ", one of BigGraphite "bgQ".
edf2c6e causes bgQ not to wait for cQ to consume items.
#296 occured when cQ is full. But with edf2c6e, bgQ gets full instead. So we have #337.

edf2c6e is also bad because it prevents exceptions from bubling up, and because it removes the protection on exception_box .

I think the solution should instead be to bound the queue sizes.
This can be achieved by propagating back pressure further up (if we can) or by explicitly dropping points (if we cannot). Then BG will degrade more gracefully.
I see carbon has USE_FLOW_CONTROL, but I haven't checked if it does the right thing. Is it set to true in your setup?

This being said, we are really speaking of graceful degradation here. It is likely that another issue in your setup is causing cQ (and bgQ) not to empty fast enough. I would check system health for the specific nodes running BG (FDs, ....) and health of the Cassandra cluster (do you have probes?).

[github-vincent-miszczak]

#296 and #337 both occurred without edf2c6e.
I was running vanilla 0.11 with PyPy when the bug triggered. Also it happened on one process among 48 (12 per node over 4 nodes) and Cassandra was OK at this time. To monitor Cassandra, I'm using advanced dashboards on Datadog to ensure eveything was ok (CPU ok, no hints, no dropped messages, low task queues, latency ok, no weird anything).

About #296, is there a metric that shows cQ/bgQ? I could graph at the moment the problem occurred, comparing different processes/nodes.

My USE_FLOW_CONTROL is True, but I have MAX_CACHE_SIZE = inf. When the bug triggered, back pressure was put on Carbon itself, filling up the memory. If I had bounded the cache size, Carbon would had dropped points forever and the process would had never crashed and be restarted by systemd (even worst).

IMHO the real issue is that an async call can never return(this is the problem I had). The async call should ensure/promise it will return in a bounded time. I think a timeout is necessary but it should not be on waiting for the async call to complete, but rather on the async call itself to avoid leaking anything.

Also the synchronous writes does not seem to take care about pending async writes, so I'm not even sure the original throttle design did the job. Maybe a flush() method waiting for all pending async tasks to complete would have more sense, also it would be appropriate for the back-pressure mechanism.

@unbrice I did not understand your point on queue sizes, queues can be full only if they are bounded.

#296 occured when cQ is full. But with edf2c6e, bgQ gets full instead

I think the solution should instead to bound the queue sizes.

[unbrice]

About #296, is there a metric that shows cQ/bgQ? I could graph at the moment the problem occurred, comparing different processes/nodes.

Hum, I don't have access to a prod instance to see which exisiting metrics could be used to visualise these unfortunatelly (I changed employers after participating to this project). Maybe this help for cQ? bgQ would be a carbon-level metric, maybe carbon.agents.<instance>.cache.size

My USE_FLOW_CONTROL is True, but I have MAX_CACHE_SIZE = inf. When the bug triggered, back pressure was put on Carbon itself, filling up the memory.

I see... So it seems working as configured.
Fundamentally, you must pick your poison between:

• MAX_CACHE_SIZE=some_number, USE_FLOW_CONTROL=True: points may be rejected, storage usage is bound
• MAX_CACHE_SIZE=some_number, USE_FLOW_CONTROL=False: points may be lost, storage usage is bound
• MAX_CACHE_SIZE=inf: points are never rejected or lost, but storage usage is not bound. This allows for "interesting" snowballing effects when eg: the GC slows down.

If I had bounded the cache size, Carbon would had dropped points forever and the process would had never crashed and be restarted by systemd (even worst).

My understanding is different, as per above. If you had bound the cache size but set USE_FLOW_CONTROL=True, the slow machines would stop accepting points rather than droping them. Assuming you have a load balancer or redundant writers it should work.
If you don't have a LB, yet if you care about not droping points, then I'd love to discuss your setup IRL next time I pass by Montpelliers. But that's probably beyond the scope of this bug ;-)

The async call should ensure/promise it will return in a bounded time. I think a timeout is necessary but it should not be on waiting for the async call to complete, but rather on the async call itself to avoid leaking anything.

What you suggest amounts to having cQ discard points when it is full. Not only it would discard points, but it would also prevent backpressure from working for those who bound the cache size.

[github-vincent-miszczak]

If you had bound the cache size but set USE_FLOW_CONTROL=True, the slow machines would stop accepting points rather than droping them.

You are right, I meant clients (relay with bounded queues in my case) would start dropping points.

What you suggest amounts to having cQ discard points when it is full. Not only it would discard points, but it would also prevent backpressure from working for those who bound the cache size.

My understanding of the current code is that insert_downsampled_points_async should already be time bounded by DEFAULT_TIMEOUT. For some reason (PyPy bug, Cassandra bug, BG bug ?) it is not 100% true.
Also my understanding of sync writes is that it waits for an async write to complete but does not care about other async writes so there is no pressure. I made minor changes to slow down until Cassandra is able to write all requests. It also bounds the number of in-flight async write requests. Finally I removed strict versioning of Cassandra driver as the bug described has been fixed. master...hjdr4:sync-writes

[iksaif]

FYI: https://github.com/criteo/biggraphite/blob/master/biggraphite/drivers/cassandra.py#L528 should already limit the size of the Cassandra queue.
Because Carbon is mono-threaded waiting for one write from time to time should "mostly" work. But you are right, this is not a strict guarantee.