Bug 1489976

Description of problem:
Sustainable single node logging throughput on OpenShift is limited to approximately 400 messages per second with journald as log driver.   At this rate logging-fluentd, with cpu limits removed, uses a full core (the maximum it can use without the multiprocess plugin) and journald uses 65% of a core.   Beyond this rate, as we approach 500 messages per sec, indexing of messages starts falling behind significantly, and fluentd message backlog (trailing journal) increases by at least 10,000 log messages per min.

This bug is being opened to track any documentation or tuning recommendations needed for this limitation.

Links:

inventory used to deploy logging :  https://gist.github.com/wabouhamad/40e85c4848ceb09dd25bb4374327b632

deployment config for elasticsearch: https://gist.github.com/wabouhamad/aabb0776eabf236372a84a4d4b45bd05

daemonset config for logging-fluentd:
https://gist.github.com/wabouhamad/0edb511fce77e2a631b25a326ecdbff5

Ansible playbook to tune journald: https://gist.github.com/wabouhamad/e0c2cb8937ecbf15870b34f3d669a8f3

Logtest cluster-loader config file:
https://gist.github.com/wabouhamad/bb64bec3b752e791617ec59822b8ab51



Version-Release number of selected component (if applicable):
Logging version 3.6.173.0.27

How reproducible:
Always when logging at this rate


Steps to Reproduce:
Cluster details:  All instances are m4.xlarge on AWS.  1 master, 1 infra node where ES is running and 1 compute node where logging-fluentd and an application pod are running.
Deploy logging with the inventory linked above.  Adjust hostnames accordingly
Edit the elasticsearch deployment configuration to increase the CPU limit (see https://bugzilla.redhat.com/show_bug.cgi?id=1488509)
Tune journald on the cluster compute nodes using the playbook linked above.
Start a pod to generate messages to stdout at 100, 200, 400 and 500 messages per second (tool used by QE:  https://github.com/openshift/svt/blob/master/openshift_scalability/content/logtest/ocp_logtest-README.md)
Use a monitoring tool such as pbench (https://github.com/distributed-system-analysis/pbench/blob/master/README.md) to monitor cpu, memory, etc on the system where the pod is running
Monitor number of messages across multiple components:
logged by the logging pod form Master node:
oc logs -n <logging_pod_project>   <logging_pod_name> | tail -1

logged by pod from journal (on compute node)
journalctl -u docker | grep <unique_string_from_logged_message> | tail -1

In elasticsearch under indexed pod project
export POD=<logging-es-pod-name>
oc exec $POD -n logging -- curl --connect-timeout 2 -s -k --cert /etc/elasticsearch/secret/admin-cert --key /etc/elasticsearch/secret/admin-key https://logging-es:9200/_cat/indices?v

Any messages lost.  Check total number of messages collected from steps above and compare with message sequence number

During the test, monitor the following log message rates on the compute node running the logging pod:
Number of messages fluentd is behind journald, and ensure that this number is not growing over time:
journalctl -c $( cat /var/log/journal.pos ) | wc -l

journal logging rate per min: 
journalctl -S "$( date +'%Y-%m-%d %H:%M:%S' --date="60 seconds ago" )" | wc -l


Actual results:

Around 400 sustained messages per second, logging-fluentd runs out out of cpu capacity and is no longer able to keep up with incoming messages.  Eventually the fluentd file buffer cache is exhausted.

See private comment for internal link to pbench data


Expected results:

Unknown - need to set end user expectations in this area.  Fluentd claims to be able to process 18K messages per second (https://www.fluentd.org/faqs) and internal discussions (see private link below) indicate user expectations of rates higher than 400 messages per second.

Additional info: