Merge pull request #465 from kanoi/master

timeout reporting and remove unused fpgautils code

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,36 @@ 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[1].count == 0 &&
+			cgpu->usbinfo.usb_tmo[2].count == 0) {
+				snprintf(details, sizeof(details),
+					 "%"PRIu64" 0", cgpu->usbinfo.tmo_count);
+		} else {
+			snprintf(details, sizeof(details),
+				 "%"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);
+		}
+
+		root = api_add_string(root, "USB tmo", details, true);
 #endif
 	}
 

usbutils.c

@@ -458,14 +458,17 @@ 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 SECTOMS(s) ((int)((s) * 1000))
+
+#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 STATS_TIMEVAL(tv)
-#define USB_REJECT(sgpu, mode)
+#define USB_STATS(sgpu_, sta_, fin_, err_, mode_, cmd_, seq_, tmo_)
+#define STATS_TIMEVAL(tv_)
+#define USB_REJECT(sgpu_, mode_)
 
 #endif // DO_USB_STATS
 
@@ -2118,15 +2121,45 @@ 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, extrams;
 
 	if (cgpu->usbinfo.usbstat < 1)
 		newstats(cgpu);
 
+	cgpu->usbinfo.tmo_count++;
+
+	// 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), totms, 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;
+		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]);
 	details->modes |= mode;
 
@@ -2234,7 +2267,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 +2294,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 +2614,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 +2702,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 +2743,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 +2793,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 +2820,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);
 

usbutils.h

@@ -186,6 +186,19 @@ 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;
+	uint32_t min_tmo;
+	uint32_t max_tmo;
+	uint64_t total_over;
+	uint64_t total_tmo;
+};
+
 struct cg_usb_info {
 	uint8_t bus_number;
 	uint8_t device_address;
@@ -224,6 +237,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 {