All of lore.kernel.org
 help / color / mirror / Atom feed
* [Drbd-dev] Proposed update to packet dumping code
@ 2006-08-09 22:50 Graham, Simon
  2006-08-09 23:14 ` Lars Ellenberg
  2006-08-10  9:39 ` Philipp Reisner
  0 siblings, 2 replies; 5+ messages in thread
From: Graham, Simon @ 2006-08-09 22:50 UTC (permalink / raw)
  To: drbd-dev

[-- Attachment #1: Type: text/plain, Size: 1307 bytes --]

I'm trying to track down a problem where I really need to get a dump of
the packets sent back and forth and I also need to be able to control
the output at run time - the attached is a proposed patch to the
DUMP_EACH_PACKET code in trunk that does the following:

1. I've fixed the code so it compiles and runs and updated it to include
(some of) the new messages in drbd-8

2. When you build with DUMP_EACH_PACKET defined, a module parameter
dump_packets is added that can be set via sysfs. Values
   are:

	0 - no tracing of packets
	1 - summary tracing of key packets - no file/line # and no
tracing of Ping packets
	2 - full tracing - trace includes file/line# and all packets are
traced
	3 - max tracing -- info on set-in-sync and set-out-of-sync calls
also included (this set-in-sync was in
		 the existing code, so I left it there but it's annoying
in general!)

3. I've split the code into an inline that does a quick check to see if
the tracing is enabled and a global function
   that does the work.

At the moment, this is still not on by default but my intention would be
that you could use a driver with this turned on in production (and
therefore be able to debug problems in the field).

Let me know what you think and if anything else should be done.
Simon


[-- Attachment #2: drbd-dump-packet.patch --]
[-- Type: application/octet-stream, Size: 9545 bytes --]

Index: drbd/drbd_receiver.c
===================================================================
--- drbd/drbd_receiver.c	(revision 3489)
+++ drbd/drbd_receiver.c	(working copy)
@@ -2373,6 +2373,8 @@
 		else
 			handler = NULL;
 
+		dump_packet(mdev,mdev->data.socket,2,&mdev->data.rbuf, __FILE__, __LINE__);
+
 		if (unlikely(!handler)) {
 			ERR("unknown packet type %d, l: %d!\n",
 			    header->command, header->length);
@@ -2383,7 +2385,6 @@
 			    cmdname(header->command), header->length);
 			break;
 		}
-		dump_packet(mdev,mdev->data.socket,2,&mdev->data.rbuf, __FILE__, __LINE__);
 	}
 }
 
Index: drbd/drbd_actlog.c
===================================================================
--- drbd/drbd_actlog.c	(revision 3489)
+++ drbd/drbd_actlog.c	(working copy)
@@ -732,8 +732,10 @@
 	sbnr = BM_SECT_TO_BIT(sector + BM_SECT_PER_BIT-1);
 
 #ifdef DUMP_EACH_PACKET
-	INFO("drbd_set_in_sync: sector=%lu size=%d sbnr=%lu ebnr=%lu\n",
-			(unsigned long)sector, size, sbnr, ebnr);
+	if (dump_packets >= DUMP_MAX) {
+	    INFO("drbd_set_in_sync: sector=%llx size=%x sbnr=%lx ebnr=%lx\n",
+		 (long long)sector, size, sbnr, ebnr);
+	}
 #endif
 
 	if (sbnr > ebnr) return;
@@ -794,6 +796,13 @@
 	sbnr = BM_SECT_TO_BIT(sector);
 	ebnr = BM_SECT_TO_BIT(esector);
 
+#ifdef DUMP_EACH_PACKET
+	if (dump_packets >= DUMP_MAX) {
+	    INFO("drbd_set_out_of_sync: sector=%llx size=%x sbnr=%lx ebnr=%lx\n",
+		 (long long)sector, size, sbnr, ebnr);
+	}
+#endif
+
 	/*
 	 * ok, (capacity & 7) != 0 sometimes, but who cares...
 	 * we count rs_{total,left} in bits, not sectors.
Index: drbd/linux/drbd_config.h
===================================================================
--- drbd/linux/drbd_config.h	(revision 3489)
+++ drbd/linux/drbd_config.h	(working copy)
@@ -36,8 +36,9 @@
 #define DUMP_MD 2       // Dump even all cstate changes (I like it!)
 //#define PARANOIA // some extra checks
 
-// don't enable this, unless you can cope with gigabyte syslogs :)
-//#define DUMP_EACH_PACKET
+// Define this to enable printing of packets under control of dump_packets
+// module parameter (/sys/module/drbd/parameters/dump_packets)
+//#define DUMP_EACH_PACKET
 
 // Dump every hour the usage / not usage of zero copy IO
 //#define SHOW_SENDPAGE_USAGE
Index: drbd/drbd_main.c
===================================================================
--- drbd/drbd_main.c	(revision 3489)
+++ drbd/drbd_main.c	(working copy)
@@ -126,6 +126,14 @@
 #endif
 int disable_bd_claim = 0;
 
+#ifdef DUMP_EACH_PACKET
+int dump_packets = 0;	// Module parameter that controls packet tracing
+			// 0 = none
+			// 1 = summary (trace 'interesting' packets in summary fmt)
+			// 2 = verbose (trace all packets in full format)
+module_param(dump_packets,int,0644);
+#endif
+
 // devfs name
 char* drbd_devfs_name = "drbd";
 
@@ -859,6 +867,7 @@
 	}
 
 #if DUMP_MD >= 2
+	{
 	char *pbp,pb[300];
 	pbp = pb;
 	*pbp=0;
@@ -872,6 +881,7 @@
 	PSC(peer_isp);
 	PSC(user_isp);
 	INFO("%s\n", pb);
+	}
 #endif
 
 	mdev->state.i = ns.i;
@@ -2870,5 +2880,145 @@
 	return 1;
 }
 
+#ifdef DUMP_EACH_PACKET
+#define PSM(A) \
+do { \
+	if( mask.A ) { \
+		int i = snprintf(p, len, " " #A "( %s )", \
+				A##s_to_name(val.A)); \
+		if (i >= len) return op; \
+		p += i; \
+		len -= i; \
+	} \
+} while (0)
+
+STATIC char *dump_st(char *p, int len, drbd_state_t mask, drbd_state_t val)
+{
+	char *op=p;
+	*p = '\0';
+	PSM(role);
+	PSM(peer);
+	PSM(conn);
+	PSM(disk);
+	PSM(pdsk);
+
+	return op;
+}
+
+#define INFOP(fmt, args...) \
+do { \
+	if (dump_packets > DUMP_SUMMARY) { \
+		INFO("%s:%d: %s [%d] %s %s " fmt , \
+		     file, line, current->comm, current->pid, \
+		     sockname, recv?"<<<":">>>" \
+		     , ## args ); \
+	} \
+	else { \
+		INFO("%s " fmt, recv?"<<<":">>>", ## args ); \
+	} \
+} while (0)
+
+void
+_dump_packet(drbd_dev *mdev, struct socket *sock,
+	    int recv, Drbd_Polymorph_Packet *p, char* file, int line)
+{
+	char *sockname = sock == mdev->meta.socket ? "meta" : "data";
+	int cmd = (recv == 2) ? p->head.command : be16_to_cpu(p->head.command);
+	char tmp[300];
+	drbd_state_t m,v;
+
+	switch (cmd) {
+	case HandShake:
+		INFOP("%s (protocol %u)\n", cmdname(cmd), be32_to_cpu(p->HandShake.protocol_version));
+		break;
+
+	case ReportBitMap: /* don't report this */
+		break;
+
+	case Data:
+	case DataReply:
+	case RSDataReply:
+		INFOP("%s (sector %llx, id %llx, seq %x, f %x)\n", cmdname(cmd),
+		     (long long)be64_to_cpu(p->Data.sector), 
+		     (long long)be64_to_cpu(p->Data.block_id),
+		     be32_to_cpu(p->Data.seq_num),
+		     be32_to_cpu(p->Data.dp_flags)
+		);
+		break;
+
+	case RecvAck:
+	case WriteAck:
+	case NegAck:
+		INFOP("%s (sector %llx, size %x, id %llx, seq %x)\n", cmdname(cmd),
+		     (long long)be64_to_cpu(p->BlockAck.sector), 
+		     be32_to_cpu(p->BlockAck.blksize),
+		     (long long)be64_to_cpu(p->BlockAck.block_id),
+		     be32_to_cpu(p->BlockAck.seq_num)
+		);
+		break;
+
+	case DataRequest:
+	case RSDataRequest:
+		INFOP("%s (sector %llx, size %x, id %llx)\n", cmdname(cmd),
+		     (long long)be64_to_cpu(p->BlockRequest.sector), 
+		     be32_to_cpu(p->BlockRequest.blksize),
+		     (long long)be64_to_cpu(p->BlockRequest.block_id)
+		);
+		break;
+
+	case Barrier:
+	case BarrierAck:
+		INFOP("%s (barrier %u)\n", cmdname(cmd), p->Barrier.barrier);
+		break;
+
+	case ReportSizes:
+		INFOP("%s (d %lluMiB, u %lluMiB, c %lldMiB, max bio %x, q order %x)\n", cmdname(cmd), 
+		     (long long)(be64_to_cpu(p->Sizes.d_size)>>(20-9)),
+		     (long long)(be64_to_cpu(p->Sizes.u_size)>>(20-9)),
+		     (long long)(be64_to_cpu(p->Sizes.c_size)>>(20-9)),
+		     be32_to_cpu(p->Sizes.max_segment_size),
+		     be32_to_cpu(p->Sizes.queue_order_type));
+		break;
+
+	case ReportState:
+		v.i = be32_to_cpu(p->State.state);
+		m.i = 0xffffffff;
+		dump_st(tmp,sizeof(tmp),m,v);
+		INFOP("%s (s %x {%s})\n", cmdname(cmd), v.i, tmp);
+		break;
+
+	case StateChgRequest:
+		m.i = be32_to_cpu(p->ReqState.mask);
+		v.i = be32_to_cpu(p->ReqState.val);
+		dump_st(tmp,sizeof(tmp),m,v);
+		INFOP("%s (m %x v %x {%s})\n", cmdname(cmd), m.i, v.i, tmp);
+		break;
+
+	case StateChgReply:
+		INFOP("%s (ret %x)\n", cmdname(cmd), 
+		     be32_to_cpu(p->RqSReply.retcode));
+		break;
+
+	case DiscardNote:
+		INFOP("%s (id %llx, seq %x)\n", cmdname(cmd),
+		     (long long)be64_to_cpu(p->Discard.block_id),
+		     be32_to_cpu(p->Discard.seq_num));
+		break;
+
+	case Ping:
+	case PingAck:
+		/*
+		 * Dont trace pings at summary level
+		 */
+		if (dump_packets <= DUMP_SUMMARY)
+			break;
+		/* fall through... */
+	default:
+		INFOP("%s (%u)\n",cmdname(cmd), cmd);
+		break;
+	}
+}
+#endif
+
 module_init(drbd_init)
 module_exit(drbd_cleanup)
Index: drbd/drbd_int.h
===================================================================
--- drbd/drbd_int.h	(revision 3489)
+++ drbd/drbd_int.h	(working copy)
@@ -361,8 +361,22 @@
 		[StateChgReply]    = "StateChgReply"
 	};
 
-	if (cmd == HandShake) return "HandShake";
-	if (Data > cmd || cmd >= MAX_CMD) return "Unknown";
+	if (Data > cmd || cmd >= MAX_CMD) {
+	    switch (cmd) {
+	    case HandShakeM:
+		return "HandShakeM";
+		break;
+	    case HandShakeS:
+		return "HandShakeS";
+		break;
+	    case HandShake:
+		return "HandShake";
+		break;
+	    default:
+		return "Unknown";
+		break;
+	    }
+	}
 	return cmdnames[cmd];
 }
 
@@ -543,7 +557,10 @@
 	Drbd_Sizes_Packet        Sizes;
 	Drbd_GenCnt_Packet       GenCnt;
 	Drbd_State_Packet        State;
+	Drbd_Req_State_Packet	 ReqState;
+	Drbd_RqS_Reply_Packet	 RqSReply;
 	Drbd_BlockRequest_Packet BlockRequest;
+	Drbd_Discard_Packet	 Discard;
 } __attribute((packed)) Drbd_Polymorph_Packet;
 
 /**********************************************************************/
@@ -1602,63 +1619,29 @@
 }
 
 #ifdef DUMP_EACH_PACKET
+
 /*
+ * variable that controls dumping
+ */
+extern int dump_packets;
+
+#define DUMP_NONE 0
+#define DUMP_SUMMARY 1
+#define DUMP_ALL 2
+#define DUMP_MAX 3
+
+/*
  * enable to dump information about every packet exchange.
  */
-#define INFOP(fmt, args...) \
-	INFO("%s:%d: %s [%d] %s %s " fmt , \
-	     file, line, current->comm, current->pid, \
-	     sockname, recv?"<<<":">>>" \
-	     , ## args )
+extern void _dump_packet(drbd_dev *mdev, struct socket *sock,
+			 int recv, Drbd_Polymorph_Packet *p, char* file, int line);
+
 static inline void
 dump_packet(drbd_dev *mdev, struct socket *sock,
 	    int recv, Drbd_Polymorph_Packet *p, char* file, int line)
 {
-	char *sockname = sock == mdev->meta.socket ? "meta" : "data";
-	int cmd = (recv == 2) ? p->head.command : be16_to_cpu(p->head.command);
-	switch (cmd) {
-	case HandShake:
-		INFOP("%s (%u)\n", be32_to_cpu(p->HandShake.protocol_version));
-		break;
-
-	case Ping:
-	case PingAck:
-	case BecomeSyncTarget:
-	case BecomeSyncSource:
-	case UnplugRemote:
-
-	case SyncParam:
-	case ReportParams:
-		INFOP("%s\n", cmdname(cmd));
-		break;
-
-	case ReportBitMap: /* don't report this */
-		break;
-
-	case Data:
-	case DataReply:
-	case RSDataReply:
-
-	case RecvAck:   /* yes I know. but it is the same layout */
-	case WriteAck:
-	case NegAck:
-
-	case DataRequest:
-	case RSDataRequest:
-		INFOP("%s (%lu,%llx)\n", cmdname(cmd),
-		     (long)be64_to_cpu(p->Data.sector), (long long)p->Data.block_id
-		);
-		break;
-
-	case Barrier:
-	case BarrierAck:
-		INFOP("%s (%u)\n", cmdname(cmd), p->Barrier.barrier);
-		break;
-
-	default:
-		INFOP("%s (%u)\n",cmdname(cmd), cmd);
-		break;
-	}
+	if (dump_packets > DUMP_NONE)
+		_dump_packet(mdev,sock,recv,p,file,line);
 }
 #else
 #define dump_packet(ignored...) ((void)0)

^ permalink raw reply	[flat|nested] 5+ messages in thread
* RE: [Drbd-dev] Proposed update to packet dumping code
@ 2006-08-10  0:43 Graham, Simon
  0 siblings, 0 replies; 5+ messages in thread
From: Graham, Simon @ 2006-08-10  0:43 UTC (permalink / raw)
  To: Lars Ellenberg, drbd-dev

> I'd like to even be able to "echo $mask > sysfs", to select which
> packets to dump. this could be done by reserving the lower values
> (using the first few bits) for generic switching, and if you see a
> higher number with all lower bits cleared, you'd shift it and
interpret
> it as a bitmask.  whether thats useful, I don't know...
> 

I think something like this would be useful too -- the way I'd like to
approach it though is more general - rather than using bits to control
which packet types are printed, I would suggest migrating over time to a
scheme where ALL of the DRBD tracing is controlled by a couple of sysfs
variables -- perhaps using the following:

1. A variable that controls the type of tracing -- packet dumps would be
one type, examples of others might be resync, bitmap,
   activity log, bio's etc -- this variable would be a bitmap

2. A variable to control the verbosity - this would be a value and the
higher the number, the more output is produced.

Having done that, replace the existing trace macros & printk calls with
macros are passed type/level params and which check the values of the
variables inline and then call printk if the trace should be output. Of
course it's important to have a type/level combination that is always
output since there is some output that must always be printed...

This, I think, is orthogonal to the code I sent with this patch though
-- it would have to change a little but it would be straightforward to
make the change in this code (but a fair amount of work to change all
the other trace calls). 

Can I suggest that we (ok, you ;-) add the enhanced packet dumping code
now and maybe later on move to a more dynamic and configurable tracing
scheme? I'm certainly willing to make changes and repost this patch if
there is something specific you'd like me to change...

Simon

PS: Some might argue that the levels already exist by means of the
various printk levels; there are, however, a couple of major issues with
this, including:

1. It's not possible to control the level of output on a per-driver
level
2. The mechanism for getting different levels of printk output to the
console and messages file is confusing and difficult and
   I for one have never managed to grok the /proc/sys/kernel/printk
file...
3. There's no concept of debug types in printk.


^ permalink raw reply	[flat|nested] 5+ messages in thread
* RE: [Drbd-dev] Proposed update to packet dumping code
@ 2006-08-10 19:41 Graham, Simon
  0 siblings, 0 replies; 5+ messages in thread
From: Graham, Simon @ 2006-08-10 19:41 UTC (permalink / raw)
  To: Philipp Reisner, drbd-dev

[-- Attachment #1: Type: text/plain, Size: 1559 bytes --]

I found in debugging my problem that I was still getting too much output, so I've enhanced the trace a little to enable one to specify which devices have their packets traced - I did this by adding a 2nd sysfs variable dump_packet_devs which is a bitmap of devices to trace (which means you can only trace the first 32 devices -- is that a problem for anyone?).

I also fixed up some formatting errors (including fields that are meaningless, adding the socket name to the summary trace, tracing packets sent with drbd_send_cmd2()).

One other thing in this patch is a bit more tracing in tl_verify() when a failure is detected -- you can remove this if you like, but I think it's actually useful (more on this in a separate email later!)

Simon


> -----Original Message-----
> From: drbd-dev-bounces@linbit.com [mailto:drbd-dev-bounces@linbit.com]
> On Behalf Of Philipp Reisner
> Sent: Thursday, August 10, 2006 5:40 AM
> To: drbd-dev@linbit.com
> Subject: Re: [Drbd-dev] Proposed update to packet dumping code
> 
> > Let me know what you think and if anything else should be done.
> > Simon
> 
> Ok, I have applied the patch to trunk...
> 
> -Phil
> --
> : Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
> : LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
> : Schönbrunnerstr 244, 1120 Vienna, Austria    http://www.linbit.com :
> _______________________________________________
> drbd-dev mailing list
> drbd-dev@lists.linbit.com
> http://lists.linbit.com/mailman/listinfo/drbd-dev

[-- Attachment #2: drbd-trace-update.patch --]
[-- Type: application/octet-stream, Size: 3241 bytes --]

Index: drbd_main.c
===================================================================
--- drbd_main.c	(revision 3504)
+++ drbd_main.c	(working copy)
@@ -131,7 +131,12 @@
 			// 0 = none
 			// 1 = summary (trace 'interesting' packets in summary fmt)
 			// 2 = verbose (trace all packets in full format)
+int dump_packet_devs = 0;// bitmap of drbd devices to have tracing
+			// enabled
+
 module_param(dump_packets,int,0644);
+module_param(dump_packet_devs,int,0644);
+
 #endif
 
 // devfs name
@@ -306,11 +311,21 @@
 	hlist_for_each_entry(i, n, slot, colision) {
 		if (i==req) {
 			D_ASSERT(drbd_req_get_sector(i) == sector);
+			if (drbd_req_get_sector(i) != sector) {
+				ERR("tl_verify: found req %p but it has wrong sector (%llx versus %llx)\n",
+				    req, (long long)drbd_req_get_sector(i), (long long)sector);
+			}
 			rv=1;
 			break;
 		}
 	}
 
+	// Really better find it!
+	if (!rv) {
+		ERR("tl_verify: failed to find req %p, sector %llx in list\n", 
+		    req, (long long)sector);
+	}
+
 	spin_unlock_irq(&mdev->tl_lock);
 
 	return rv;
@@ -1295,6 +1310,8 @@
 
 	down(&mdev->data.mutex);
 
+	dump_packet(mdev,mdev->data.socket,0,(void*)&h, __FILE__, __LINE__);
+
 	ok = ( sizeof(h) == drbd_send(mdev,mdev->data.socket,&h,sizeof(h),0) );
 	ok = ok && ( size == drbd_send(mdev,mdev->data.socket,data,size,0) );
 
@@ -1713,7 +1730,6 @@
 	unsigned int dp_flags=0;
 
 	down(&mdev->data.mutex);
-
 	p.head.magic   = BE_DRBD_MAGIC;
 	p.head.command = cpu_to_be16(Data);
 	p.head.length  = cpu_to_be16( sizeof(p)-sizeof(Drbd_Header)
@@ -2903,11 +2919,13 @@
 	if (dump_packets > DUMP_SUMMARY) { \
 		INFO("%s:%d: %s [%d] %s %s " fmt , \
 		     file, line, current->comm, current->pid, \
-		     sockname, recv?"<<<":">>>" \
-		     , ## args ); \
+		     sockname, recv?"<<<":">>>", \
+		     ## args ); \
 	} \
 	else { \
-		INFO("%s " fmt, recv?"<<<":">>>", ## args ); \
+		INFO("%s %s " fmt, sockname, \
+		     recv?"<<<":">>>", \
+		     ## args ); \
 	} \
 } while (0)
 
@@ -2929,8 +2947,6 @@
 		break;
 
 	case Data:
-	case DataReply:
-	case RSDataReply:
 		INFOP("%s (sector %llx, id %llx, seq %x, f %x)\n", cmdname(cmd),
 		     (long long)be64_to_cpu(p->Data.sector), 
 		     (long long)be64_to_cpu(p->Data.block_id),
@@ -2939,6 +2955,14 @@
 		);
 		break;
 
+	case DataReply:
+	case RSDataReply:
+		INFOP("%s (sector %llx, id %llx)\n", cmdname(cmd),
+		     (long long)be64_to_cpu(p->Data.sector), 
+		     (long long)be64_to_cpu(p->Data.block_id)
+		);
+		break;
+
 	case RecvAck:
 	case WriteAck:
 	case NegAck:
Index: drbd_int.h
===================================================================
--- drbd_int.h	(revision 3504)
+++ drbd_int.h	(working copy)
@@ -1619,9 +1619,10 @@
 #ifdef DUMP_EACH_PACKET
 
 /*
- * variable that controls dumping
+ * variables that controls dumping
  */
 extern int dump_packets;
+extern int dump_packet_devs; 
 
 #define DUMP_NONE 0
 #define DUMP_SUMMARY 1
@@ -1638,7 +1639,8 @@
 dump_packet(drbd_dev *mdev, struct socket *sock,
 	    int recv, Drbd_Polymorph_Packet *p, char* file, int line)
 {
-	if (dump_packets > DUMP_NONE)
+	if (dump_packets > DUMP_NONE &&
+	    ( ( 1 << (int)(mdev-drbd_conf)) & dump_packet_devs) )
 		_dump_packet(mdev,sock,recv,p,file,line);
 }
 #else

^ permalink raw reply	[flat|nested] 5+ messages in thread
end of thread, other threads:[~2006-08-10 19:41 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2006-08-09 22:50 [Drbd-dev] Proposed update to packet dumping code Graham, Simon
2006-08-09 23:14 ` Lars Ellenberg
2006-08-10  9:39 ` Philipp Reisner
  -- strict thread matches above, loose matches on Subject: below --
2006-08-10  0:43 Graham, Simon
2006-08-10 19:41 Graham, Simon

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.