From 4d70a423263f136ba957163222e766a85558724f Mon Sep 17 00:00:00 2001 From: kanoi Date: Sat, 14 May 2016 13:52:51 +1000 Subject: [PATCH] ckdb - add some process and lock time stats to shift processing --- src/ckdb.h | 2 +- src/ckdb_data.c | 18 ++++++++++++++---- src/ckdb_dbio.c | 18 ++++++++++++++---- 3 files changed, 29 insertions(+), 9 deletions(-) diff --git a/src/ckdb.h b/src/ckdb.h index 533d4b25..94faa91b 100644 --- a/src/ckdb.h +++ b/src/ckdb.h @@ -52,7 +52,7 @@ #define DB_VLOCK "1" #define DB_VERSION "1.0.7" -#define CKDB_VERSION DB_VERSION"-2.108" +#define CKDB_VERSION DB_VERSION"-2.109" #define WHERE_FFL " - from %s %s() line %d" #define WHERE_FFL_HERE __FILE__, __func__, __LINE__ diff --git a/src/ckdb_data.c b/src/ckdb_data.c index 3636031f..6271c002 100644 --- a/src/ckdb_data.c +++ b/src/ckdb_data.c @@ -5562,7 +5562,7 @@ bool make_markersummaries(bool msg, char *by, char *code, char *inet, K_ITEM *wm_item, *wm_last = NULL, *s_item = NULL; bool ok, did; int count = 0; - tv_t now; + tv_t now, share_stt, share_fin, proc_lock_stt, proc_lock_fin; K_RLOCK(workmarkers_free); wm_item = last_in_ktree(workmarkers_workinfoid_root, ctx); @@ -5591,6 +5591,7 @@ bool make_markersummaries(bool msg, char *by, char *code, char *inet, * This way we know that the high shares in the DB will match the start * of, or be after the start of, the shares included in the reload * All duplicate high shares are ignored */ + setnow(&share_stt); count = 0; do { did = false; @@ -5600,11 +5601,14 @@ bool make_markersummaries(bool msg, char *by, char *code, char *inet, if (s_item) { did = true; ok = shares_db(conn, s_item); - if (!ok) + if (!ok) { + setnow(&share_fin); goto flailed; + } count++; } } while (did); + setnow(&share_fin); DATA_WORKMARKERS(workmarkers, wm_last); @@ -5628,16 +5632,22 @@ bool make_markersummaries(bool msg, char *by, char *code, char *inet, /* So we can't change any sharesummaries/markersummaries while a * payout is being generated * N.B. this is a long lock since it stores the markersummaries */ + setnow(&proc_lock_stt); K_WLOCK(process_pplns_free); ok = sharesummaries_to_markersummaries(conn, workmarkers, by, code, inet, &now, trf_root); K_WUNLOCK(process_pplns_free); + setnow(&proc_lock_fin); + LOGWARNING("%s() pplns lock time %.3fs", + __func__, tvdiff(&proc_lock_fin, &proc_lock_stt)); flailed: PQfinish(conn); - if (count > 0) - LOGWARNING("%s() Stored: %d high shares", __func__, count); + if (count > 0) { + LOGWARNING("%s() Stored: %d high shares %.3fs", + __func__, count, tvdiff(&share_fin, &share_stt)); + } return ok; } diff --git a/src/ckdb_dbio.c b/src/ckdb_dbio.c index 80ef8d52..e31e3867 100644 --- a/src/ckdb_dbio.c +++ b/src/ckdb_dbio.c @@ -4448,6 +4448,7 @@ bool sharesummaries_to_markersummaries(PGconn *conn, WORKMARKERS *workmarkers, char *reason = NULL; int ss_count, ms_count; char *st = NULL; + tv_t db_stt, db_fin, lck_stt, lck_fin; LOGWARNING("%s() Processing: workmarkers %"PRId64"/%s/" "End %"PRId64"/Stt %"PRId64"/%s/%s", @@ -4594,6 +4595,7 @@ bool sharesummaries_to_markersummaries(PGconn *conn, WORKMARKERS *workmarkers, ss_item = ss_prev; } + setnow(&db_stt); if (conn == NULL) { conn = dbconnect(); conned = true; @@ -4604,6 +4606,7 @@ bool sharesummaries_to_markersummaries(PGconn *conn, WORKMARKERS *workmarkers, PQclear(res); if (!PGOK(rescode)) { PGLOGERR("Begin", rescode, conn); + setnow(&db_fin); goto flail; } @@ -4612,6 +4615,7 @@ bool sharesummaries_to_markersummaries(PGconn *conn, WORKMARKERS *workmarkers, if (!(markersummary_add(conn, ms_item, by, code, inet, cd, trf_root))) { reason = "db error"; + setnow(&db_fin); goto rollback; } ms_item = ms_item->next; @@ -4625,6 +4629,7 @@ bool sharesummaries_to_markersummaries(PGconn *conn, WORKMARKERS *workmarkers, workmarkers->description, MARKER_PROCESSED_STR, by, code, inet, cd, trf_root); + setnow(&db_fin); rollback: if (ok) res = PQexec(conn, "Commit", CKPQ_WRITE); @@ -4638,9 +4643,10 @@ flail: if (reason) { // already displayed the full workmarkers detail at the top - LOGERR("%s() %s: workmarkers %"PRId64"/%s/%s", + LOGERR("%s() %s: workmarkers %"PRId64"/%s/%s db %.3fs", shortname, reason, workmarkers->markerid, - workmarkers->description, workmarkers->status); + workmarkers->description, workmarkers->status, + tvdiff(&db_fin, &db_stt)); ok = false; } @@ -4667,6 +4673,7 @@ flail: ms_count = new_markersummary_store->count; ss_count = old_sharesummary_store->count; + setnow(&lck_stt); K_WLOCK(sharesummary_free); K_WLOCK(markersummary_free); K_RLOCK(workmarkers_free); @@ -4719,16 +4726,19 @@ flail: K_RUNLOCK(workmarkers_free); K_WUNLOCK(markersummary_free); K_WUNLOCK(sharesummary_free); + setnow(&lck_fin); LOGWARNING("%s() Processed: %d ms %d ss %"PRId64" shares " "%"PRId64" diff for workmarkers %"PRId64"/%s/" - "End %"PRId64"/Stt %"PRId64"/%s/%s", + "End %"PRId64"/Stt %"PRId64"/%s/%s db %.3fs " + "lck %.3fs", shortname, ms_count, ss_count, shareacc, diffacc, workmarkers->markerid, workmarkers->poolinstance, workmarkers->workinfoidend, workmarkers->workinfoidstart, workmarkers->description, - workmarkers->status); + workmarkers->status, tvdiff(&db_fin, &db_stt), + tvdiff(&lck_fin, &lck_stt)); } free_ktree(ms_root, NULL); new_markersummary_store = k_free_store(new_markersummary_store);