thodg/cgminer

diff --git a/API-README b/API-README
index 0e66170..1fa904d 100644
--- a/API-README
+++ b/API-README
@@ -312,14 +312,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
diff --git a/README b/README
index 4baa0d2..7f6f95d 100644
--- a/README
+++ b/README
@@ -473,6 +473,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 cgminer with the --sharelog option, you can get detailed
 information for each share found. The argument to the option may be "-" for
diff --git a/api.c b/api.c
index 67f0d78..ddd938a 100644
--- a/api.c
+++ b/api.c
@@ -2911,6 +2911,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
@@ -2928,6 +2932,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)
diff --git a/cgminer.c b/cgminer.c
index 9e9ef64..791875f 100644
--- a/cgminer.c
+++ b/cgminer.c
@@ -142,6 +142,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;
@@ -1063,6 +1064,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
@@ -1765,6 +1769,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] = "";
 
 #ifdef __BIG_ENDIAN__
         int swapcounter = 0;
@@ -1789,8 +1794,10 @@ 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);
+	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)) {
@@ -1812,6 +1819,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
@@ -1828,11 +1856,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) {
@@ -1881,8 +1909,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);
 		}
 
@@ -2000,7 +2028,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;
@@ -2009,7 +2037,7 @@ static bool get_upstream_work(struct work *work, CURL *curl)
 
 	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);
@@ -2022,8 +2050,8 @@ static bool get_upstream_work(struct work *work, CURL *curl)
 	} 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;
 
@@ -3425,12 +3453,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 ? "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();
@@ -3483,6 +3512,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();
 
@@ -4214,6 +4247,8 @@ static bool test_nonce(struct thr_info *thr, struct work *work, uint32_t nonce)
 
 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++;
@@ -4338,6 +4373,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);
diff --git a/miner.h b/miner.h
index 924bc85..13f1541 100644
--- a/miner.h
+++ b/miner.h
@@ -456,6 +456,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 double us_tdiff(struct timeval *end, struct timeval *start);
+extern double tdiff(struct timeval *end, struct timeval *start);
 
 struct string_elist {
 	char *string;
@@ -582,6 +583,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
@@ -829,6 +831,13 @@ struct work {
 	UT_hash_handle hh;
 
 	time_t share_found_time;
+
+	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;
 };
 
 #ifdef USE_MODMINER 
diff --git a/util.c b/util.c
index 59743fd..b3a5a1b 100644
--- a/util.c
+++ b/util.c
@@ -787,3 +787,9 @@ double us_tdiff(struct timeval *end, struct timeval *start)
 {
 	return end->tv_sec * 1000000 + end->tv_usec - start->tv_sec * 1000000 - start->tv_usec;
 }
+
+/* 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;
+}