break up stattracking #1039

src/demo/demo.c

@@ -403,14 +403,16 @@ summary_table(struct ncdirect* nc, const char* spec){
   uint64_t totalbytes = 0;
   long unsigned totalframes = 0;
   uint64_t totalrenderns = 0;
+  uint64_t totalwriteoutns = 0;
   printf("\n");
   table_segment(nc, "             runtime", "│");
   table_segment(nc, " frames", "│");
   table_segment(nc, "output(B)", "│");
   table_segment(nc, "rendering", "│");
   table_segment(nc, " %r", "│");
+  table_segment(nc, " %w", "│");
   table_segment(nc, "    FPS", "│");
-  table_segment(nc, "TheoFPS", "║\n══╤════════╤════════╪═══════╪═════════╪═════════╪═══╪═══════╪═══════╣\n");
+  table_segment(nc, "TheoFPS", "║\n══╤════════╤════════╪═══════╪═════════╪═════════╪═══╪═══╪═══════╪═══════╣\n");
   char timebuf[PREFIXSTRLEN + 1];
   char tfpsbuf[PREFIXSTRLEN + 1];
   char totalbuf[BPREFIXSTRLEN + 1];
@@ -444,11 +446,13 @@ summary_table(struct ncdirect* nc, const char* spec){
     ncdirect_fg_rgb(nc, rescolor);
     printf("%8s", demos[results[i].selector - 'a'].name);
     ncdirect_fg_rgb8(nc, 178, 102, 255);
-    printf("│%*ss│%7ju│%*s│ %*ss│%3jd│%7.1f│%*s║",
+    printf("│%*ss│%7ju│%*s│ %*ss│%3jd│%3jd│%7.1f│%*s║",
            PREFIXFMT(timebuf), (uintmax_t)(results[i].stats.renders),
            BPREFIXFMT(totalbuf), PREFIXFMT(rtimebuf),
            (uintmax_t)(results[i].timens ?
             results[i].stats.render_ns * 100 / results[i].timens : 0),
+           (uintmax_t)(results[i].timens ?
+            results[i].stats.writeout_ns * 100 / results[i].timens : 0),
            results[i].timens ?
             results[i].stats.renders / ((double)results[i].timens / GIG) : 0.0,
            PREFIXFMT(tfpsbuf));
@@ -462,17 +466,19 @@ summary_table(struct ncdirect* nc, const char* spec){
     totalframes += results[i].stats.renders;
     totalbytes += results[i].stats.render_bytes;
     totalrenderns += results[i].stats.render_ns;
+    totalwriteoutns += results[i].stats.writeout_ns;
   }
   qprefix(nsdelta, GIG, timebuf, 0);
   bprefix(totalbytes, 1, totalbuf, 0);
   qprefix(totalrenderns, GIG, rtimebuf, 0);
-  table_segment(nc, "", "══╧════════╧════════╪═══════╪═════════╪═════════╪═══╪═══════╪═══════╝\n");
+  table_segment(nc, "", "══╧════════╧════════╪═══════╪═════════╪═════════╪═══╪═══╪═══════╪═══════╝\n");
   printf("            ");
   table_printf(nc, "│", "%*ss", PREFIXFMT(timebuf));
   table_printf(nc, "│", "%7lu", totalframes);
   table_printf(nc, "│", "%*s", BPREFIXFMT(totalbuf));
   table_printf(nc, "│", " %*ss", PREFIXFMT(rtimebuf));
   table_printf(nc, "│", "%3ld", nsdelta ? totalrenderns * 100 / nsdelta : 0);
+  table_printf(nc, "│", "%3ld", nsdelta ? totalwriteoutns * 100 / nsdelta : 0);
   table_printf(nc, "│", "%7.1f", nsdelta ? totalframes / ((double)nsdelta / GIG) : 0);
   printf("\n");
   ncdirect_fg_rgb8(nc, 0xff, 0xb0, 0xb0);

src/lib/render.c

@@ -89,12 +89,25 @@ blocking_write(int fd, const char* buf, size_t buflen){
   return 0;
 }
 
+// update timings for writeout. only call on success.
 static void
-update_render_stats(const struct timespec* time1, const struct timespec* time0,
-                    ncstats* stats, int bytes){
-  int64_t elapsed = timespec_to_ns(time1) - timespec_to_ns(time0);
-  //fprintf(stderr, "Rendering took %ld.%03lds\n", elapsed / NANOSECS_IN_SEC,
-  //        (elapsed % NANOSECS_IN_SEC) / 1000000);
+update_write_stats(const struct timespec* time1, const struct timespec* time0,
+                   ncstats* stats){
+  const int64_t elapsed = timespec_to_ns(time1) - timespec_to_ns(time0);
+  if(elapsed > 0){ // don't count clearly incorrect information, egads
+    stats->writeout_ns += elapsed;
+    if(elapsed > stats->writeout_max_ns){
+      stats->writeout_max_ns = elapsed;
+    }
+    if(elapsed < stats->writeout_min_ns){
+      stats->writeout_min_ns = elapsed;
+    }
+  }
+}
+
+// negative 'bytes' is recorded as a failure.
+static void
+update_render_bytes(ncstats* stats, int bytes){
   if(bytes >= 0){
     stats->render_bytes += bytes;
     if(bytes > stats->render_max_bytes){
@@ -106,6 +119,14 @@ update_render_stats(const struct timespec* time1, const struct timespec* time0,
   }else{
     ++stats->failed_renders;
   }
+}
+
+static void
+update_render_stats(const struct timespec* time1, const struct timespec* time0,
+                    ncstats* stats){
+  const int64_t elapsed = timespec_to_ns(time1) - timespec_to_ns(time0);
+  //fprintf(stderr, "Rendering took %ld.%03lds\n", elapsed / NANOSECS_IN_SEC,
+  //        (elapsed % NANOSECS_IN_SEC) / 1000000);
   if(elapsed > 0){ // don't count clearly incorrect information, egads
     ++stats->renders;
     stats->render_ns += elapsed;
@@ -1033,8 +1054,7 @@ notcurses_render_internal(notcurses* nc, struct crender* rvec){
 }
 
 int notcurses_render(notcurses* nc){
-  struct timespec start, done;
-  int ret;
+  struct timespec start, rasterdone, writedone;
   clock_gettime(CLOCK_MONOTONIC, &start);
   int dimy, dimx;
   notcurses_resize(nc, &dimy, &dimx);
@@ -1043,13 +1063,18 @@ int notcurses_render(notcurses* nc){
   struct crender* crender = malloc(crenderlen);
   init_rvec(crender, crenderlen / sizeof(struct crender));
   if(notcurses_render_internal(nc, crender) == 0){
+    clock_gettime(CLOCK_MONOTONIC, &rasterdone);
+    update_render_stats(&rasterdone, &start, &nc->stats);
     bytes = notcurses_rasterize(nc, crender, nc->rstate.mstreamfp);
   }
+  update_render_bytes(&nc->stats, bytes);
   free(crender);
-  clock_gettime(CLOCK_MONOTONIC, &done);
-  update_render_stats(&done, &start, &nc->stats, bytes);
-  ret = bytes >= 0 ? 0 : -1;
-  return ret;
+  if(bytes < 0){
+    return -1;
+  }
+  clock_gettime(CLOCK_MONOTONIC, &writedone);
+  update_write_stats(&writedone, &rasterdone, &nc->stats);
+  return 0;
 }
 
 // copy the UTF8-encoded EGC out of the cell, whether simple or complex. the