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 #include #include +#include #include #include #include @@ -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 ; ibc->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)