:

PATCH In review Steve Dickson 2 participants 3 messages Oct 24, 2008 – Nov 3, 2008 1 message not in the archive

Subsystems (3)

Networking NFS client NFS server

lore

Share & tools

lore

Steve Dickson

author

2008-10-24 17:31 UTC #0 lore raw

PATCH 1/1 :

[As requested, here is the debugging portion broken out of the 6th patch in the "Dynamic Pseudo Root" patch series.]

Added dprintk to the top and bottom of both expkey_parse() and svc_export_parse(). The top dprintks shows what rpc.mountd gave to the routines to parse. These match up well with the current debugging statements in the rpc.mount routines nfsd_export() and nfsd_fh().

The bottom two dprintks show when either routine error out. This was very useful in debugging why exports failed or hang.

I also added a number dprintks to the sunrpc caching code. Being there was exactly one debugging statement through out the entire chuck of code, it was literally impossible to tell whats going on. This dprintks will show if and when upcalls are made and (more importantly) when they are not.

All of these dprintks are not very busy code paths. They only pop when an exported is created or modified.

Signed-off-by Steve Dickson <[email protected]>

fs/nfsd/export.c renamed from fs/nfsd/export.c.org +8 -0

diff -up linux/fs/nfsd/export.c.org linux/fs/nfsd/export.c
@@ -104,6 +104,7 @@ static int expkey_parse(struct cache_det
 	if (mesg[mlen-1] != '\n')
 		return -EINVAL;
 	mesg[mlen-1] = 0;
+	dprintk("expkey_parse: '%s'\n", mesg);
 
 	buf = kmalloc(PAGE_SIZE, GFP_KERNEL);
 	err = -ENOMEM;

@@ -182,6 +183,8 @@ static int expkey_parse(struct cache_det
 	if (dom)
 		auth_domain_put(dom);
 	kfree(buf);
+	if (err)
+		dprintk("expkey_parse: err %d\n", err);
 	return err;
 }

@@ -353,6 +356,8 @@ static void svc_export_request(struct ca
 		return;
 	}
 	qword_add(bpp, blen, pth);
+	dprintk("svc_export_request: pth %s\n", pth);
+
 	(*bpp)[-1] = '\n';
 }

@@ -520,6 +525,7 @@ static int svc_export_parse(struct cache
 	if (mesg[mlen-1] != '\n')
 		return -EINVAL;
 	mesg[mlen-1] = 0;
+	dprintk("svc_export_parse: '%s'\n", mesg);
 
 	buf = kmalloc(PAGE_SIZE, GFP_KERNEL);
 	err = -ENOMEM;

@@ -632,6 +638,8 @@ static int svc_export_parse(struct cache
 	if (dom)
 		auth_domain_put(dom);
 	kfree(buf);
+	if (err)
+		dprintk("svc_export_parse: err %d\n", err);
 	return err;
 }

net/sunrpc/cache.c renamed from net/sunrpc/cache.c.org +13 -5

diff -up linux/net/sunrpc/cache.c.org linux/net/sunrpc/cache.c
@@ -215,11 +215,13 @@ int cache_check(struct cache_detail *det
 		if (rv == -EAGAIN)
 			rv = -ENOENT;
 	} else if (rv == -EAGAIN || age > refresh_age/2) {
-		dprintk("RPC:       Want update, refage=%ld, age=%ld\n",
-				refresh_age, age);
+		dprintk("check_check: upcall: h 0x%p pending %d rv %d\n", 
+			h, test_bit(CACHE_PENDING, &h->flags), rv);
 		if (!test_and_set_bit(CACHE_PENDING, &h->flags)) {
 			switch (cache_make_upcall(detail, h)) {
 			case -EINVAL:
+				dprintk("check_check: upcall(-EINVAL): h 0x%p rv %d\n",
+					h, rv);
 				clear_bit(CACHE_PENDING, &h->flags);
 				if (rv == -EAGAIN) {
 					set_bit(CACHE_NEGATIVE, &h->flags);

@@ -231,6 +233,8 @@ int cache_check(struct cache_detail *det
 
 			case -EAGAIN:
 				clear_bit(CACHE_PENDING, &h->flags);
+				dprintk("check_check: upcall(-EAGAIN): h 0x%p flags 0x%lx\n",
+					h, h->flags);
 				cache_revisit_request(h);
 				break;
 			}

@@ -560,13 +564,16 @@ static int cache_defer_req(struct cache_
 		/* too much in the cache, randomly drop this one,
 		 * or continue and drop the oldest below
 		 */
-		if (net_random()&1)
+		if (net_random()&1) {
+			dprintk("cache_defer_req:  0x%p: dropping request\n", item);
 			return -ETIMEDOUT;
+		}
 	}
 	dreq = req->defer(req);
-	if (dreq == NULL)
+	if (dreq == NULL) {
+		dprintk("cache_defer_req: 0x%p: request timedout\n", item);
 		return -ETIMEDOUT;
-
+	}
 	dreq->item = item;
 
 	spin_lock(&cache_defer_lock);

@@ -596,6 +603,7 @@ static int cache_defer_req(struct cache_
 		/* must have just been validated... */
 		cache_revisit_request(item);
 	}
+	dprintk("cache_defer_req:  0x%p: request deferred\n", item);
 	return 0;
 }

A message that is not in the archive (sent off-list or not yet received): [email protected]

J. Bruce Fields

2008-10-31 20:39 UTC #2 lore raw

Quoted 11 lines · Steve Dickson

[As requested, here is the debugging portion broken out of the 6th patch in the "Dynamic Pseudo Root" patch series.]
Added dprintk to the top and bottom of both expkey_parse() and svc_export_parse(). The top dprintks shows what rpc.mountd gave to the routines to parse. These match up well with the current debugging statements in the rpc.mount routines nfsd_export() and nfsd_fh().
The bottom two dprintks show when either routine error out. This was very useful in debugging why exports failed or hang.

Did you try experiment with strace very much before trying this? Something like

strace -e read,write -s 1000 -p pidof rpc.gssd

will show the contents of the upcalls and downcalls and any returned error, so I'm not convinced that dprintk's of the upcall/downcall data are necessary.

net/sunrpc/cache.c int cache_check(struct cache_detail *det · line 219

Quoted 11 lines

diff -up linux/net/sunrpc/cache.c.org linux/net/sunrpc/cache.c

net/sunrpc/cache.c renamed from net/sunrpc/cache.c.org +2 -2

@@ -215,11 +215,13 @@ int cache_check(struct cache_detail *det
 		if (rv == -EAGAIN)
 			rv = -ENOENT;
 	} else if (rv == -EAGAIN || age > refresh_age/2) {
-		dprintk("RPC:       Want update, refage=%ld, age=%ld\n",
-				refresh_age, age);
+		dprintk("check_check: upcall: h 0x%p pending %d rv %d\n", 
+			h, test_bit(CACHE_PENDING, &h->flags), rv);

THis is actually changing the information printed instead of adding more. Are you sure this is what you want?

Quoted 7 lines

net/sunrpc/cache.c renamed from net/sunrpc/cache.c.org +2 -0
 		if (!test_and_set_bit(CACHE_PENDING, &h->flags)) {
 			switch (cache_make_upcall(detail, h)) {
 			case -EINVAL:
+				dprintk("check_check: upcall(-EINVAL): h 0x%p rv %d\n",
+					h, rv);
 
From a quick check of cache_make_upcall, -EINVAL is returned either when

cache_request is NULL (looks like that would be a bug?), or in the case where nobody's listening on the given upcall channel, in which case there's already a printk().

--b.

Quoted 44 lines

net/sunrpc/cache.c renamed from net/sunrpc/cache.c.org +9 -3

 				clear_bit(CACHE_PENDING, &h->flags);
 				if (rv == -EAGAIN) {
 					set_bit(CACHE_NEGATIVE, &h->flags);

@@ -231,6 +233,8 @@ int cache_check(struct cache_detail *det
 
 			case -EAGAIN:
 				clear_bit(CACHE_PENDING, &h->flags);
+				dprintk("check_check: upcall(-EAGAIN): h 0x%p flags 0x%lx\n",
+					h, h->flags);
 				cache_revisit_request(h);
 				break;
 			}

@@ -560,13 +564,16 @@ static int cache_defer_req(struct cache_
 		/* too much in the cache, randomly drop this one,
 		 * or continue and drop the oldest below
 		 */
-		if (net_random()&1)
+		if (net_random()&1) {
+			dprintk("cache_defer_req:  0x%p: dropping request\n", item);
 			return -ETIMEDOUT;
+		}
 	}
 	dreq = req->defer(req);
-	if (dreq == NULL)
+	if (dreq == NULL) {
+		dprintk("cache_defer_req: 0x%p: request timedout\n", item);
 		return -ETIMEDOUT;
-
+	}
 	dreq->item = item;
 
 	spin_lock(&cache_defer_lock);

@@ -596,6 +603,7 @@ static int cache_defer_req(struct cache_
 		/* must have just been validated... */
 		cache_revisit_request(item);
 	}
+	dprintk("cache_defer_req:  0x%p: request deferred\n", item);
 	return 0;
 }

_______________________________________________
NFSv4 mailing list
[email protected]
http://linux-nfs.org/cgi-bin/mailman/listinfo/nfsv4

Steve Dickson

author

2008-11-03 13:53 UTC #3 lore raw

Quoted 14 lines · J. Bruce Fields

Quoted 11 lines · Steve Dickson
[As requested, here is the debugging portion broken out of the 6th patch in the "Dynamic Pseudo Root" patch series.]
Added dprintk to the top and bottom of both expkey_parse() and svc_export_parse(). The top dprintks shows what rpc.mountd gave to the routines to parse. These match up well with the current debugging statements in the rpc.mount routines nfsd_export() and nfsd_fh().
The bottom two dprintks show when either routine error out. This was very useful in debugging why exports failed or hang.

Quoted 9 lines

Did you try experiment with strace very much before trying this? Something like
strace -e read,write -s 1000 -p pidof rpc.gssd
will show the contents of the upcalls and downcalls and any returned error, so I'm not convinced that dprintk's of the upcall/downcall data are necessary.

No, I have not, but it does look interesting and I'll give it try.

But I also think its important to have one united debugging interface that gives meaningful information when its turned on.

For example, today you turn on export debugging with
rpcdebug -m nfsd -s export

you get a couple of "found this", "path is that" message that are basically meaningless and you have no idea where they are coming from.

When you turn on the cache debugging via:
rpcdebug -m nfsd -s cache

you get absolutely nothing, since there is exactly one dprintk() in all that code that I could never get to pop...

So with my proposed dprinks it makes those commands much more meaningful and useful by adding straightforward debugging strings that identify where they are in the kernel. They also tie in nicely with the syslog entries that currently come out of the mountd debugging. Also they are not in a high traffic area. Meaning they only pop when during exports and mounts, unlike an I/O path...

Maybe I'm don't understand the current debugging philosophy, but if a couple non-intrusive dprintk make the debugging commands a bit more useful, why isn't that a good thing?

steved.