Merge commit 'bd3c98a' into cgmerges

Conflicts:
	miner.c
	miner.h

API-README

@@ -313,14 +313,16 @@ The list of requests - a (*) means it requires privileged access - and replies a
                               the screen curses debug settings
                               You can only specify one setting
                               Only the first character is checked (case insensitive):
-                              Silent, Quiet, Verbose, Debug, RPCProto, PerDevice, Normal
+                              Silent, Quiet, Verbose, Debug, RPCProto, PerDevice,
+                              WorkTime, Normal
                               The output fields are (as above):
                               Silent=true/false,
                               Quiet=true/false,
                               Verbose=true/false,
                               Debug=true/false,
                               RPCProto=true/false,
-                              PerDevice=true/false|
+                              PerDevice=true/false,
+                              WorkTime=true/false|
 
  setconfig|name,N (*)
                none           There is no reply section just the STATUS section

README

@@ -480,6 +480,22 @@ it will log to a file called logfile.txt and otherwise work the same.
 There is also the -m option on linux which will spawn a command of your choice
 and pipe the output directly to that command.
 
+The WorkTime details 'debug' option adds details on the end of each line
+displayed for Accepted or Rejected work done. An example would be:
+
+  <-00000223.95214f4c O G:0.524 (97.672) W:4.910 (0.000) S:0.577 R:13:49:55
+
+The first 2 hex codes are the previous block hash, the rest are reported in
+seconds unless stated otherwise:
+The previous hash is followed by 'C' or 'O' if the work was cloned or original,
+G:n.nnn is how long the original getwork to the pool took, (m.mmm) is how long
+from the original getwork complete until work started, W:n.nnn is how long the
+work took to process until it was ready to submit, (m.mmm) is how long from
+ready to submit to actually doing the submit, this is usually 0.000 unless
+there was a problem with the first attempt at submitting the work, S:n.nnn
+is how long it took to submit the work and await the reply, R:hh:mm:ss is the
+actual time the work submit reply was received - so you can count back from
+that to work out each absolute time
 
 If you start BFGMiner with the --sharelog option, you can get detailed
 information for each share found. The argument to the option may be "-" for

api.c

@@ -2839,6 +2839,10 @@ static void debugstate(__maybe_unused SOCKETTYPE c, char *param, bool isjson, __
 		opt_quiet = false;
 		opt_protocol = false;
 		want_per_device_stats = false;
+		opt_worktime = false;
+		break;
+	case 'w':
+		opt_worktime ^= true;
 		break;
 	default:
 		// anything else just reports the settings
@@ -2856,6 +2860,7 @@ static void debugstate(__maybe_unused SOCKETTYPE c, char *param, bool isjson, __
 	root = api_add_bool(root, "Debug", &opt_debug, false);
 	root = api_add_bool(root, "RPCProto", &opt_protocol, false);
 	root = api_add_bool(root, "PerDevice", &want_per_device_stats, false);
+	root = api_add_bool(root, "WorkTime", &opt_worktime, false);
 
 	root = print_data(root, buf, isjson);
 	if (isjson)

miner.c

@@ -159,6 +159,7 @@ bool opt_delaynet;
 bool opt_disable_pool = true;
 char *opt_icarus_options = NULL;
 char *opt_icarus_timing = NULL;
+bool opt_worktime;
 
 char *opt_kernel_path;
 char *cgminer_path;
@@ -1195,6 +1196,9 @@ static struct opt_table opt_config_table[] = {
 	OPT_WITH_ARG("--userpass|-O",
 		     set_userpass, NULL, NULL,
 		     "Username:Password pair for bitcoin JSON-RPC server"),
+	OPT_WITHOUT_ARG("--worktime",
+			opt_set_bool, &opt_worktime,
+			"Display extra work time debug information"),
 	OPT_WITH_ARG("--pools",
 			opt_set_bool, NULL, NULL, opt_hidden),
 	OPT_ENDTABLE
@@ -2098,6 +2102,7 @@ static bool submit_upstream_work(const struct work *work, CURL *curl, bool resub
 	int rolltime;
 	uint32_t *hash32;
 	char hashshow[64+1] = "";
+	char worktime[200] = "";
 
 	if (work->tmpl) {
 		unsigned char data[76];
@@ -2128,12 +2133,14 @@ static bool submit_upstream_work(const struct work *work, CURL *curl, bool resub
 
 	applog(LOG_DEBUG, "DBG: sending %s submit RPC call: %s", pool->rpc_url, sd);
 
+	gettimeofday((struct timeval *)&(work->tv_submit), NULL);
 	/* issue JSON-RPC request */
 	val = json_rpc_call(curl, pool->rpc_url, pool->rpc_userpass, s, false, false, &rolltime, pool, true);
 
 	free(s);
 	free(sd);
 
+	gettimeofday((struct timeval *)&(work->tv_submit_reply), NULL);
 	if (unlikely(!val)) {
 		applog(LOG_INFO, "submit_upstream_work json_rpc_call failed");
 		if (!pool_tset(pool, &pool->submit_fail)) {
@@ -2155,6 +2162,27 @@ static bool submit_upstream_work(const struct work *work, CURL *curl, bool resub
 			sprintf(hashshow, "%08lx.%08lx%s", (unsigned long)(hash32[6]), (unsigned long)(hash32[5]),
 				work->block? " BLOCK!" : "");
 		}
+
+		if (opt_worktime) {
+			double getwork_time = tdiff((struct timeval *)&(work->tv_getwork_reply),
+							(struct timeval *)&(work->tv_getwork));
+			double getwork_to_work = tdiff((struct timeval *)&(work->tv_work_start),
+							(struct timeval *)&(work->tv_getwork_reply));
+			double work_time = tdiff((struct timeval *)&(work->tv_work_finish),
+							(struct timeval *)&(work->tv_work_start));
+			double work_to_submit = tdiff((struct timeval *)&(work->tv_submit),
+							(struct timeval *)&(work->tv_work_finish));
+			double submit_time = tdiff((struct timeval *)&(work->tv_submit_reply),
+							(struct timeval *)&(work->tv_submit));
+			struct tm *tm = localtime(&(work->tv_submit_reply.tv_sec));
+			sprintf(worktime, " <-%08lx.%08lx %c G:%1.3f (%1.3f) W:%1.3f (%1.3f) S:%1.3f R:%02d:%02d:%02d",
+				(unsigned long)swab32(*(uint32_t *)&(work->data[28])),
+				(unsigned long)swab32(*(uint32_t *)&(work->data[24])),
+				work->clone ? 'C' : 'O',
+				getwork_time, getwork_to_work, work_time,
+				work_to_submit, submit_time,
+				tm->tm_hour, tm->tm_min, tm->tm_sec);
+		}
 	}
 
 	/* Theoretically threads could race when modifying accepted and
@@ -2173,11 +2201,11 @@ static bool submit_upstream_work(const struct work *work, CURL *curl, bool resub
 		applog(LOG_DEBUG, "PROOF OF WORK RESULT: true (yay!!!)");
 		if (!QUIET) {
 			if (total_pools > 1)
-				applog(LOG_NOTICE, "Accepted %s %s %d pool %d %s",
-				       hashshow, cgpu->api->name, cgpu->device_id, work->pool->pool_no, resubmit ? "(resubmit)" : "");
+				applog(LOG_NOTICE, "Accepted %s %s %d pool %d %s%s",
+				       hashshow, cgpu->api->name, cgpu->device_id, work->pool->pool_no, resubmit ? "(resubmit)" : "", worktime);
 			else
-				applog(LOG_NOTICE, "Accepted %s %s %d %s",
-				       hashshow, cgpu->api->name, cgpu->device_id, resubmit ? "(resubmit)" : "");
+				applog(LOG_NOTICE, "Accepted %s %s %d %s%s",
+				       hashshow, cgpu->api->name, cgpu->device_id, resubmit ? "(resubmit)" : "", worktime);
 		}
 		sharelog("accept", work);
 		if (opt_shares && total_accepted >= opt_shares) {
@@ -2227,8 +2255,8 @@ static bool submit_upstream_work(const struct work *work, CURL *curl, bool resub
 			} else
 				strcpy(reason, "");
 
-			applog(LOG_NOTICE, "Rejected %s %s %d %s%s %s",
-			       hashshow, cgpu->api->name, cgpu->device_id, where, reason, resubmit ? "(resubmit)" : "");
+			applog(LOG_NOTICE, "Rejected %s %s %d %s%s %s%s",
+			       hashshow, cgpu->api->name, cgpu->device_id, where, reason, resubmit ? "(resubmit)" : "", worktime);
 			sharelog(disposition, work);
 		}
 
@@ -2411,7 +2439,7 @@ static bool get_upstream_work(struct work *work, CURL *curl)
 {
 	struct pool *pool = work->pool;
 	struct cgminer_pool_stats *pool_stats = &(pool->cgminer_pool_stats);
-	struct timeval tv_start, tv_end, tv_elapsed;
+	struct timeval tv_elapsed;
 	json_t *val = NULL;
 	bool rc = false;
 	char *url;
@@ -2428,7 +2456,7 @@ tryagain:
 
 	url = pool->rpc_url;
 
-	gettimeofday(&tv_start, NULL);
+	gettimeofday(&(work->tv_getwork), NULL);
 
 	val = json_rpc_call(curl, url, pool->rpc_userpass, rpc_req, false,
 			    false, &work->rolltime, pool, false);
@@ -2447,8 +2475,8 @@ tryagain:
 	} else
 		applog(LOG_DEBUG, "Failed json_rpc_call in get_upstream_work");
 
-	gettimeofday(&tv_end, NULL);
-	timersub(&tv_end, &tv_start, &tv_elapsed);
+	gettimeofday(&(work->tv_getwork_reply), NULL);
+	timersub(&(work->tv_getwork_reply), &(work->tv_getwork), &tv_elapsed);
 	pool_stats->getwork_wait_rolling += ((double)tv_elapsed.tv_sec + ((double)tv_elapsed.tv_usec / 1000000)) * 0.63;
 	pool_stats->getwork_wait_rolling /= 1.63;
 
@@ -4093,12 +4121,13 @@ static void display_options(void)
 	clear_logwin();
 retry:
 	wlogprint("[N]ormal [C]lear [S]ilent mode (disable all output)\n");
-	wlogprint("[D]ebug:%s\n[P]er-device:%s\n[Q]uiet:%s\n[V]erbose:%s\n[R]PC debug:%s\n[L]og interval:%d\n",
+	wlogprint("[D]ebug:%s\n[P]er-device:%s\n[Q]uiet:%s\n[V]erbose:%s\n[R]PC debug:%s\n[W]orkTime details:%s\n[L]og interval:%d\n",
 		opt_debug_console ? "on" : "off",
 	        want_per_device_stats? "on" : "off",
 		opt_quiet ? "on" : "off",
 		opt_log_output ? "on" : "off",
 		opt_protocol ? "on" : "off",
+		opt_worktime ? "on" : "off",
 		opt_log_interval);
 	wlogprint("Select an option or any other key to return\n");
 	input = getch();
@@ -4152,6 +4181,10 @@ retry:
 		goto retry;
 	} else if (!strncasecmp(&input, "s", 1)) {
 		opt_realquiet = true;
+	} else if (!strncasecmp(&input, "w", 1)) {
+		opt_worktime ^= true;
+		wlogprint("WorkTime details %s\n", opt_worktime ? "enabled" : "disabled");
+		goto retry;
 	} else
 		clear_logwin();
 
@@ -4972,6 +5005,8 @@ bool test_nonce(struct work *work, uint32_t nonce, bool checktarget)
 
 bool submit_nonce(struct thr_info *thr, struct work *work, uint32_t nonce)
 {
+	gettimeofday(&(work->tv_work_finish), NULL);
+
 	total_diff1++;
 	thr->cgpu->diff1++;
 	work->pool->diff1++;
@@ -5103,6 +5138,8 @@ void *miner_thread(void *userdata)
 			}
 			pool_stats->getwork_calls++;
 
+			gettimeofday(&(work->tv_work_start), NULL);
+
 			thread_reportin(mythr);
 			hashes = api->scanhash(mythr, work, work->blk.nonce + max_nonce);
 			thread_reportin(mythr);

miner.h

@@ -501,6 +501,7 @@ extern void thr_info_cancel(struct thr_info *thr);
 extern void thr_info_freeze(struct thr_info *thr);
 extern void nmsleep(unsigned int msecs);
 extern void rename_thr(const char* name);
+extern double tdiff(struct timeval *end, struct timeval *start);
 
 struct string_elist {
 	char *string;
@@ -642,6 +643,7 @@ extern bool opt_delaynet;
 extern bool opt_restart;
 extern char *opt_icarus_options;
 extern char *opt_icarus_timing;
+extern bool opt_worktime;
 #ifdef USE_BITFORCE
 extern bool opt_bfl_noncerange;
 #endif
@@ -909,6 +911,13 @@ struct work {
 	blktemplate_t	*tmpl;
 	int		*tmpl_refcount;
 	unsigned int	dataid;
+
+	struct timeval tv_getwork;
+	struct timeval tv_getwork_reply;
+	struct timeval tv_work_start;
+	struct timeval tv_work_finish;
+	struct timeval tv_submit;
+	struct timeval tv_submit_reply;
 };
 
 extern void get_datestamp(char *, struct timeval *);

util.c

@@ -766,3 +766,9 @@ void rename_thr(const char* name) {
 	(void)name;
 #endif
 }
+
+/* Returns the seconds difference between end and start times as a double */
+double tdiff(struct timeval *end, struct timeval *start)
+{
+	return end->tv_sec - start->tv_sec + (end->tv_usec - start->tv_usec) / 1000000.0;
+}