From 660012678a60fa88e9391a7f2119e167c762c492 Mon Sep 17 00:00:00 2001 From: Kano Date: Sat, 20 Jul 2013 07:04:31 +1000 Subject: [PATCH 1/5] usbutils ensure stats macros are using the macro arguments --- usbutils.c | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/usbutils.c b/usbutils.c index 25e8f02b..19fa7297 100644 --- a/usbutils.c +++ b/usbutils.c @@ -458,14 +458,14 @@ struct cg_usb_stats { static struct cg_usb_stats *usb_stats = NULL; static int next_stat = USB_NOSTAT; -#define USB_STATS(sgpu, sta, fin, err, mode, cmd, seq) \ - stats(cgpu, sta, fin, err, mode, cmd, seq) -#define STATS_TIMEVAL(tv) cgtime(tv) -#define USB_REJECT(sgpu, mode) rejected_inc(sgpu, mode) +#define USB_STATS(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_) \ + stats(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_) +#define STATS_TIMEVAL(tv_) cgtime(tv_) +#define USB_REJECT(sgpu_, mode_) rejected_inc(sgpu_, mode_) #else -#define USB_STATS(sgpu, sta, fin, err, mode, cmd, seq) -#define STATS_TIMEVAL(tv) -#define USB_REJECT(sgpu, mode) +#define USB_STATS(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_) +#define STATS_TIMEVAL(tv_) +#define USB_REJECT(sgpu_, mode_) #endif // DO_USB_STATS From 52cda25f980ec6ebb87c317cd1c5fdb9c5bfa938 Mon Sep 17 00:00:00 2001 From: Kano Date: Sat, 20 Jul 2013 10:24:29 +1000 Subject: [PATCH 2/5] usbutils report failed timeouts --- usbutils.c | 43 +++++++++++++++++++++++++++++-------------- 1 file changed, 29 insertions(+), 14 deletions(-) diff --git a/usbutils.c b/usbutils.c index 19fa7297..fecd2e5b 100644 --- a/usbutils.c +++ b/usbutils.c @@ -458,12 +458,18 @@ struct cg_usb_stats { static struct cg_usb_stats *usb_stats = NULL; static int next_stat = USB_NOSTAT; -#define USB_STATS(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_) \ - stats(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_) +#define SECTOMS(s) ((int)((s) * 1000)) + +// timeout checks are only done when stats are enabled +#define TIMEOUT_OVER_MS 500 + +#define USB_STATS(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_, tmo_) \ + stats(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_, tmo_) #define STATS_TIMEVAL(tv_) cgtime(tv_) #define USB_REJECT(sgpu_, mode_) rejected_inc(sgpu_, mode_) + #else -#define USB_STATS(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_) +#define USB_STATS(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_, tmo_) #define STATS_TIMEVAL(tv_) #define USB_REJECT(sgpu_, mode_) @@ -2118,15 +2124,23 @@ void update_usb_stats(__maybe_unused struct cgpu_info *cgpu) } #if DO_USB_STATS -static void stats(struct cgpu_info *cgpu, struct timeval *tv_start, struct timeval *tv_finish, int err, int mode, enum usb_cmds cmd, int seq) +static void stats(struct cgpu_info *cgpu, struct timeval *tv_start, struct timeval *tv_finish, int err, int mode, enum usb_cmds cmd, int seq, int timeout) { struct cg_usb_stats_details *details; double diff; - int item; + int item, elapsedms; if (cgpu->usbinfo.usbstat < 1) newstats(cgpu); + // timeout checks are only done when stats are enabled + elapsedms = SECTOMS(tdiff(tv_finish, tv_start)); + if (elapsedms > (timeout + TIMEOUT_OVER_MS)) { + applog(LOG_ERR, "%s%i: TIMEOUT %s took %dms but was %dms", + cgpu->drv->name, cgpu->device_id, + usb_cmdname(cmd), elapsedms, timeout) ; + } + details = &(usb_stats[cgpu->usbinfo.usbstat - 1].details[cmd * 2 + seq]); details->modes |= mode; @@ -2234,7 +2248,7 @@ usb_bulk_transfer(struct libusb_device_handle *dev_handle, errn = errno; cg_runlock(&cgusb_fd_lock); STATS_TIMEVAL(&tv_finish); - USB_STATS(cgpu, &tv_start, &tv_finish, err, mode, cmd, seq); + USB_STATS(cgpu, &tv_start, &tv_finish, err, mode, cmd, seq, timeout); if (err < 0) applog(LOG_DEBUG, "%s%i: %s (amt=%d err=%d ern=%d)", @@ -2261,7 +2275,7 @@ usb_bulk_transfer(struct libusb_device_handle *dev_handle, errn = errno; cg_runlock(&cgusb_fd_lock); STATS_TIMEVAL(&tv_finish); - USB_STATS(cgpu, &tv_start, &tv_finish, err, mode, cmd, seq); + USB_STATS(cgpu, &tv_start, &tv_finish, err, mode, cmd, seq, timeout); if (err < 0) applog(LOG_DEBUG, "%s%i: %s (amt=%d err=%d ern=%d)", @@ -2581,7 +2595,6 @@ int _usb_write(struct cgpu_info *cgpu, int ep, char *buf, size_t bufsiz, int *pr } usbdev = cgpu->usbdev; - if (timeout == DEVTIMEOUT) timeout = usbdev->found->timeout; @@ -2670,6 +2683,8 @@ int __usb_transfer(struct cgpu_info *cgpu, uint8_t request_type, uint8_t bReques goto out_; } usbdev = cgpu->usbdev; + if (timeout == DEVTIMEOUT) + timeout = usbdev->found->timeout; USBDEBUG("USB debug: @_usb_transfer() data=%s", bin2hex((unsigned char *)data, (size_t)siz)); @@ -2709,11 +2724,10 @@ int __usb_transfer(struct cgpu_info *cgpu, uint8_t request_type, uint8_t bReques STATS_TIMEVAL(&tv_start); cg_rlock(&cgusb_fd_lock); err = libusb_control_transfer(usbdev->handle, request_type, - bRequest, wValue, wIndex, (unsigned char *)buf, (uint16_t)siz, - timeout == DEVTIMEOUT ? usbdev->found->timeout : timeout); + bRequest, wValue, wIndex, (unsigned char *)buf, (uint16_t)siz, timeout); cg_runlock(&cgusb_fd_lock); STATS_TIMEVAL(&tv_finish); - USB_STATS(cgpu, &tv_start, &tv_finish, err, MODE_CTRL_WRITE, cmd, SEQ0); + USB_STATS(cgpu, &tv_start, &tv_finish, err, MODE_CTRL_WRITE, cmd, SEQ0, timeout); USBDEBUG("USB debug: @_usb_transfer(%s (nodev=%s)) err=%d%s", cgpu->drv->name, bool_str(cgpu->usbinfo.nodev), err, isnodev(err)); @@ -2760,6 +2774,8 @@ int _usb_transfer_read(struct cgpu_info *cgpu, uint8_t request_type, uint8_t bRe goto out_unlock; } usbdev = cgpu->usbdev; + if (timeout == DEVTIMEOUT) + timeout = usbdev->found->timeout; *amount = 0; @@ -2785,11 +2801,10 @@ int _usb_transfer_read(struct cgpu_info *cgpu, uint8_t request_type, uint8_t bRe cg_rlock(&cgusb_fd_lock); err = libusb_control_transfer(usbdev->handle, request_type, bRequest, wValue, wIndex, - (unsigned char *)buf, (uint16_t)bufsiz, - timeout == DEVTIMEOUT ? usbdev->found->timeout : timeout); + (unsigned char *)buf, (uint16_t)bufsiz, timeout); cg_runlock(&cgusb_fd_lock); STATS_TIMEVAL(&tv_finish); - USB_STATS(cgpu, &tv_start, &tv_finish, err, MODE_CTRL_READ, cmd, SEQ0); + USB_STATS(cgpu, &tv_start, &tv_finish, err, MODE_CTRL_READ, cmd, SEQ0, timeout); USBDEBUG("USB debug: @_usb_transfer_read(%s (nodev=%s)) amt/err=%d%s%s%s", cgpu->drv->name, bool_str(cgpu->usbinfo.nodev), err, isnodev(err), err > 0 ? " = " : BLANK, err > 0 ? bin2hex((unsigned char *)buf, (size_t)err) : BLANK); From 2dffc96e3ce0748045ef6ca3f62f2529e0a3409a Mon Sep 17 00:00:00 2001 From: Kano Date: Sat, 20 Jul 2013 12:56:57 +1000 Subject: [PATCH 3/5] log USB timeouts in API stats --- api.c | 26 +++++++++++++++++++++++++- usbutils.c | 27 ++++++++++++++++++--------- usbutils.h | 14 ++++++++++++++ 3 files changed, 57 insertions(+), 10 deletions(-) diff --git a/api.c b/api.c index 8c29bf99..50bbbbf4 100644 --- a/api.c +++ b/api.c @@ -3023,7 +3023,7 @@ static int itemstats(struct io_data *io_data, int i, char *id, struct cgminer_st if (cgpu) { #ifdef USE_USBUTILS - char details[128]; + char details[256]; if (cgpu->usbinfo.pipe_count) snprintf(details, sizeof(details), @@ -3046,6 +3046,30 @@ static int itemstats(struct io_data *io_data, int i, char *id, struct cgminer_st cgpu->usbinfo.total_write_delay); root = api_add_string(root, "USB Delay", details, true); + + if (cgpu->usbinfo.usb_tmo[0].count == 0 && + cgpu->usbinfo.usb_tmo[0].count == 0 && + cgpu->usbinfo.usb_tmo[0].count == 0) { + snprintf(details, sizeof(details), + "%"PRIu64" 0", cgpu->usbinfo.tmo_count); + } else { + snprintf(details, sizeof(details), + "%"PRIu64" %d=%d/%"PRIu64"/%"PRIu64 + " %d=%d/%"PRIu64"/%"PRIu64 + " %d=%d/%"PRIu64"/%"PRIu64" ", + cgpu->usbinfo.tmo_count, + USB_TMO_0, cgpu->usbinfo.usb_tmo[0].count, + cgpu->usbinfo.usb_tmo[0].total_over, + cgpu->usbinfo.usb_tmo[0].total_tmo, + USB_TMO_1, cgpu->usbinfo.usb_tmo[1].count, + cgpu->usbinfo.usb_tmo[1].total_over, + cgpu->usbinfo.usb_tmo[1].total_tmo, + USB_TMO_2, cgpu->usbinfo.usb_tmo[2].count, + cgpu->usbinfo.usb_tmo[2].total_over, + cgpu->usbinfo.usb_tmo[2].total_tmo); + } + + root = api_add_string(root, "USB tmo", details, true); #endif } diff --git a/usbutils.c b/usbutils.c index fecd2e5b..3da8dc29 100644 --- a/usbutils.c +++ b/usbutils.c @@ -460,9 +460,6 @@ static int next_stat = USB_NOSTAT; #define SECTOMS(s) ((int)((s) * 1000)) -// timeout checks are only done when stats are enabled -#define TIMEOUT_OVER_MS 500 - #define USB_STATS(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_, tmo_) \ stats(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_, tmo_) #define STATS_TIMEVAL(tv_) cgtime(tv_) @@ -2128,17 +2125,29 @@ static void stats(struct cgpu_info *cgpu, struct timeval *tv_start, struct timev { struct cg_usb_stats_details *details; double diff; - int item, elapsedms; + int item, extrams; if (cgpu->usbinfo.usbstat < 1) newstats(cgpu); + cgpu->usbinfo.tmo_count++; + // timeout checks are only done when stats are enabled - elapsedms = SECTOMS(tdiff(tv_finish, tv_start)); - if (elapsedms > (timeout + TIMEOUT_OVER_MS)) { - applog(LOG_ERR, "%s%i: TIMEOUT %s took %dms but was %dms", - cgpu->drv->name, cgpu->device_id, - usb_cmdname(cmd), elapsedms, timeout) ; + extrams = SECTOMS(tdiff(tv_finish, tv_start)) - timeout; + if (extrams >= USB_TMO_0) { + int offset = 0; + + if (extrams >= USB_TMO_2) { + applog(LOG_ERR, "%s%i: TIMEOUT %s took %dms but was %dms", + cgpu->drv->name, cgpu->device_id, + usb_cmdname(cmd), extrams+timeout, timeout) ; + offset = 2; + } else if (extrams >= USB_TMO_1) + offset = 1; + + cgpu->usbinfo.usb_tmo[offset].count++; + cgpu->usbinfo.usb_tmo[offset].total_over += extrams; + cgpu->usbinfo.usb_tmo[offset].total_tmo += timeout; } details = &(usb_stats[cgpu->usbinfo.usbstat - 1].details[cmd * 2 + seq]); diff --git a/usbutils.h b/usbutils.h index 75f1e511..abfcc57b 100644 --- a/usbutils.h +++ b/usbutils.h @@ -186,6 +186,17 @@ struct cg_usb_device { #define USB_MAX_READ 8192 +#define USB_TMO_0 50 +#define USB_TMO_1 100 +#define USB_TMO_2 500 +#define USB_TMOS 3 + +struct cg_usb_tmo { + uint32_t count; + uint64_t total_over; + uint64_t total_tmo; +}; + struct cg_usb_info { uint8_t bus_number; uint8_t device_address; @@ -224,6 +235,9 @@ struct cg_usb_info { * multiple of these */ unsigned char bulkbuf[USB_MAX_READ+4]; + + uint64_t tmo_count; + struct cg_usb_tmo usb_tmo[USB_TMOS]; }; enum usb_cmds { From 759ce6e7d2464aad608b6b328280b5ae483aa156 Mon Sep 17 00:00:00 2001 From: Kano Date: Sat, 20 Jul 2013 13:20:24 +1000 Subject: [PATCH 4/5] usb timeouts - min/max also --- api.c | 12 +++++++++--- usbutils.c | 12 +++++++++++- usbutils.h | 2 ++ 3 files changed, 22 insertions(+), 4 deletions(-) diff --git a/api.c b/api.c index 50bbbbf4..b67cff46 100644 --- a/api.c +++ b/api.c @@ -3054,17 +3054,23 @@ static int itemstats(struct io_data *io_data, int i, char *id, struct cgminer_st "%"PRIu64" 0", cgpu->usbinfo.tmo_count); } else { snprintf(details, sizeof(details), - "%"PRIu64" %d=%d/%"PRIu64"/%"PRIu64 - " %d=%d/%"PRIu64"/%"PRIu64 - " %d=%d/%"PRIu64"/%"PRIu64" ", + "%"PRIu64" %d=%d/%d/%d/%"PRIu64"/%"PRIu64 + " %d=%d/%d/%d/%"PRIu64"/%"PRIu64 + " %d=%d/%d/%d/%"PRIu64"/%"PRIu64" ", cgpu->usbinfo.tmo_count, USB_TMO_0, cgpu->usbinfo.usb_tmo[0].count, + cgpu->usbinfo.usb_tmo[0].min_tmo, + cgpu->usbinfo.usb_tmo[0].max_tmo, cgpu->usbinfo.usb_tmo[0].total_over, cgpu->usbinfo.usb_tmo[0].total_tmo, USB_TMO_1, cgpu->usbinfo.usb_tmo[1].count, + cgpu->usbinfo.usb_tmo[1].min_tmo, + cgpu->usbinfo.usb_tmo[1].max_tmo, cgpu->usbinfo.usb_tmo[1].total_over, cgpu->usbinfo.usb_tmo[1].total_tmo, USB_TMO_2, cgpu->usbinfo.usb_tmo[2].count, + cgpu->usbinfo.usb_tmo[2].min_tmo, + cgpu->usbinfo.usb_tmo[2].max_tmo, cgpu->usbinfo.usb_tmo[2].total_over, cgpu->usbinfo.usb_tmo[2].total_tmo); } diff --git a/usbutils.c b/usbutils.c index 3da8dc29..a0dbbe3c 100644 --- a/usbutils.c +++ b/usbutils.c @@ -2135,12 +2135,13 @@ static void stats(struct cgpu_info *cgpu, struct timeval *tv_start, struct timev // timeout checks are only done when stats are enabled extrams = SECTOMS(tdiff(tv_finish, tv_start)) - timeout; if (extrams >= USB_TMO_0) { + uint32_t totms = (uint32_t)(timeout + extrams); int offset = 0; if (extrams >= USB_TMO_2) { applog(LOG_ERR, "%s%i: TIMEOUT %s took %dms but was %dms", cgpu->drv->name, cgpu->device_id, - usb_cmdname(cmd), extrams+timeout, timeout) ; + usb_cmdname(cmd), totms, timeout) ; offset = 2; } else if (extrams >= USB_TMO_1) offset = 1; @@ -2148,6 +2149,15 @@ static void stats(struct cgpu_info *cgpu, struct timeval *tv_start, struct timev cgpu->usbinfo.usb_tmo[offset].count++; cgpu->usbinfo.usb_tmo[offset].total_over += extrams; cgpu->usbinfo.usb_tmo[offset].total_tmo += timeout; + if (cgpu->usbinfo.usb_tmo[offset].min_tmo == 0) { + cgpu->usbinfo.usb_tmo[offset].min_tmo = totms; + cgpu->usbinfo.usb_tmo[offset].max_tmo = totms; + } else { + if (cgpu->usbinfo.usb_tmo[offset].min_tmo > totms) + cgpu->usbinfo.usb_tmo[offset].min_tmo = totms; + if (cgpu->usbinfo.usb_tmo[offset].max_tmo < totms) + cgpu->usbinfo.usb_tmo[offset].max_tmo = totms; + } } details = &(usb_stats[cgpu->usbinfo.usbstat - 1].details[cmd * 2 + seq]); diff --git a/usbutils.h b/usbutils.h index abfcc57b..cc855770 100644 --- a/usbutils.h +++ b/usbutils.h @@ -193,6 +193,8 @@ struct cg_usb_device { struct cg_usb_tmo { uint32_t count; + uint32_t min_tmo; + uint32_t max_tmo; uint64_t total_over; uint64_t total_tmo; }; From 369a45431d8d918005f668ca6a885383716f051a Mon Sep 17 00:00:00 2001 From: Kano Date: Sat, 20 Jul 2013 16:04:04 +1000 Subject: [PATCH 5/5] api correct timeout stat display --- api.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/api.c b/api.c index b67cff46..5d24771e 100644 --- a/api.c +++ b/api.c @@ -3048,8 +3048,8 @@ static int itemstats(struct io_data *io_data, int i, char *id, struct cgminer_st root = api_add_string(root, "USB Delay", details, true); if (cgpu->usbinfo.usb_tmo[0].count == 0 && - cgpu->usbinfo.usb_tmo[0].count == 0 && - cgpu->usbinfo.usb_tmo[0].count == 0) { + cgpu->usbinfo.usb_tmo[1].count == 0 && + cgpu->usbinfo.usb_tmo[2].count == 0) { snprintf(details, sizeof(details), "%"PRIu64" 0", cgpu->usbinfo.tmo_count); } else {