[Devel] [PATCH RHEL7 COMMIT] trace: add debug prints to nail down busyloop in tracing_read_pipe

[Konstantin Khorenko]

The commit is pushed to "branch-rh7-3.10.0-327.36.1.vz7.20.x-ovz" and will appear at https://src.openvz.org/scm/ovz/vzkernel.git
after rh7-3.10.0-327.36.1.vz7.20.6
------>
commit fffc6b8b528c0005b2bda431bb6c1a3282e2cbdf
Author: Stanislav Kinsburskiy <skinsbursky at virtuozzo.com>
Date:   Mon Nov 28 18:12:14 2016 +0400

    trace: add debug prints to nail down busyloop in tracing_read_pipe
    
    Below is the possible situation, which can lead to permanent cycle:
    
    trace_read_pipe
    waitagain:
      tracing_wait_pipe
        trace_empty == False
      trace_seq_to_user == -EBUSY
      goto waitagain
    
    This patch adds debug prints to make sure, that the assumption is valid plus
    provides some more state information in this case.
    
    https://jira.sw.ru/browse/PSBM-53928
    
    Signed-off-by: Stanislav Kinsburskiy <skinsbursky at virtuozzo.com>
---
 kernel/trace/trace.c | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index f5ebfe08..130f1b8e 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -4113,6 +4113,8 @@ tracing_read_pipe(struct file *filp, char __user *ubuf,
 	struct trace_iterator *iter = filp->private_data;
 	struct trace_array *tr = iter->tr;
 	ssize_t sret;
+	size_t loops = 0;
+	enum print_line_t ret = 0;
 
 	/* return any leftover data */
 	sret = trace_seq_to_user(&iter->seq, ubuf, cnt);
@@ -4163,7 +4165,6 @@ waitagain:
 	trace_event_read_lock();
 	trace_access_lock(iter->cpu_file);
 	while (trace_find_next_entry_inc(iter) != NULL) {
-		enum print_line_t ret;
 		int len = iter->seq.len;
 
 		ret = print_trace_line(iter);
@@ -4198,8 +4199,20 @@ waitagain:
 	 * If there was nothing to send to user, in spite of consuming trace
 	 * entries, go back to wait for more entries.
 	 */
-	if (sret == -EBUSY)
+	if (sret == -EBUSY) {
+		if ((loops % 10000) == 0) {
+			WARN_ON(1);
+			printk("%ldk loops in tracing_read_pipe\n", loops / 1000);
+			printk("trace_empty(iter): %d\n", trace_empty(iter));
+			printk("iter->seq.len    : %d\n", iter->seq.len);
+			printk("iter->seq.readpos: %d\n", iter->seq.readpos);
+			printk("iter->cpu_file   : %d\n", iter->cpu_file);
+			printk("iter->lost_events: %ld\n", iter->lost_events);
+			printk("ret              : %d\n", ret);
+			printk("cnt              : %ld\n", cnt);
+		}
 		goto waitagain;
+	}
 
 out:
 	mutex_unlock(&iter->mutex);