From 796f3906c183e29a76b9028d3f1358ccc583344b Mon Sep 17 00:00:00 2001 From: Kano Date: Sun, 16 Sep 2012 07:57:43 +1000 Subject: [PATCH] WorkTime - multiple nonce per work and identify the work source --- README | 23 +++++++++------- cgminer.c | 77 ++++++++++++++++++++++++++++++++++++++-------------- driver-cpu.c | 4 +-- miner.h | 19 +++++++------ 4 files changed, 82 insertions(+), 41 deletions(-) diff --git a/README b/README index 7f6f95d7..fd29dc8c 100644 --- a/README +++ b/README @@ -476,19 +476,22 @@ 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 + <-00000059.ed4834a3 M:X G:17:02:38:0.405 C:1.855 (2.995) W:3.440 (0.000) S:0.461 R:17:02:47 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 +The previous hash is followed by the getwork mode used M:X where X is one of +P:Pool, T:Test Pool, L:LP or B:Benchmark, +then G:hh:mm:ss:n.nnn, which is when the getwork or LP was sent to the pool and +the n.nnn is how long it took to reply, +followed by 'O' on it's own if it is an original getwork, or 'C:n.nnn' if it was +a clone with n.nnn stating how long after the work was recieved that it was cloned, +(m.mmm) is how long from when the original work was received 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 submitting the work, +S:n.nnn is how long it took to submit the completed work and await the reply, +R:hh:mm:ss is the actual time the work submit reply was received 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/cgminer.c b/cgminer.c index 791875ff..2b1a2101 100644 --- a/cgminer.c +++ b/cgminer.c @@ -359,7 +359,7 @@ static void sharelog(const char*disposition, const struct work*work) thr_id = work->thr_id; cgpu = thr_info[thr_id].cgpu; pool = work->pool; - t = (unsigned long int)work->share_found_time; + t = (unsigned long int)(work->tv_work_found.tv_sec); target = bin2hex(work->target, sizeof(work->target)); if (unlikely(!target)) { applog(LOG_ERR, "sharelog target OOM"); @@ -1768,6 +1768,7 @@ static bool submit_upstream_work(const struct work *work, CURL *curl, bool resub struct pool *pool = work->pool; int rolltime; uint32_t *hash32; + struct timeval tv_submit, tv_submit_reply; char hashshow[64+1] = ""; char worktime[200] = ""; @@ -1794,10 +1795,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); + gettimeofday(&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); + gettimeofday(&tv_submit_reply, NULL); if (unlikely(!val)) { applog(LOG_INFO, "submit_upstream_work json_rpc_call failed"); if (!pool_tset(pool, &pool->submit_fail)) { @@ -1821,24 +1822,39 @@ static bool submit_upstream_work(const struct work *work, CURL *curl, bool resub } if (opt_worktime) { + char workclone[20]; + struct tm *tm, tm_getwork, tm_submit_reply; 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), + double work_time = tdiff((struct timeval *)&(work->tv_work_found), (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", + double work_to_submit = tdiff(&tv_submit, + (struct timeval *)&(work->tv_work_found)); + double submit_time = tdiff(&tv_submit_reply, &tv_submit); + + tm = localtime(&(work->tv_getwork.tv_sec)); + memcpy(&tm_getwork, tm, sizeof(struct tm)); + tm = localtime(&(tv_submit_reply.tv_sec)); + memcpy(&tm_submit_reply, tm, sizeof(struct tm)); + + if (work->clone) { + sprintf(workclone, "C:%1.3f", + tdiff((struct timeval *)&(work->tv_cloned), + (struct timeval *)&(work->tv_getwork_reply))); + } + else + strcpy(workclone, "O"); + + sprintf(worktime, " <-%08lx.%08lx M:%c G:%02d:%02d:%02d:%1.3f %s (%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); + work->getwork_mode, tm_getwork.tm_hour, tm_getwork.tm_min, + tm_getwork.tm_sec, getwork_time, workclone, + getwork_to_work, work_time, work_to_submit, submit_time, + tm_submit_reply.tm_hour, tm_submit_reply.tm_min, + tm_submit_reply.tm_sec); } } @@ -2022,6 +2038,9 @@ static void get_benchmark_work(struct work *work) memcpy(work, &bench_block, min_size); work->mandatory = true; work->pool = pools[0]; + gettimeofday(&(work->tv_getwork), NULL); + memcpy(&(work->tv_getwork_reply), &(work->tv_getwork), sizeof(struct timeval)); + work->getwork_mode = GETWORK_MODE_BENCHMARK; } static bool get_upstream_work(struct work *work, CURL *curl) @@ -2068,6 +2087,7 @@ static bool get_upstream_work(struct work *work, CURL *curl) work->pool = pool; work->longpoll = false; + work->getwork_mode = GETWORK_MODE_POOL; total_getworks++; pool->getwork_requested++; @@ -2376,6 +2396,7 @@ static struct work *make_clone(struct work *work) memcpy(work_clone, work, sizeof(struct work)); work_clone->clone = true; + gettimeofday((struct timeval *)&(work_clone->tv_cloned), NULL); work_clone->longpoll = false; work_clone->mandatory = false; /* Make cloned work appear slightly older to bias towards keeping the @@ -3845,6 +3866,7 @@ static void *longpoll_thread(void *userdata); static bool pool_active(struct pool *pool, bool pinging) { + struct timeval tv_getwork, tv_getwork_reply; bool ret = false; json_t *val; CURL *curl; @@ -3857,8 +3879,10 @@ static bool pool_active(struct pool *pool, bool pinging) } applog(LOG_INFO, "Testing pool %s", pool->rpc_url); + gettimeofday(&tv_getwork, NULL); val = json_rpc_call(curl, pool->rpc_url, pool->rpc_userpass, rpc_req, true, false, &rolltime, pool, false); + gettimeofday(&tv_getwork_reply, NULL); if (val) { struct work *work = make_work(); @@ -3870,6 +3894,9 @@ static bool pool_active(struct pool *pool, bool pinging) pool->pool_no, pool->rpc_url); work->pool = pool; work->rolltime = rolltime; + memcpy(&(work->tv_getwork), &tv_getwork, sizeof(struct timeval)); + memcpy(&(work->tv_getwork_reply), &tv_getwork_reply, sizeof(struct timeval)); + work->getwork_mode = GETWORK_MODE_TESTPOOL; applog(LOG_DEBUG, "Pushing pooltest work to base pool"); tq_push(thr_info[stage_thr_id].q, work); @@ -4161,7 +4188,7 @@ out: work->mined = true; } -bool submit_work_sync(struct thr_info *thr, const struct work *work_in) +bool submit_work_sync(struct thr_info *thr, const struct work *work_in, struct timeval *tv_work_found) { struct workio_cmd *wc; @@ -4176,7 +4203,8 @@ bool submit_work_sync(struct thr_info *thr, const struct work *work_in) wc->cmd = WC_SUBMIT_WORK; wc->thr = thr; memcpy(wc->work, work_in, sizeof(*work_in)); - wc->work->share_found_time = time(NULL); + if (tv_work_found) + memcpy(&(wc->work->tv_work_found), tv_work_found, sizeof(struct timeval)); applog(LOG_DEBUG, "Pushing submit work to work thread"); @@ -4247,7 +4275,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); + struct timeval tv_work_found; + gettimeofday(&tv_work_found, NULL); total_diff1++; thr->cgpu->diff1++; @@ -4258,7 +4287,7 @@ bool submit_nonce(struct thr_info *thr, struct work *work, uint32_t nonce) if (!test_nonce(thr, work, nonce)) return true; - return submit_work_sync(thr, work); + return submit_work_sync(thr, work, &tv_work_found); } static inline bool abandon_work(struct work *work, struct timeval *wdiff, uint64_t hashes) @@ -4471,7 +4500,7 @@ enum { }; /* Stage another work item from the work returned in a longpoll */ -static void convert_to_work(json_t *val, int rolltime, struct pool *pool) +static void convert_to_work(json_t *val, int rolltime, struct pool *pool, struct timeval *tv_lp, struct timeval *tv_lp_reply) { struct work *work; bool rc; @@ -4487,6 +4516,9 @@ static void convert_to_work(json_t *val, int rolltime, struct pool *pool) work->pool = pool; work->rolltime = rolltime; work->longpoll = true; + memcpy(&(work->tv_getwork), tv_lp, sizeof(struct timeval)); + memcpy(&(work->tv_getwork_reply), tv_lp_reply, sizeof(struct timeval)); + work->getwork_mode = GETWORK_MODE_LP; if (pool->enabled == POOL_REJECTING) work->mandatory = true; @@ -4555,7 +4587,7 @@ static void *longpoll_thread(void *userdata) /* This *pool is the source of the actual longpoll, not the pool we've * tied it to */ struct pool *pool = NULL; - struct timeval start, end; + struct timeval start, reply, end; CURL *curl = NULL; int failures = 0; int rolltime; @@ -4600,13 +4632,16 @@ retry_pool: curl_easy_setopt(curl, CURLOPT_FRESH_CONNECT, 1); val = json_rpc_call(curl, pool->lp_url, pool->rpc_userpass, rpc_req, false, true, &rolltime, pool, false); + + gettimeofday(&reply, NULL); + if (likely(val)) { soval = json_object_get(json_object_get(val, "result"), "submitold"); if (soval) pool->submit_old = json_is_true(soval); else pool->submit_old = false; - convert_to_work(val, rolltime, pool); + convert_to_work(val, rolltime, pool, &start, &reply); failures = 0; json_decref(val); } else { diff --git a/driver-cpu.c b/driver-cpu.c index 8ffc7802..e3a74de6 100644 --- a/driver-cpu.c +++ b/driver-cpu.c @@ -75,7 +75,7 @@ static inline void affine_to_cpu(int id, int cpu) /* TODO: resolve externals */ -extern bool submit_work_sync(struct thr_info *thr, const struct work *work_in); +extern bool submit_work_sync(struct thr_info *thr, const struct work *work_in, struct timeval *tv); extern char *set_int_range(const char *arg, int *i, int min, int max); extern int dev_from_id(int thr_id); @@ -827,7 +827,7 @@ CPUSearch: /* if nonce found, submit work */ if (unlikely(rc)) { applog(LOG_DEBUG, "CPU %d found something?", dev_from_id(thr_id)); - if (unlikely(!submit_work_sync(thr, work))) { + if (unlikely(!submit_work_sync(thr, work, NULL))) { applog(LOG_ERR, "Failed to submit_work_sync in miner_thread %d", thr_id); } work->blk.nonce = last_nonce + 1; diff --git a/miner.h b/miner.h index 13f15412..74cc0019 100644 --- a/miner.h +++ b/miner.h @@ -798,6 +798,11 @@ struct pool { struct cgminer_pool_stats cgminer_pool_stats; }; +#define GETWORK_MODE_TESTPOOL 'T' +#define GETWORK_MODE_POOL 'P' +#define GETWORK_MODE_LP 'L' +#define GETWORK_MODE_BENCHMARK 'B' + struct work { unsigned char data[128]; unsigned char hash1[64]; @@ -830,14 +835,12 @@ struct work { int id; 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; + struct timeval tv_getwork; + struct timeval tv_getwork_reply; + struct timeval tv_cloned; + struct timeval tv_work_start; + struct timeval tv_work_found; + char getwork_mode; }; #ifdef USE_MODMINER