ckdb - add some process and lock time stats to shift processing

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__

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;
 }

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);