Index: drbd/drbd_receiver.c =================================================================== --- drbd/drbd_receiver.c (.../trunk) (revision 4486) +++ drbd/drbd_receiver.c (.../branches/panic-2) (revision 4486) @@ -1754,13 +1754,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 4486) +++ drbd/drbd_actlog.c (.../branches/panic-2) (revision 4486) @@ -729,12 +729,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); - } -#endif + MTRACE(TraceTypePacket, TraceLvlAll, + INFO("drbd_set_in_sync: sector=%llx size=%x sbnr=%lx ebnr=%lx\n", + (long long)sector, size, sbnr, ebnr); + ); if (sbnr > ebnr) return; @@ -794,12 +792,10 @@ 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 + MTRACE(TraceTypePacket, TraceLvlAll, + INFO("drbd_set_out_of_sync: sector=%llx size=%x sbnr=%lx ebnr=%lx\n", + (long long)sector, size, sbnr, ebnr); + ); /* 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 (.../trunk) (revision 4486) +++ drbd/linux/drbd_config.h (.../branches/panic-2) (revision 4486) @@ -36,19 +36,20 @@ #define DUMP_MD 2 // Dump even all cstate changes (I like it!) //#define PARANOIA // some extra checks -// 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 +// Define this to enable dynamic tracing controlled by module parameters +// at run time. This enables ALL use of dynamic tracing including packet +// and bio dumping, etc +#define ENABLE_DYNAMIC_TRACE + // You can disable the use of the sendpage() call (= zero copy // IO ) If you have the feeling that this might be the cause // for troubles. Index: drbd/drbd_main.c =================================================================== --- drbd/drbd_main.c (.../trunk) (revision 4486) +++ drbd/drbd_main.c (.../branches/panic-2) (revision 4486) @@ -38,6 +38,7 @@ #include #include #include +#include #include #include #include @@ -110,17 +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 +#ifdef ENABLE_DYNAMIC_TRACE +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 @@ -513,7 +511,7 @@ } -static void print_st(drbd_dev* mdev, char *name, drbd_state_t ns) +STATIC void print_st(drbd_dev* mdev, char *name, drbd_state_t ns) { ERR(" %s = { cs:%s st:%s/%s ds:%s/%s %c%c%c%c }\n", name, @@ -1436,7 +1434,7 @@ * This helper function expects the sector and block_id parameter already * in big endian! */ -static int _drbd_send_ack(drbd_dev *mdev, Drbd_Packet_Cmd cmd, +STATIC int _drbd_send_ack(drbd_dev *mdev, Drbd_Packet_Cmd cmd, u64 sector, u32 blksize, u64 block_id) @@ -2141,7 +2139,7 @@ return -ENOMEM; } -static int drbd_notify_sys(struct notifier_block *this, unsigned long code, +STATIC int drbd_notify_sys(struct notifier_block *this, unsigned long code, void *unused) { /* just so we have it. you never know what interessting things we @@ -2151,12 +2149,12 @@ return NOTIFY_DONE; } -static struct notifier_block drbd_notifier = { +STATIC struct notifier_block drbd_notifier = { .notifier_call = drbd_notify_sys, }; -static void __exit drbd_cleanup(void) +STATIC void __exit drbd_cleanup(void) { int i, rr; @@ -2657,12 +2655,17 @@ mod_timer(&mdev->md_sync_timer,jiffies + 5*HZ ); } -static void drbd_uuid_move_history(drbd_dev *mdev) + +STATIC void drbd_uuid_move_history(drbd_dev *mdev) { int i; for ( i=History_start ; ibc->md.uuid[i+1] = mdev->bc->md.uuid[i]; + + MTRACE(TraceTypeUuid,TraceLvlAll, + drbd_print_uuid(mdev,i+1); + ); } } @@ -2673,6 +2676,11 @@ } else { mdev->bc->md.uuid[idx] = val & ~((u64)1); } + + MTRACE(TraceTypeUuid,TraceLvlSummary, + drbd_print_uuid(mdev,idx); + ); + drbd_md_mark_dirty(mdev); } @@ -2682,6 +2690,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); } @@ -2690,12 +2701,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); } @@ -2707,11 +2727,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); } @@ -2769,7 +2798,7 @@ * Crude but fast random-number generator. Uses a linear congruential * generator, with occasional help from get_random_bytes(). */ -static unsigned long +STATIC unsigned long _drbd_fault_random(struct fault_random_state *rsp) { long refresh; @@ -2783,7 +2812,7 @@ return swahw32(rsp->state); } -static char * +STATIC char * _drbd_fault_str(unsigned int type) { static char *_faults[] = { "Meta-data write", @@ -2812,7 +2841,167 @@ } #endif -#ifdef DUMP_EACH_PACKET +#ifdef ENABLE_DYNAMIC_TRACE + +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*"; +} + +/* Pretty print a UUID value */ +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]); +} + + +/* + +drbd_print_buffer + +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'; + } + } +} + #define PSM(A) \ do { \ if( mask.A ) { \ @@ -2839,7 +3028,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?"<<<":">>>", \ @@ -2958,7 +3147,7 @@ /* * Dont trace pings at summary level */ - if (dump_packets <= DUMP_SUMMARY) + if (trace_level < TraceLvlAll) break; /* fall through... */ default: @@ -2966,7 +3155,59 @@ break; } } + +// Debug routine to dump info about bio + +void _dump_bio(drbd_dev *mdev, struct bio *bio, int complete) +{ +#ifdef CONFIG_LBD +#define SECTOR_FORMAT "%Lx" +#else +#define SECTOR_FORMAT "%lx" #endif +#define SECTOR_SHIFT 9 + 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 4486) +++ drbd/drbd_req.c (.../branches/panic-2) (revision 4486) @@ -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); @@ -749,6 +750,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 4486) +++ drbd/drbd_int.h (.../branches/panic-2) (revision 4486) @@ -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 @@ -1191,6 +1191,98 @@ extern drbd_dev *drbd_new_device(int minor); +// Dynamic tracing framework +#ifdef ENABLE_DYNAMIC_TRACE + +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_uuid(drbd_dev *mdev, unsigned int idx); + +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 +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); + ); +} + +// Packet dumping support +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) +{ + MTRACE(TraceTypePacket, TraceLvlSummary, + _dump_packet(mdev,sock,recv,p,file,line); + ); +} + +#else + +#define MTRACE(ignored...) ((void)0) +#define TRACE(ignored...) ((void)0) + +#define dump_bio(ignored...) ((void)0) +#define dump_packet(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); @@ -1750,37 +1842,6 @@ return seq; } -#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, - 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) -{ - if (dump_packets > DUMP_NONE && - ( ( 1 << mdev_to_minor(mdev)) & dump_packet_devs) ) - _dump_packet(mdev,sock,recv,p,file,line); -} -#else -#define dump_packet(ignored...) ((void)0) -#endif - static inline void drbd_suicide(void) { #ifdef TASK_ZOMBIE