[Drbd-dev] DRBD-8: <FOR REVIEW> dynamic tracing facility

[Drbd-dev] DRBD-8: <FOR REVIEW> dynamic tracing facility

[Graham, Simon]

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

As we discussed a few weeks ago, I propose adding a more general purpose
trace facility that can be controlled at run time - attached is a patch
that implements the following:

. New macros TRACE/MTRACE that can be used to add trace statements
(using existing macros/routines) that
  are controlled at run time.
. Controls are module parameters:
  . trace_type - bitmap of enabled types; currently defined are
packet-dump, bio-dump, uuid-dump
  . trace_level - the higher the level, the more detail
  . trace_devs - bitmap of devices for which trace is enabled
. I've converted the packet dumping code to use this
. I've added two new types using it:
  . bio-dump - this dumps info on bio's coming from above drbd. This is
controlled by a new config
    parameter DUMP_EACH_BIO that is off by default (although I think it
could be on by default and
    will be in our version).
  . uuid-dump - dumps info on updates to uuid's, comparisons, etc

I actually went back and forth on how much of this to implement inline
versus via a routine call and it turned out to be pretty much the same
amount of code at each trace site no matter what so I made it all
inline.

Comments?
Simon


[-- Attachment #2: drbd-traceupdate.patch --]
[-- Type: application/octet-stream, Size: 15969 bytes --]

Index: drbd/drbd_receiver.c
===================================================================
--- drbd/drbd_receiver.c	(.../trunk)	(revision 4334)
+++ drbd/drbd_receiver.c	(.../branches/panic-2)	(revision 4334)
@@ -1742,13 +1742,14 @@
 	int hg;
 	drbd_conns_t rv = conn_mask;
 
-	//INFO("drbd_sync_handshake:\n");
-	//drbd_uuid_dump(mdev,"self",mdev->bc->md.uuid);
-	//drbd_uuid_dump(mdev,"peer",mdev->p_uuid);
-
 	hg = drbd_uuid_compare(mdev);
 
-	//INFO("uuid_compare()=%d\n",hg);
+	MTRACE(TraceTypeUuid,TraceLvlSummary,
+	       INFO("drbd_sync_handshake:\n");
+	       drbd_uuid_dump(mdev,"self",mdev->bc->md.uuid);
+	       drbd_uuid_dump(mdev,"peer",mdev->p_uuid);
+	       INFO("uuid_compare()=%d\n",hg);
+	    );
 
 	if (hg == 100) {
 		int pcount = (mdev->state.role==Primary) + (peer_role==Primary);
Index: drbd/drbd_actlog.c
===================================================================
--- drbd/drbd_actlog.c	(.../trunk)	(revision 4334)
+++ drbd/drbd_actlog.c	(.../branches/panic-2)	(revision 4334)
@@ -731,10 +731,10 @@
 	sbnr = BM_SECT_TO_BIT(sector + BM_SECT_PER_BIT-1);
 
 #ifdef DUMP_EACH_PACKET
-	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);
-	}
+	MTRACE(TraceTypePacket, TraceLvlAll,
+	       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;
@@ -796,10 +796,10 @@
 	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);
-	}
+	MTRACE(TraceTypePacket, TraceLvlAll,
+	       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...
Index: drbd/linux/drbd_config.h
===================================================================
--- drbd/linux/drbd_config.h	(.../trunk)	(revision 4334)
+++ drbd/linux/drbd_config.h	(.../branches/panic-2)	(revision 4334)
@@ -43,12 +43,15 @@
 // Dump every hour the usage / not usage of zero copy IO
 //#define SHOW_SENDPAGE_USAGE
 
+// Include code to enable dumping of BIOs received from above
+//#define DUMP_EACH_BIO
+
 // You can disable the use of the sendpage() call (= zero copy
 // IO )  If you have the feeling that this might be the cause
Index: drbd/drbd_main.c
===================================================================
--- drbd/drbd_main.c	(.../trunk)	(revision 4334)
+++ drbd/drbd_main.c	(.../branches/panic-2)	(revision 4334)
@@ -38,6 +38,7 @@
 #include <asm/uaccess.h>
 #include <asm/types.h>
 #include <net/sock.h>
+#include <linux/ctype.h>
 #include <linux/smp_lock.h>
 #include <linux/fs.h>
 #include <linux/file.h>
@@ -110,19 +111,14 @@
 
 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)
-int dump_packet_devs = 0;// bitmap of drbd devices to have tracing
-			// enabled
+int trace_type = 0;	// Bitmap of trace types to enable
+int trace_level= 0;	// Current trace level
+int trace_devs = 0;	// Bitmap of devices to trace
 
-module_param(dump_packets,int,0644);
-module_param(dump_packet_devs,int,0644);
+module_param(trace_level,int,0644);
+module_param(trace_type,int,0644);
+module_param(trace_devs,int,0644);
 
-#endif
-
 // global panic flag
 volatile int drbd_did_panic = 0;
 
@@ -2640,12 +2636,33 @@
 	mod_timer(&mdev->md_sync_timer,jiffies + 5*HZ );
 }
 
+static char *_drbd_uuid_str(unsigned int idx) {
+	static char *uuid_str[] = {
+		"Current",
+		"Bitmap",
+		"History_start",
+		"History_end",
+		"UUID_SIZE",
+		"UUID_FLAGS",
+	};
+
+	return (idx < EXT_UUID_SIZE) ? uuid_str[idx] : "*Unknown UUID index*";
+}
+
+static void _drbd_print_uuid(drbd_dev *mdev, unsigned int idx) {
+	INFO(" uuid[%s] now %016llX\n",_drbd_uuid_str(idx),mdev->bc->md.uuid[idx]);
+}
+
 static void drbd_uuid_move_history(drbd_dev *mdev)
 {
 	int i;
 
 	for ( i=History_start ; i<History_end ; i++ ) {
 		mdev->bc->md.uuid[i+1] = mdev->bc->md.uuid[i];
+
+		MTRACE(TraceTypeUuid,TraceLvlAll,
+		       _drbd_print_uuid(mdev,i+1);
+			);
 	}
 }
 
@@ -2656,6 +2673,11 @@
 	} else {
 		mdev->bc->md.uuid[idx] = val & ~((u64)1);
 	}
+
+	MTRACE(TraceTypeUuid,TraceLvlSummary,
+	       _drbd_print_uuid(mdev,idx);
+		);
+
 	drbd_md_mark_dirty(mdev);
 }
 
@@ -2665,6 +2687,9 @@
 	if(mdev->bc->md.uuid[idx]) {
 		drbd_uuid_move_history(mdev);
 		mdev->bc->md.uuid[History_start]=mdev->bc->md.uuid[idx];
+		MTRACE(TraceTypeUuid,TraceLvlMetrics,
+		       _drbd_print_uuid(mdev,History_start);
+			);
 	}
 	_drbd_uuid_set(mdev,idx,val);
 }
@@ -2673,12 +2698,21 @@
 {
 	D_ASSERT(mdev->bc->md.uuid[Bitmap] == 0);
 	mdev->bc->md.uuid[Bitmap] = mdev->bc->md.uuid[Current];
+	MTRACE(TraceTypeUuid,TraceLvlMetrics,
+	       _drbd_print_uuid(mdev,Bitmap);
+		);
+
 	get_random_bytes(&mdev->bc->md.uuid[Current], sizeof(u64));
 	if (mdev->state.role == Primary) {
 		mdev->bc->md.uuid[Current] |= 1;
 	} else {
 		mdev->bc->md.uuid[Current] &= ~((u64)1);
 	}
+
+	MTRACE(TraceTypeUuid,TraceLvlSummary,
+	       _drbd_print_uuid(mdev,Current);
+		);
+
 	drbd_md_mark_dirty(mdev);
 }
 
@@ -2690,11 +2724,20 @@
 		drbd_uuid_move_history(mdev);
 		mdev->bc->md.uuid[History_start]=mdev->bc->md.uuid[Bitmap];
 		mdev->bc->md.uuid[Bitmap]=0;
+
+		MTRACE(TraceTypeUuid,TraceLvlMetrics,
+		       _drbd_print_uuid(mdev,History_start);
+		       _drbd_print_uuid(mdev,Bitmap);
+			);
 	} else {
 		if( mdev->bc->md.uuid[Bitmap] ) WARN("bm UUID already set");
 
 		mdev->bc->md.uuid[Bitmap] = val;
 		mdev->bc->md.uuid[Bitmap] &= ~((u64)1);
+
+		MTRACE(TraceTypeUuid,TraceLvlMetrics,
+		       _drbd_print_uuid(mdev,Bitmap);
+			);
 	}
 	drbd_md_mark_dirty(mdev);
 }
@@ -2822,7 +2865,7 @@
 
 #define INFOP(fmt, args...) \
 do { \
-	if (dump_packets > DUMP_SUMMARY) { \
+	if (trace_level >= TraceLvlAll) { \
 		INFO("%s:%d: %s [%d] %s %s " fmt , \
 		     file, line, current->comm, current->pid, \
 		     sockname, recv?"<<<":">>>", \
@@ -2941,7 +2984,7 @@
 		/*
 		 * Dont trace pings at summary level
 		 */
-		if (dump_packets <= DUMP_SUMMARY)
+		if (trace_level < TraceLvlAll)
 			break;
 		/* fall through... */
 	default:
@@ -2951,5 +2994,199 @@
 }
 #endif
 
+/*
+
+DbgPrintBuffer
+
+This routine dumps binary data to the debugging output. Can be
+called at interrupt level.
+
+Arguments:
+
+    prefix      - String is output at the beginning of each line output
+    flags       - Control operation of the routine. Currently defined
+                  Flags are:
+                  DBGPRINT_BUFFADDR; if set, each line starts with the
+                      virtual address of the line being outupt. If clear,
+                      each line starts with the offset from the beginning
+                      of the buffer.
+    size        - Indicates the size of each entry in the buffer. Supported
+                  values are sizeof(char), sizeof(short) and sizeof(int)
+    buffer      - Start address of buffer
+    buffer_va   - Virtual address of start of buffer (normally the same
+                  as Buffer, but having it separate allows it to hold
+                  file address for example)
+    length      - length of buffer
+
+*/
+void
+drbd_print_buffer(const char *prefix,unsigned int flags,int size,
+		  const void *buffer,const void *buffer_va,
+		  unsigned int length)
+
+#define LINE_SIZE       16
+#define LINE_ENTRIES    (int)(LINE_SIZE/size)
+{
+	const unsigned char *pstart;
+	const unsigned char *pstart_va;
+	const unsigned char *pend;
+	char bytes_str[LINE_SIZE*3+8],ascii_str[LINE_SIZE+8];
+	char *pbytes=bytes_str,*pascii=ascii_str;
+	int  offset=0;
+	long sizemask;
+	int  field_width;
+	int  index;
+	const unsigned char *pend_str;
+	const unsigned char *p;
+	int count;
+
+	// verify size parameter 
+	if (size != sizeof(char) && size != sizeof(short) && size != sizeof(int)) {
+		printk(KERN_DEBUG "drbd_print_buffer: ERROR invalid size %d\n", size);
+		return;
+	}
+
+	sizemask = size-1;
+	field_width = size*2;
+
+	// Adjust start/end to be on appropriate boundary for size
+	buffer = (const char *)((long)buffer & ~sizemask);
+	pend   = (const unsigned char *)(((long)buffer + length + sizemask) & ~sizemask);
+
+	if (flags & DBGPRINT_BUFFADDR) {
+		// Move start back to nearest multiple of line size if printing address
+		// This results in nicely formatted output with addresses being on
+		// line size (16) byte boundaries
+		pstart = (const unsigned char *)((long)buffer & ~(LINE_SIZE-1));
+	}
+	else {
+		pstart = (const unsigned char *)buffer;
+	}
+
+	// Set value of start VA to print if addresses asked for
+	pstart_va = (const unsigned char *)buffer_va - ((const unsigned char *)buffer-pstart);
+
+	// Calculate end position to nicely align right hand side
+	pend_str = pstart + (((pend-pstart) + LINE_SIZE-1) & ~(LINE_SIZE-1));
+
+	// Init strings
+	*pbytes = *pascii = '\0';
+
+	// Start at beginning of first line
+	p = pstart;
+	count=0;
+
+	while (p < pend_str) {
+		if (p < (const unsigned char *)buffer || p >= pend) {
+			// Before start of buffer or after end- print spaces
+			pbytes += sprintf(pbytes,"%*c ",field_width,' ');
+			pascii += sprintf(pascii,"%*c",size,' ');
+			p += size;
+		}
+		else {
+			// Add hex and ascii to strings
+			int val;
+			switch (size) {
+			default:
+			case 1:
+				val = *(unsigned char *)p;
+				break;
+			case 2:
+				val = *(unsigned short *)p;
+				break;
+			case 4:
+				val = *(unsigned int *)p;
+				break;
+			}
+
+			pbytes += sprintf(pbytes,"%0*x ",field_width,val);
+
+			for (index = size; index; index--) {
+				*pascii++ = isprint(*p) ? *p : '.';
+				p++;
+			}
+		}
+
+		count++;
+
+		if (count == LINE_ENTRIES || p >= pend_str) {
+			// Null terminate and print record
+			*pascii = '\0';
+			printk(KERN_DEBUG "%s%8.8lx: %*s|%*s|\n",
+			       prefix,
+			       (flags & DBGPRINT_BUFFADDR)
+			       ? (long)pstart_va : (long)offset,
+			       LINE_ENTRIES*(field_width+1),bytes_str,
+			       LINE_SIZE,ascii_str);
+
+			// Move onto next line
+			pstart_va += (p-pstart);
+			pstart = p;
+			count  = 0;
+			offset+= LINE_SIZE;
+
+			// Re-init strings
+			pbytes = bytes_str;
+			pascii = ascii_str;
+			*pbytes = *pascii = '\0';
+		}
+	}
+}
+
+
+// Debug routine to dump info about bio
+
+#ifdef DUMP_EACH_BIO
+#ifdef CONFIG_LBD
+#define SECTOR_FORMAT "%Lx"
+#else
+#define SECTOR_FORMAT "%lx"
+#endif
+#define SECTOR_SHIFT 9
+
+void _dump_bio(drbd_dev *mdev, struct bio *bio, int complete)
+{
+	unsigned long lowaddr = (unsigned long)(bio->bi_sector << SECTOR_SHIFT);
+	char *faddr = (char *)(lowaddr);
+	struct bio_vec *bvec;
+	int segno;
+
+	INFO("%s %s Bio:%p - %soffset " SECTOR_FORMAT ", size %x\n",
+	     complete? "<<<":">>>",
+	     bio_rw(bio)==WRITE?"Write":"Read",bio,
+	     complete? (drbd_bio_uptodate(bio)? "Success, ":"Failed, ") : "",
+	     bio->bi_sector << SECTOR_SHIFT, 
+	     bio->bi_size);
+
+	if (trace_level >= TraceLvlMetrics &&
+	    ((bio_rw(bio) == WRITE) ^ complete) ) {
+		printk(KERN_DEBUG "  ind     page   offset   length\n");
+		__bio_for_each_segment(bvec, bio, segno, 0) {
+			printk(KERN_DEBUG "  [%d] %p %8.8x %8.8x\n",segno,
+			       bvec->bv_page, bvec->bv_offset, bvec->bv_len);
+
+			if (trace_level >= TraceLvlAll) {
+				char *bvec_buf;
+				unsigned long flags;
+
+				bvec_buf = bvec_kmap_irq(bvec, &flags);
+
+				drbd_print_buffer("    ",DBGPRINT_BUFFADDR,1, 
+						  bvec_buf, 
+						  faddr, 
+						  (bvec->bv_len <= 0x80)? bvec->bv_len : 0x80);
+
+				bvec_kunmap_irq(bvec_buf, &flags);
+
+				if (bvec->bv_len > 0x40)
+					printk(KERN_DEBUG "    ....\n");
+
+				faddr += bvec->bv_len;
+			}
+		}
+	}
+}
+#endif
+
 module_init(drbd_init)
 module_exit(drbd_cleanup)
Index: drbd/drbd_req.c
===================================================================
--- drbd/drbd_req.c	(.../trunk)	(revision 4334)
+++ drbd/drbd_req.c	(.../branches/panic-2)	(revision 4334)
@@ -177,6 +177,7 @@
 		 * up here anyways during the freeze ...
 		 * then again, if it is a READ, it is not in the TL at all.
 		 * is it still leagal to complete a READ during freeze? */
+		dump_bio(mdev,req->master_bio,1);
 		bio_endio(req->master_bio, req->master_bio->bi_size, ok ? 0 : -EIO);
 		req->master_bio = NULL;
 		dec_ap_bio(mdev);
@@ -744,6 +745,8 @@
 		return 0;
 	}
 
+	dump_bio(mdev,bio,0);
+
 	local = inc_local(mdev);
 	if (!local) {
 		bio_put(req->private_bio); /* or we get a bio leak */
Index: drbd/drbd_int.h
===================================================================
--- drbd/drbd_int.h	(.../trunk)	(revision 4334)
+++ drbd/drbd_int.h	(.../branches/panic-2)	(revision 4334)
@@ -254,7 +254,7 @@
 /* drbd_meta-data.c (still in drbd_main.c) */
 #define DRBD_MD_MAGIC (DRBD_MAGIC+4) // 4th incarnation of the disk layout.
 
-#define DRBD_PANIC 3
+#define DRBD_PANIC 2
 /* do_panic alternatives:
  *	0: panic();
  *	1: machine_halt; SORRY, this DOES NOT WORK
@@ -1194,6 +1194,78 @@
 
 extern drbd_dev *drbd_new_device(int minor);
 
+// Dynamic tracing framework
+
+extern int trace_type;
+extern int trace_devs;
+extern int trace_level;
+
+enum {
+	TraceLvlAlways = 0,
+	TraceLvlSummary,
+	TraceLvlMetrics,
+	TraceLvlAll,
+	TraceLvlMax
+};
+
+enum {
+	TraceTypePacket = 0x00000001,
+	TraceTypeRq     = 0x00000002,
+	TraceTypeUuid	= 0x00000004,
+};
+
+static inline int
+is_trace(unsigned int type, unsigned int level) {
+	return ((trace_level >= level) && (type & trace_type));
+}
+static inline int
+is_mdev_trace(drbd_dev *mdev, unsigned int type, unsigned int level) {
+	return (is_trace(type, level) && 
+		( ( 1 << mdev_to_minor(mdev)) & trace_devs));
+}
+
+#define MTRACE(type,lvl,code...) \
+do { \
+	if (unlikely(is_mdev_trace(mdev,type,lvl))) { \
+		code \
+	} \
+} while (0)
+
+#define TRACE(type,lvl,code...) \
+do { \
+	if (unlikely(is_trace(type,lvl))) { \
+		code \
+	} \
+} while (0)
+
+// Buffer printing support
+// DbgPrintFlags: used for Flags arg to DbgPrintBuffer
+// - DBGPRINT_BUFFADDR; if set, each line starts with the
+//       virtual address of the line being output. If clear,
+//       each line starts with the offset from the beginning
+//       of the buffer.
+typedef enum {
+    DBGPRINT_BUFFADDR = 0x0001,
+}  DbgPrintFlags;
+
+extern void
+drbd_print_buffer(const char *prefix,unsigned int flags,int size,
+		  const void *buffer,const void *buffer_va,
+		  unsigned int length);
+
+// Bio printing support
+#ifdef DUMP_EACH_BIO
+extern void _dump_bio(drbd_dev *mdev, struct bio *bio, int complete);
+
+static inline void dump_bio(drbd_dev *mdev, struct bio *bio, int complete) {
+	MTRACE(TraceTypeRq,TraceLvlSummary,
+	       _dump_bio(mdev, bio, complete);
+		);
+}
+#else
+#define dump_bio(ignored...) ((void)0)
+#endif
+
 // drbd_req
 extern int drbd_make_request_26(request_queue_t *q, struct bio *bio);
 extern int drbd_read_remote(drbd_dev *mdev, drbd_request_t *req);
@@ -1724,17 +1796,6 @@
 #ifdef DUMP_EACH_PACKET
 
 /*
- * variables that controls dumping
- */
-extern int dump_packets;
-extern int dump_packet_devs; 
-
-#define DUMP_NONE 0
-#define DUMP_SUMMARY 1
-#define DUMP_ALL 2
-#define DUMP_MAX 3
-
-/*
  * enable to dump information about every packet exchange.
  */
 extern void _dump_packet(drbd_dev *mdev, struct socket *sock,
@@ -1744,9 +1805,9 @@
 dump_packet(drbd_dev *mdev, struct socket *sock,
 	    int recv, Drbd_Polymorph_Packet *p, char* file, int line)
 {
-	if (dump_packets > DUMP_NONE &&
-	    ( ( 1 << mdev_to_minor(mdev)) & dump_packet_devs) )
-		_dump_packet(mdev,sock,recv,p,file,line);
+	MTRACE(TraceTypePacket, TraceLvlSummary,
+	       _dump_packet(mdev,sock,recv,p,file,line);
+		);
 }
 #else
 #define dump_packet(ignored...) ((void)0)

Re: [Drbd-dev] DRBD-8: <FOR REVIEW> dynamic tracing facility

[Philipp Reisner]

Am Sonntag, 24. September 2006 15:47 schrieb Graham, Simon:
> As we discussed a few weeks ago, I propose adding a more general purpose
> trace facility that can be controlled at run time - attached is a patch
> that implements the following:
>
> . New macros TRACE/MTRACE that can be used to add trace statements
> (using existing macros/routines) that
>   are controlled at run time.
> . Controls are module parameters:
>   . trace_type - bitmap of enabled types; currently defined are
> packet-dump, bio-dump, uuid-dump
>   . trace_level - the higher the level, the more detail
>   . trace_devs - bitmap of devices for which trace is enabled
> . I've converted the packet dumping code to use this
> . I've added two new types using it:
>   . bio-dump - this dumps info on bio's coming from above drbd. This is
> controlled by a new config
>     parameter DUMP_EACH_BIO that is off by default (although I think it
> could be on by default and
>     will be in our version).
>   . uuid-dump - dumps info on updates to uuid's, comparisons, etc
>
> I actually went back and forth on how much of this to implement inline
> versus via a routine call and it turned out to be pretty much the same
> amount of code at each trace site no matter what so I made it all
> inline.
>
> Comments?

Hi Simon,

I have two opinions about this:
 * Good stuff, it is nice to have all this in place, although I would 
   also like to disable the whole tracing/dumping at compile time.

 * On the other hand I am not sure if it could become obsolete by
   the current rumours about a DTrace replacement on Linux (SystemTrap)

So, over all, I will accept a patch:
 * That converts our current stuff over to such a tracing framework
 * Probably add event more tracing. (As you have done for UUIDs)
 * The tracing facility allowes to enable/disable different classes
   of tracing information at run-time.
 * But I would also like to disable it at completely at compile time.

-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 :

RE: [Drbd-dev] DRBD-8: <FOR REVIEW> dynamic tracing facility

[Graham, Simon]

Hi Philipp,

Just want to make sure I understand fully...

> I have two opinions about this:
>  * Good stuff, it is nice to have all this in place, although I would
>    also like to disable the whole tracing/dumping at compile time.
> 
>  * On the other hand I am not sure if it could become obsolete by
>    the current rumours about a DTrace replacement on Linux
(SystemTrap)

I was not aware of DTrace but I have looked at SystemTap and decided it
doesn't really work -- we need some level of trace that is always turned
on (so we can diagnose field problems after the fact) combined with the
ability to enable more extensive tracing at will and I don't think
SystemTap will do both of these. To be honest I don't really like the
fact that the tracing definition is separate from the driver code
(probably the exact reason why other people like it 
;-)

Also -- whilst there may be work afoot to add this to the kernel, we
need this now with the current kernel versions we are going to ship
product with - I know that printk's are perhaps not the best (especially
if you aren't careful about where to insert them) but they do provide
what is needed now.

> 
> So, over all, I will accept a patch:
>  * That converts our current stuff over to such a tracing framework

Do you mean you want all the existing INFO/WARN/etc tracing to use this?

I did consider this but decided not to for a couple of reasons:
1. Lots of this trace should continue to always be printed -- I could
add
   an option to the framework that lets the caller specify 'always print
   this' but I'm not sure it adds value. However, I can see that there
is
   benefit in having ALL trace code wrapped in the new framework macros
   
2. I didn't want to include the overhead of testing trace types/levels
etc
   in every single place where a trace message is output - however, I
can 
   certainly arrange for these to generate no code in the cases
   where the output should always be produced.

3. It would be a huge patch to change every single trace call in one go.

So, to be honest, I decided not to do this initially but just get a
framework
in place and then let you and Lars convert what you think needs it ;-)

Now - I can certainly change all of the existing trace calls to use the
new
TRACE/MTRACE macros if that's really what you want (btw, the existing
INFO/WARN/etc
macros wont go away, they will just be wrapped by the new trace call).

>  * Probably add event more tracing. (As you have done for UUIDs)

Can we leave adding this until later? It's rather difficult for me to
decide
all the possible extra tracing that is needed ;-)

>  * The tracing facility allowes to enable/disable different classes
>    of tracing information at run-time.

Something more than I have already done? The intent of the trace_types
parameter
is exactly this - to define the class(es) of output required.

if I convert the existing trace statements, I'll probably add one (maybe
two)
more trace types that cover the existing stuff and have it enabled by
default.

>  * But I would also like to disable it at completely at compile time.

Including the existing trace statements?
I'm OK with this, just checking that's what you want - the ability to
generate a driver with no tracing in it at all.

Thanks for your review,
Simon 

Re: [Drbd-dev] DRBD-8: <FOR REVIEW> dynamic tracing facility

[Philipp Reisner]

Am Dienstag, 26. September 2006 23:42 schrieb Graham, Simon:
> Hi Philipp,
>
> Just want to make sure I understand fully...
>
> > I have two opinions about this:
> >  * Good stuff, it is nice to have all this in place, although I would
> >    also like to disable the whole tracing/dumping at compile time.
> >
> >  * On the other hand I am not sure if it could become obsolete by
> >    the current rumours about a DTrace replacement on Linux
>
> (SystemTrap)
>
> I was not aware of DTrace but I have looked at SystemTap and decided it
> doesn't really work -- we need some level of trace that is always turned
> on (so we can diagnose field problems after the fact) combined with the
> ability to enable more extensive tracing at will and I don't think
> SystemTap will do both of these. To be honest I don't really like the
> fact that the tracing definition is separate from the driver code
> (probably the exact reason why other people like it
> ;-)
>
> Also -- whilst there may be work afoot to add this to the kernel, we
> need this now with the current kernel versions we are going to ship
> product with - I know that printk's are perhaps not the best (especially
> if you aren't careful about where to insert them) but they do provide
> what is needed now.

Right.

> > So, over all, I will accept a patch:
> >  * That converts our current stuff over to such a tracing framework
>
> Do you mean you want all the existing INFO/WARN/etc tracing to use this?
>

Hi Simon,

No, sorry. I did not express myself clearly.

I am happy with your approach:
 1) Having the framework in place first
 2) Converting the current INFO/WARN statements over to it next
 3) Adding more stuff to it later

I think the only thing that was missing from your patch
was the ability to disable it completely it compile time.

If you had not sent it with the comment 'FOR REVIEW' I had probably
comited it to SVN. ;)

-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 :

RE: [Drbd-dev] DRBD-8: <FOR REVIEW> dynamic tracing facility

[Graham, Simon]

> 
> I think the only thing that was missing from your patch
> was the ability to disable it completely it compile time.
> 

Got it -- I will make that change and resubmit the patch today - thanks
for the clarification.

Simon