ckdb - more shift stats

src/ckdb.h

@@ -52,7 +52,7 @@
 
 #define DB_VLOCK "1"
 #define DB_VERSION "1.0.7"
-#define CKDB_VERSION DB_VERSION"-2.110"
+#define CKDB_VERSION DB_VERSION"-2.111"
 
 #define WHERE_FFL " - from %s %s() line %d"
 #define WHERE_FFL_HERE __FILE__, __func__, __LINE__

src/ckdb_data.c

@@ -5564,7 +5564,8 @@ 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, share_stt, share_fin, proc_lock_stt, proc_lock_fin;
+	tv_t now, share_stt, share_fin;
+	tv_t proc_lock_stt, proc_lock_got, proc_lock_fin;
 
 	K_RLOCK(workmarkers_free);
 	wm_item = last_in_ktree(workmarkers_workinfoid_root, ctx);
@@ -5636,12 +5637,14 @@ bool make_markersummaries(bool msg, char *by, char *code, char *inet,
 	 * N.B. this is a long lock since it stores the markersummaries */
 	setnow(&proc_lock_stt);
 	K_WLOCK(process_pplns_free);
+	setnow(&proc_lock_got);
 	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",
+	LOGWARNING("%s() pplns lock time %.3fs+%.3fs",
-		   __func__, tvdiff(&proc_lock_fin, &proc_lock_stt));
+		   __func__, tvdiff(&proc_lock_got, &proc_lock_stt),
+		   tvdiff(&proc_lock_fin, &proc_lock_got));
 
 flailed:
 	PQfinish(conn);

src/ckdb_dbio.c

@@ -4448,7 +4448,11 @@ 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;
+	tv_t add_stt, db_stt, db_fin, lck_stt, lck_got, lck_fin;
+
+	DATE_ZERO(&add_stt);
+	DATE_ZERO(&db_stt);
+	DATE_ZERO(&db_fin);
 
 	LOGWARNING("%s() Processing: workmarkers %"PRId64"/%s/"
 		   "End %"PRId64"/Stt %"PRId64"/%s/%s",
@@ -4474,6 +4478,7 @@ bool sharesummaries_to_markersummaries(PGconn *conn, WORKMARKERS *workmarkers,
 		goto flail;
 	}
 
+	setnow(&add_stt);
 	// Check there aren't already any matching markersummaries
 	lookmarkersummary.markerid = workmarkers->markerid;
 	lookmarkersummary.userid = 0;
@@ -4495,6 +4500,7 @@ bool sharesummaries_to_markersummaries(PGconn *conn, WORKMARKERS *workmarkers,
 		 *  so this will continue and regenerate the markersummaries
 		 */
 		reason = "markersummaries already exist";
+		setnow(&add_stt);
 		goto flail;
 	}
 
@@ -4677,6 +4683,7 @@ flail:
 		K_WLOCK(sharesummary_free);
 		K_WLOCK(markersummary_free);
 		K_RLOCK(workmarkers_free);
+		setnow(&lck_got);
 		ms_item = STORE_HEAD_NOLOCK(new_markersummary_store);
 		while (ms_item) {
 			// move the new markersummaries into the trees/stores
@@ -4730,15 +4737,17 @@ flail:
 
 		LOGWARNING("%s() Processed: %d ms %d ss %"PRId64" shares "
 			   "%"PRId64" diff for workmarkers %"PRId64"/%s/"
-			   "End %"PRId64"/Stt %"PRId64"/%s/%s db %.3fs "
+			   "End %"PRId64"/Stt %"PRId64"/%s/%s add %.3f "
-			   "lck %.3fs",
+			   "db %.3fs lck %.3fs+%.3f",
 			   shortname, ms_count, ss_count, shareacc, diffacc,
 			   workmarkers->markerid, workmarkers->poolinstance,
 			   workmarkers->workinfoidend,
 			   workmarkers->workinfoidstart,
 			   workmarkers->description,
-			   workmarkers->status, tvdiff(&db_fin, &db_stt),
+			   workmarkers->status, tvdiff(&db_stt, &add_stt),
-			   tvdiff(&lck_fin, &lck_stt));
+			   tvdiff(&db_fin, &db_stt),
+			   tvdiff(&lck_got, &lck_stt),
+			   tvdiff(&lck_fin, &lck_got));
 	}
 	free_ktree(ms_root, NULL);
 	new_markersummary_store = k_free_store(new_markersummary_store);