Re: [3.13.2] list passed to list_sort() too long for efficiency.

[Joe Perches <joe@perches.com>]

On Wed, 2014-02-12 at 18:59 +0100, Paweł Sikora wrote:
> On Wednesday 12 of February 2014 09:46:26 Joe Perches wrote:
> > On Wed, 2014-02-12 at 18:16 +0100, Paweł Sikora wrote:
> > > [16855.582522] list passed to list_sort() too long for efficiency
> > > 
> > > could someone put some light on the last line?
> > 
> > Did you look at the list_sort function in lib/list_sort.c?
> > 
> > (granted the dmesg is harder to find that it should be
> >  because the format is split)
> > 
> > It just means it's slower than it could otherwise be
> 
> thanks,
> so without a stacktrace in dmesg we can't isolate a root of cause :/
> 

Perhaps something like this would help:

Emit the caller of list_sort using %pS when the list is too
long to be efficient.  Also emit the message if necessary
once for each call.

Coalesce formats.
Use a more current logging style with pr_<level> and pr_<fmt>

---
 lib/list_sort.c | 67 +++++++++++++++++++++++++++------------------------------
 1 file changed, 32 insertions(+), 35 deletions(-)

diff --git a/lib/list_sort.c b/lib/list_sort.c
index 1183fa7..e4e1a95 100644
--- a/lib/list_sort.c
+++ b/lib/list_sort.c
@@ -1,3 +1,5 @@
+#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt
+
 #include <linux/kernel.h>
 #include <linux/module.h>
 #include <linux/list_sort.h>
@@ -6,6 +8,8 @@
 
 #define MAX_LIST_LENGTH_BITS 20
 
+#define DEBUG
+
 /*
  * Returns a list organized in an intermediate format suited
  * to chaining of merge() calls: null-terminated, no reserved or
@@ -103,6 +107,7 @@ void list_sort(void *priv, struct list_head *head,
 	int lev;  /* index into part[] */
 	int max_lev = 0;
 	struct list_head *list;
+	bool too_big_msg = false;
 
 	if (list_empty(head))
 		return;
@@ -123,9 +128,11 @@ void list_sort(void *priv, struct list_head *head,
 		}
 		if (lev > max_lev) {
 			if (unlikely(lev >= ARRAY_SIZE(part)-1)) {
-				printk_once(KERN_DEBUG "list passed to"
-					" list_sort() too long for"
-					" efficiency\n");
+				if (!too_big_msg) {
+					too_big_msg = true;
+					pr_debug("list passed from %pS to list_sort() too long for efficiency\n",
+						 __builtin_return_address(0));
+				}
 				lev--;
 			}
 			max_lev = lev;
@@ -165,30 +172,29 @@ struct debug_el {
 /* Array, containing pointers to all elements in the test list */
 static struct debug_el **elts __initdata;
 
-static int __init check(struct debug_el *ela, struct debug_el *elb)
+static int __init check(struct debug_el *ela, struct debug_el *elb,
+			const char *caller)
 {
 	if (ela->serial >= TEST_LIST_LEN) {
-		printk(KERN_ERR "list_sort_test: error: incorrect serial %d\n",
-				ela->serial);
+		pr_err("%s: error: incorrect serial %d\n", caller, ela->serial);
 		return -EINVAL;
 	}
 	if (elb->serial >= TEST_LIST_LEN) {
-		printk(KERN_ERR "list_sort_test: error: incorrect serial %d\n",
-				elb->serial);
+		pr_err("%s: error: incorrect serial %d\n", caller, elb->serial);
 		return -EINVAL;
 	}
 	if (elts[ela->serial] != ela || elts[elb->serial] != elb) {
-		printk(KERN_ERR "list_sort_test: error: phantom element\n");
+		pr_err("%s: error: phantom element\n", caller);
 		return -EINVAL;
 	}
 	if (ela->poison1 != TEST_POISON1 || ela->poison2 != TEST_POISON2) {
-		printk(KERN_ERR "list_sort_test: error: bad poison: %#x/%#x\n",
-				ela->poison1, ela->poison2);
+		pr_err("%s: error: bad poison: %#x/%#x\n",
+		       caller, ela->poison1, ela->poison2);
 		return -EINVAL;
 	}
 	if (elb->poison1 != TEST_POISON1 || elb->poison2 != TEST_POISON2) {
-		printk(KERN_ERR "list_sort_test: error: bad poison: %#x/%#x\n",
-				elb->poison1, elb->poison2);
+		pr_err("%s: error: bad poison: %#x/%#x\n",
+		       caller, elb->poison1, elb->poison2);
 		return -EINVAL;
 	}
 	return 0;
@@ -201,7 +207,7 @@ static int __init cmp(void *priv, struct list_head *a, struct list_head *b)
 	ela = container_of(a, struct debug_el, list);
 	elb = container_of(b, struct debug_el, list);
 
-	check(ela, elb);
+	check(ela, elb, "list_sort_test");
 	return ela->value - elb->value;
 }
 
@@ -212,22 +218,17 @@ static int __init list_sort_test(void)
 	struct list_head *cur, *tmp;
 	LIST_HEAD(head);
 
-	printk(KERN_DEBUG "list_sort_test: start testing list_sort()\n");
+	pr_debug("%s: start testing list_sort()\n", __func__);
 
-	elts = kmalloc(sizeof(void *) * TEST_LIST_LEN, GFP_KERNEL);
-	if (!elts) {
-		printk(KERN_ERR "list_sort_test: error: cannot allocate "
-				"memory\n");
+	elts = kmalloc_array(TEST_LIST_LEN, sizeof(void *), GFP_KERNEL);
+	if (!elts)
 		goto exit;
-	}
 
 	for (i = 0; i < TEST_LIST_LEN; i++) {
 		el = kmalloc(sizeof(*el), GFP_KERNEL);
-		if (!el) {
-			printk(KERN_ERR "list_sort_test: error: cannot "
-					"allocate memory\n");
+		if (!el)
 			goto exit;
-		}
+
 		 /* force some equivalencies */
 		el->value = prandom_u32() % (TEST_LIST_LEN / 3);
 		el->serial = i;
@@ -244,37 +245,33 @@ static int __init list_sort_test(void)
 		int cmp_result;
 
 		if (cur->next->prev != cur) {
-			printk(KERN_ERR "list_sort_test: error: list is "
-					"corrupted\n");
+			pr_err("%s: error: list is corrupted\n", __func__);
 			goto exit;
 		}
 
 		cmp_result = cmp(NULL, cur, cur->next);
 		if (cmp_result > 0) {
-			printk(KERN_ERR "list_sort_test: error: list is not "
-					"sorted\n");
+			pr_err("%s: error: list is not sorted\n", __func__);
 			goto exit;
 		}
 
 		el = container_of(cur, struct debug_el, list);
 		el1 = container_of(cur->next, struct debug_el, list);
 		if (cmp_result == 0 && el->serial >= el1->serial) {
-			printk(KERN_ERR "list_sort_test: error: order of "
-					"equivalent elements not preserved\n");
+			pr_err("%s: error: order of equivalent elements not preserved\n",
+			       __func__);
 			goto exit;
 		}
 
-		if (check(el, el1)) {
-			printk(KERN_ERR "list_sort_test: error: element check "
-					"failed\n");
+		if (check(el, el1, __func__)) {
+			pr_err("%s: error: element check failed\n", __func__);
 			goto exit;
 		}
 		count++;
 	}
 
 	if (count != TEST_LIST_LEN) {
-		printk(KERN_ERR "list_sort_test: error: bad list length %d",
-				count);
+		pr_err("%s: error: bad list length %d\n", __func__, count);
 		goto exit;
 	}