Bug 1843461

+++ This bug was initially created as a clone of Bug #1833486 +++

Description of problem:
In v4.4 we can log 2.5k msgs/sec from a single node without issue.
Today on v4.5 I am unable to log at even 1k msgs/sec from a single node and have all my messages appear in elasticsearch.


Version-Release number of selected component (if applicable):
v4.5.0


How reproducible:
100%


Steps to Reproduce:
1. Deploy logging stack from https://github.com/openshift/origin-aggregated-logging.git on release-4.5 branch
2. Run cluster-loader logging workload
3. Check elasticsearch indices

Actual results:
# Test was 1.2M messages at 1k msg/s
$ oc exec elasticsearch-cdm-s89wygkk-1-6ffcfd6f58-5c72x -- indices | grep app
Defaulting container name to elasticsearch.
Use 'oc describe pod/elasticsearch-cdm-s89wygkk-1-6ffcfd6f58-5c72x -n openshift-logging' to see all of the containers in this pod.
green  open   app-000001   bRO5HELwQnmxjwU67WpD5Q   3   1     766500            0        829            414
green  open   app-000003   qf7pqZR0T2yX0oN2HFQ60g   3   1          0            0          0              0
green  open   app-000002   Pa4iwLpESFmOunFKifSSnA   3   1     160000            0        173             86


$ curl 'https://localhost:9200/app*/_count?pretty' -H 'Content-Type: application/json' -d'
{
    "query": {
      "term": {"kubernetes.namespace_name": "logtest-45-0"}
    }
}
'
{
  "count" : 926500,
  "_shards" : {
    "total" : 9,
    "successful" : 9,
    "skipped" : 0,
    "failed" : 0
  }
}


$ python verify_logtest_index.py --stream -i 'app*' -m 1200000
Index document count: 926500
Missing log line(s): 926501-1200000 (273500)
No duplicates found!
Number of missing logs: 273500
22.7917% message loss rate

Expected results:
All 1.2M messagse in app* indices


Additional info:

--- Additional comment from jcantril on 2020-05-11 17:04:25 UTC ---

Please post elasticsearch and fluent logs for review

--- Additional comment from ematysek on 2020-05-11 18:22:07 UTC ---

Created attachment 1687396 [details]
Elasticsearch and Fluentd Logs

Attached logs as requested.
I generated 600k logs for this cluster at 500/s and only got 370k successfully indexed.

$ python verify_logtest_index.py -i 'app*' --stream -m 600000
Index document count: 370000
Missing log line(s): 1-230000 (230000)
No duplicates found!
Number of missing logs: 230000
38.3333% message loss rate

--- Additional comment from jcantril on 2020-05-12 00:24:43 UTC ---

Maybe caused by https://bugzilla.redhat.com/show_bug.cgi?id=1834558

--- Additional comment from ematysek on 2020-05-15 20:41:15 UTC ---

The fix for bug 1834558 did significantly improve performance, however I am still seeing a decrease in throughput compared to 4.4 for single pod logging rates.

4.4 we were able to reliable log 2.5k msg/s, even seeing some passes at 3k msg/s passing.
On 4.5 2k seems reliable but I have not been able to get a single pass at 2.5k msg/s

--- Additional comment from jcantril on 2020-05-21 20:20:01 UTC ---

I'm having difficulties standing up a cluster to verify, but please try the following to bypass the proxy to elasticsearch so we may determine how it is affecting performance.

1. oc edit clusterlogging instance (set ManagementState: Unmanaged)
2. oc edit elasticsearch elasticsearch (set ManagementState: Unmanaged)
3. oc edit configmap elasticsearch (modify network be like: https://github.com/openshift/elasticsearch-operator/blob/release-4.2/pkg/k8shandler/configuration_tmpl.go#L17-L18)
4. delete elasticsearch pods to force them to restart in order to load the config
5. oc edit service elasticsearch (Modify "targetPort" to be 9200 instead of 'restapi')


Fluent should already be able to write to ES using its certificates and this should modify the service to direct traffic straight to the ES container and bypass the proxy

--- Additional comment from periklis on 2020-05-22 07:10:49 UTC ---

@ematysek

Have you tried the above comments from https://bugzilla.redhat.com/show_bug.cgi?id=1833486#c5 ?

--- Additional comment from ematysek on 2020-05-27 00:19:49 UTC ---

Unfortunately I wasn't able to get logs successfully indexed into elasticsearch after making the changes mentioned by Jeff.

--- Additional comment from ematysek on 2020-05-27 00:22:43 UTC ---

Created attachment 1692476 [details]
Fluentd Logs

Fluentd logs after making changes trying to bypass proxy.
Mostly filled with lines like this:
2020-05-26 19:13:45 +0000 [warn]: [clo_default_output_es] failed to flush the buffer. retry_time=2 next_retry_seconds=2020-05-26 19:13:47 +0000 chunk="5a690759010aca78709f913e131436a9" error_class=Fluent::Plugin::ElasticsearchOutput::RetryStreamEmitFailure error="buffer is full."

--- Additional comment from jcantril on 2020-05-27 15:46:34 UTC ---

lowering severity:low as this is not a functional blocker to 4.5

--- Additional comment from jcantril on 2020-05-27 18:35:22 UTC ---

(In reply to Eric Matysek from comment #8)
> Created attachment 1692476 [details]
> Fluentd Logs
> 
> Fluentd logs after making changes trying to bypass proxy.
> Mostly filled with lines like this:
> 2020-05-26 19:13:45 +0000 [warn]: [clo_default_output_es] failed to flush
> the buffer. retry_time=2 next_retry_seconds=2020-05-26 19:13:47 +0000
> chunk="5a690759010aca78709f913e131436a9"
> error_class=Fluent::Plugin::ElasticsearchOutput::RetryStreamEmitFailure
> error="buffer is full."

Not certain this is related to the perf issue but definitely seems like it would block forever https://github.com/uken/fluent-plugin-elasticsearch/pull/688

--- Additional comment from jcantril on 2020-05-27 18:41:32 UTC ---

(In reply to Jeff Cantrill from comment #10)
> (In reply to Eric Matysek from comment #8)
> > Created attachment 1692476 [details]
> > Fluentd Logs
> > 
> > Fluentd logs after making changes trying to bypass proxy.
> > Mostly filled with lines like this:
> > 2020-05-26 19:13:45 +0000 [warn]: [clo_default_output_es] failed to flush
> > the buffer. retry_time=2 next_retry_seconds=2020-05-26 19:13:47 +0000
> > chunk="5a690759010aca78709f913e131436a9"
> > error_class=Fluent::Plugin::ElasticsearchOutput::RetryStreamEmitFailure
> > error="buffer is full."
> 
> Not certain this is related to the perf issue but definitely seems like it
> would block forever
> https://github.com/uken/fluent-plugin-elasticsearch/pull/688

We have 4.0.5 and this was merged earlier so likely not blocking

--- Additional comment from lvlcek on 2020-05-28 12:18:24 UTC ---

I would be interested in learning how many primary shards and replicas we have for each index in ES in this case.

Can you please get indices status? You can use the "indices" utility.
https://github.com/openshift/origin-aggregated-logging/blob/master/elasticsearch/utils/indices

Given we should have significantly less indices now we need to check if we can get better performance by using more shards.

--- Additional comment from lvlcek on 2020-05-28 12:38:33 UTC ---

I found a bug. We did not update index name patterns in common.settings.* files in https://github.com/openshift/origin-aggregated-logging/tree/master/elasticsearch/index_templates
All of them are still assuming old index naming conventions ("project*",".operations*", ...etc). These files are not part of https://github.com/ViaQ/elasticsearch-templates so they need to be updated separately.

That should mean that indices should use the default Elasticsearch sharding (https://www.elastic.co/guide/en/elasticsearch/reference/6.8/indices-create-index.html#create-index-settings) which is 5 shards and 1 replicas. Indices status report should confirm this.

--- Additional comment from jcantril on 2020-06-02 21:16:08 UTC ---

Updating to target 4.6 to get these into release and backported to 4.5. requested backport in GH

--- Additional comment from ematysek on 2020-06-02 21:26:07 UTC ---

(In reply to Lukas Vlcek from comment #13)

> That should mean that indices should use the default Elasticsearch sharding
> (https://www.elastic.co/guide/en/elasticsearch/reference/6.8/indices-create-
> index.html#create-index-settings) which is 5 shards and 1 replicas. Indices
> status report should confirm this.

You can see in my original comment that the app* indices had 3 primary shards and 1 replica.
I think if the bottleneck was elasticsearch itself I would be seeing some sort of anomaly in elasticsearch pod cpu/memory usage