Add logging

Author: peckto

app/deepseg.cc

@@ -105,17 +105,14 @@ typedef std::chrono::high_resolution_clock::time_point timestamp_t;
 typedef struct {
 	timestamp_t bootns;
 	timestamp_t lastns;
-	timestamp_t waitns;
 	timestamp_t lockns;
 	timestamp_t copyns;
 	timestamp_t prepns;
-	timestamp_t tfltns;
 	timestamp_t maskns;
 	timestamp_t postns;
 	timestamp_t v4l2ns;
-	// these are already converted to ns
-	long grabns;
-	long retrns;
+	timestamp_t grabns;
+	timestamp_t retrns;
 } timinginfo_t;
 
 timestamp_t timestamp() {
@@ -135,11 +132,6 @@ typedef struct {
 	std::mutex lock;
 } capinfo_t;
 
-// timing callbacks
-void onprep(void *ctx) { ((timinginfo_t *)ctx)->prepns=timestamp(); }
-void oninfer(void *ctx) { ((timinginfo_t *)ctx)->tfltns=timestamp(); }
-void onmask(void *ctx) { ((timinginfo_t *)ctx)->maskns=timestamp(); }
-
 // let's do this!
 static bool is_number(const std::string &s) {
   return !s.empty() && std::all_of(s.begin(), s.end(), ::isdigit);
@@ -170,11 +162,13 @@ class CalcMask final {
 
 	void run() {
 		cv::Mat *raw_tmp;
+		timestamp_t t1;
 
 		while(thread_state::INIT == this->state)
 			usleep(1000); // Wait for constructor to complete initialization
 
 		while(thread_state::RUNNING == this->state) {
+			t0 = timestamp();
 			/* actual handling */
 			{
 				std::unique_lock<std::mutex> hold(lock_frame);
@@ -188,6 +182,9 @@ class CalcMask final {
 				frame_next = frame_current;
 				frame_current = raw_tmp;
 			}
+			waitns=diffnanosecs(timestamp(), t0);
+			t0 = timestamp();
+			t1 = timestamp();
 			if(!bs_maskgen_process(maskctx, *frame_current, *mask_current)) {
 				fprintf(stderr, "failed to process video frame\n");
 				exit(1);
@@ -199,15 +196,56 @@ class CalcMask final {
 				mask_current = raw_tmp;
 				new_mask = true;
 			}
+			loopns = diffnanosecs(timestamp(), t1);
 		}
 	}
 
+	// timing callbacks
+	static void onprep(void *ctx) {
+		CalcMask *cls = (CalcMask *)ctx;
+		cls->prepns=diffnanosecs(timestamp(), cls->t0);
+		cls->t0 = timestamp();
+	}
+	static void oninfer(void *ctx) {
+		CalcMask *cls = (CalcMask *)ctx;
+		cls->tfltns=diffnanosecs(timestamp(), cls->t0);
+		cls->t0 = timestamp();
+	}
+	static void onmask(void *ctx) {
+		CalcMask *cls = (CalcMask *)ctx;
+		cls->maskns=diffnanosecs(timestamp(), cls->t0);
+		cls->t0 = timestamp();
+	}
+
 public:
-	CalcMask(void *maskctx) :
+	timestamp_t t0;
+	long waitns;
+	long prepns;
+	long tfltns;
+	long maskns;
+	long loopns;
+
+	CalcMask(const char *modelname,
+			 size_t threads,
+			 size_t width,
+			 size_t height) :
 		state{thread_state::INIT},
 		thread{&CalcMask::run, this} {
+		maskctx = bs_maskgen_new(
+					modelname,
+					threads,
+					width,
+					height,
+					nullptr,
+					onprep,
+					oninfer,
+					onmask,
+					this
+					);
+		if (!maskctx)
+			exit(1);
+
 		// Do all other initialization …
-		this->maskctx = maskctx;
 		frame_next = &frame1;
 		frame_current = &frame2;
 		mask_current = &mask1;
@@ -220,6 +258,7 @@ class CalcMask final {
 	~CalcMask() {
 		state = thread_state::DONE;
 		thread.join();
+		bs_maskgen_delete(maskctx);
 	}
 
 	void set_input_frame(cv::Mat &frame) {
@@ -423,46 +462,41 @@ int main(int argc, char* argv[]) {
 		cap.set(CV_CAP_PROP_FOURCC, fourcc);
 	cap.set(CV_CAP_PROP_CONVERT_RGB, true);
 
-	void *maskctx = bs_maskgen_new(modelname, threads, width, height, nullptr, onprep, oninfer, onmask, &ti);
-	if (!maskctx)
-		exit(1);
-
 	cv::Mat mask(height, width, CV_8U);
 	cv::Mat raw;
-	CalcMask ai(maskctx);
+	CalcMask ai(modelname, threads, width, height);
 	ti.lastns = timestamp();
 	printf("Startup: %ldns\n", diffnanosecs(ti.lastns,ti.bootns));
 
 	bool filterActive = true;
 
 	// mainloop
 	for(bool running = true; running; ) {
-		ti.waitns=timestamp();
-
 		// grab new frame from cam
 		cap.grab();
+		ti.grabns=timestamp();
 		// copy new frame to buffer
 		cap.retrieve(raw);
+		ti.retrns=timestamp();
 		ai.set_input_frame(raw);
-
 		ti.copyns=timestamp();
+
 		if (raw.rows == 0 || raw.cols == 0) continue; // sanity check
 
 		if (blur_strength) {
 			raw.copyTo(bg);
 			cv::GaussianBlur(bg,bg,cv::Size(blur_strength,blur_strength),0);
 		}
+		ti.prepns = timestamp();
 
 		if (filterActive) {
 			// do background detection magic
 			ai.get_output_mask(mask);
 
 			// alpha blend background over foreground using mask
 			raw = alpha_blend(bg, raw, mask);
-		} else {
-			// fix up timing values
-			ti.maskns=ti.tfltns=ti.prepns=ti.copyns;
 		}
+		ti.maskns = timestamp();
 
 		if (flipHorizontal && flipVertical) {
 			cv::flip(raw,raw,-1);
@@ -495,18 +529,21 @@ int main(int argc, char* argv[]) {
 		}
 
 		// timing details..
-		printf("wait:%9ld lock:%9ld [grab:%9ld retr:%9ld] copy:%9ld prep:%9ld tflt:%9ld mask:%9ld post:%9ld v4l2:%9ld FPS: %5.2f\e[K\r",
-			diffnanosecs(ti.waitns,ti.lastns),
-			diffnanosecs(ti.lockns,ti.waitns),
-			ti.grabns,
-			ti.retrns,
-			diffnanosecs(ti.copyns,ti.lockns),
+		printf("main [grab:%9ld retr:%9ld copy:%9ld prep:%9ld mask:%9ld post:%9ld v4l2:%9ld FPS: %5.2f] ai: [wait:%9ld prep:%9ld tflt:%9ld mask:%9ld FPS: %5.2f] \e[K\r",
+			diffnanosecs(ti.grabns, ti.lastns),
+			diffnanosecs(ti.retrns,ti.grabns),
+			diffnanosecs(ti.copyns,ti.retrns),
 			diffnanosecs(ti.prepns,ti.copyns),
-			diffnanosecs(ti.tfltns,ti.prepns),
-			diffnanosecs(ti.maskns,ti.tfltns),
+			diffnanosecs(ti.maskns,ti.prepns),
 			diffnanosecs(ti.postns,ti.maskns),
 			diffnanosecs(ti.v4l2ns,ti.postns),
-			1e9/diffnanosecs(ti.v4l2ns,ti.lastns));
+			1e9/diffnanosecs(ti.v4l2ns,ti.lastns),
+			ai.waitns,
+			ai.prepns,
+			ai.tfltns,
+			ai.maskns,
+			1e9/ai.loopns
+		);
 		fflush(stdout);
 		ti.lastns = timestamp();
 		if (debug < 2) continue;