diego.executor.max_log_lines_per_second still floods doppler

[thelangley]

Using experimental ops file (i know), results in dopplers still being overloaded

Summary

We were able to stop a lot of noise from verbose apps but there was still log loss in other apps.

Steps to Reproduce

We checked to ensure that the logging levels were generally quite low so dopplers were not overloaded before we started.

We have applied this (diego.executor.max_log_lines_per_second) setting to a CF env with a setting of 100 and a setting of 50. We have also made a few simple ruby apps which a for loop showing an incrementing number with a variety of sleeps per cycle from 0.1 second wait to no delay at all.

We can then see errors in the logs like this...

2020-05-01T13:58:21.82+0100 [APP/PROC/WEB/0] OUT app instance exceeded log rate limit (100 log-lines/sec) set by platform operator

Which is ace

We found that there was a lot of dropped logs from the busy app, as we would expect. This is good. However, we also saw a small amount number of drops from the slower paced apps which means that the drops on the diego-cell were not effective.

We also found that the dopplers were still seeing lots of drops. Dopplers should not have seen as many drops as the logs should have been dropped before they got to the doppler component.

We may be misunderstanding what we're seeing but also, it may serve us right for using an experimental ops file.

Diego repo

executor

Environment Details

cf-deployment/v12.34.0
diego-release/v2.44.0

Possible Causes or Fixes (optional)

Log streaming holding things in a local cache on the cell?
Other metrics in the firehose also being emitted so although the application logs are reducing, the other metrics are coming out much faster too which are not blocked

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. Unfortunately, the Pivotal Tracker project is private so you may be unable to view the contents of the story.

The labels on this github issue will be updated when the story is started.

[robertjsullivan]

Do you all have any monitoring on your system? I'm curious if you are able to see the loggregator ingress metric on the diego cells to see how many messages are flowing through it. An example promql query would be rate(ingress{exported_job="diego_cell", origin="loggregator.metron"}[5m]) . A graph of dropped{origin="loggregator.metron", exported_job="diego_cell"} would be good too.

We're curious to know if the log batches that are being sent is exceeding the size limit set by Metron, which would cause Metron to drop messages. Also curious how big the log messages are than you're sending. Are you able to attach the code for your ruby test app?

Lastly, are your dopplers scaled appropriately as noted by this KPI https://docs.pivotal.io/platform/2-8/monitoring/key-cap-scaling.html#doppler-message-rate-ksi ?

[thelangley]

We have prometheus polling metrics through the firehose but as it's droppy, I'm not sure how reliable it is.

However, here's some stats.

For context: high logging was kicked off around 05:20 and ops files applied on diego-cells from around 05:30-05:40

[thelangley]

Bit more detail about the apps themselves

We have various versions of apps. Varying sleep levels. 0, 0.01, 0.001

The app instances are all running from different diego-cells so they don't step on each others' toes.

require 'sinatra'

get '/' do
	$i = 0

	while true do
   		puts("Inside the loop i = #$i" )
   		$i +=1
   		sleep (0)
	end
end

Sleep 0 app, goes bonkers and maxes out the diego-cell CPU-wise.

However, if I do cf logs <sleepy 0.001> which runs from another cell then we still see Inside the loop <number> some messages skip.

[jvshahid]

@thelangley sorry for the delayed response. There were a few critical issues that came up and pushed this one down the stack.

We found that there was a lot of dropped logs from the busy app, as we would expect. This is good. However, we also saw a small amount number of drops from the slower paced apps which means that the drops on the diego-cell were not effective.

We also found that the dopplers were still seeing lots of drops. Dopplers should not have seen as many drops as the logs should have been dropped before they got to the doppler component.

How many fast apps are you deploying? Is it possible that the infrastructure doesn't have enough resources to process that amount of logs even with the executor limit applied?

It will be really useful if you can label the graphs you put in #513 (comment)

[robertjsullivan]

We took a look at this functionality this morning, and from what we can tell it's working as expected. We set the diego cell to allow 100 log lines per second per app. We then pushed the sample app with "sleep(0)" and saw the rate of egress on the cell increase by 100 lines per second.

We did not see any corresponding drops on the cell or on doppler.

We also saw the CPU on the diego cell behave as we would expect. The app itself runs at 100% cpu but the rest of the components on Diego are protected from the load that overloaded logging would normally produce.

Our theory for what you are seeing is that your Doppler VMs are overloaded by the amount of logs coming through, even with the rate limiting. When Doppler drops envelopes, it does so indiscriminately. So it would drop envelopes there even for your slower apps. If you scale the Doppler VMs so that you don't see drops there, then you should not see drops for the slower apps.

[robertjsullivan]

For comparison's sake, we turned of the log rate limiting. You can see the CPU usage on the Diego Cell saturates the cell.

I'm going to close this issue. If you have additional findings that don't align with these results, please feel free to reopen.

[thelangley]

This is ace thanks. We'll retry with a lot more dopplers and a much more restrictive logging limit.

Thanks for checking for us :)