fix up writeout stats, report in shutdown banner

USAGE.md

@@ -2955,8 +2955,10 @@ Cumulative stats can be reset at any time.
 ```c
 typedef struct ncstats {
   // purely increasing stats
-  uint64_t renders;          // number of successful notcurses_render() runs
-  uint64_t failed_renders;   // number of aborted renders, should be 0
+  uint64_t renders;          // successful ncpile_render() runs
+  uint64_t writeouts;        // successful ncpile_rasterize() runs
+  uint64_t failed_renders;   // aborted renders, should be 0
+  uint64_t failed_writeouts; // aborted writes
   uint64_t render_bytes;     // bytes emitted to ttyfp
   int64_t render_max_bytes;  // max bytes emitted for a frame
   int64_t render_min_bytes;  // min bytes emitted for a frame
@@ -2974,7 +2976,7 @@ typedef struct ncstats {
   uint64_t bgemissions;      // RGB bg emissions
   uint64_t defaultelisions;  // default color was emitted
   uint64_t defaultemissions; // default color was elided
-  uint64_t refreshes;        // refreshes (suboptimal redraws)
+  uint64_t refreshes;        // refresh requests (non-optimized redraw)
 
   // current state -- these can decrease
   uint64_t fbbytes;          // total bytes devoted to all active framebuffers

doc/man/man3/notcurses_stats.3.md

@@ -13,8 +13,10 @@ notcurses_stats - notcurses runtime statistics
 ```c
 typedef struct ncstats {
   // purely increasing stats
-  uint64_t renders;          // number of successful renders
+  uint64_t renders;          // successful ncpile_render() runs
+  uint64_t writeouts;        // successful ncpile_rasterize() runs
   uint64_t failed_renders;   // aborted renders, should be 0
+  uint64_t failed_writeouts; // aborted writes
   uint64_t render_bytes;     // bytes emitted to ttyfp
   int64_t render_max_bytes;  // max bytes emitted for a frame
   int64_t render_min_bytes;  // min bytes emitted for a frame

include/notcurses/notcurses.h

@@ -1205,8 +1205,10 @@ API bool notcurses_cansixel(const struct notcurses* nc);
 
 typedef struct ncstats {
   // purely increasing stats
-  uint64_t renders;          // number of successful notcurses_render() runs
-  uint64_t failed_renders;   // number of aborted renders, should be 0
+  uint64_t renders;          // successful ncpile_render() runs
+  uint64_t writeouts;        // successful ncpile_rasterize() runs
+  uint64_t failed_renders;   // aborted renders, should be 0
+  uint64_t failed_writeouts; // aborted writes
   uint64_t render_bytes;     // bytes emitted to ttyfp
   int64_t render_max_bytes;  // max bytes emitted for a frame
   int64_t render_min_bytes;  // min bytes emitted for a frame

src/lib/notcurses.c

@@ -772,6 +772,7 @@ reset_stats(ncstats* stats){
   memset(stats, 0, sizeof(*stats));
   stats->render_min_ns = 1ull << 62u;
   stats->render_min_bytes = 1ull << 62u;
+  stats->writeout_min_ns = 1ull << 62u;
   stats->fbbytes = fbbytes;
 }
 
@@ -780,7 +781,10 @@ static void
 stash_stats(notcurses* nc){
   nc->stashstats.renders += nc->stats.renders;
   nc->stashstats.render_ns += nc->stats.render_ns;
+  nc->stashstats.writeouts += nc->stats.writeouts;
+  nc->stashstats.writeout_ns += nc->stats.writeout_ns;
   nc->stashstats.failed_renders += nc->stats.failed_renders;
+  nc->stashstats.failed_writeouts += nc->stats.failed_writeouts;
   nc->stashstats.render_bytes += nc->stats.render_bytes;
   if(nc->stashstats.render_max_bytes < nc->stats.render_max_bytes){
     nc->stashstats.render_max_bytes = nc->stats.render_max_bytes;
@@ -794,6 +798,12 @@ stash_stats(notcurses* nc){
   if(nc->stashstats.render_min_ns > nc->stats.render_min_ns){
     nc->stashstats.render_min_ns = nc->stats.render_min_ns;
   }
+  if(nc->stashstats.writeout_max_ns < nc->stats.writeout_max_ns){
+    nc->stashstats.writeout_max_ns = nc->stats.writeout_max_ns;
+  }
+  if(nc->stashstats.writeout_min_ns > nc->stats.writeout_min_ns){
+    nc->stashstats.writeout_min_ns = nc->stats.writeout_min_ns;
+  }
   nc->stashstats.cellelisions += nc->stats.cellelisions;
   nc->stashstats.cellemissions += nc->stats.cellemissions;
   nc->stashstats.fgelisions += nc->stats.fgelisions;
@@ -1246,6 +1256,14 @@ int notcurses_stop(notcurses* nc){
         fprintf(stderr, "\n%ju render%s, %ss total (%ss min, %ss max, %ss avg)\n",
                 nc->stashstats.renders, nc->stashstats.renders == 1 ? "" : "s",
                 totalbuf, minbuf, maxbuf, avgbuf);
+        qprefix(nc->stashstats.writeout_ns, NANOSECS_IN_SEC, totalbuf, 0);
+        qprefix(nc->stashstats.writeout_min_ns, NANOSECS_IN_SEC, minbuf, 0);
+        qprefix(nc->stashstats.writeout_max_ns, NANOSECS_IN_SEC, maxbuf, 0);
+        qprefix(nc->stashstats.writeouts ? nc->stashstats.writeout_ns / nc->stashstats.writeouts : 0,
+                NANOSECS_IN_SEC, avgbuf, 0);
+        fprintf(stderr, "%ju write%s, %ss total (%ss min, %ss max, %ss avg)\n",
+                nc->stashstats.writeouts, nc->stashstats.writeouts == 1 ? "" : "s",
+                totalbuf, minbuf, maxbuf, avgbuf);
         bprefix(nc->stashstats.render_bytes, 1, totalbuf, 0),
         bprefix(nc->stashstats.render_min_bytes, 1, minbuf, 0),
         bprefix(nc->stashstats.render_max_bytes, 1, maxbuf, 0),
@@ -1268,17 +1286,16 @@ int notcurses_stop(notcurses* nc){
                 nc->stashstats.fgelisions,
                 nc->stashstats.bgemissions,
                 nc->stashstats.bgelisions);
-        fprintf(stderr, " Elide rates: %.2f%% %.2f%% %.2f%%\n",
+        fprintf(stderr, "Cell emits:elides: %ju/%ju (%.2f%%) %.2f%% %.2f%% %.2f%%\n",
+                nc->stashstats.cellemissions, nc->stashstats.cellelisions,
+                (nc->stashstats.cellemissions + nc->stashstats.cellelisions) == 0 ? 0 :
+                (nc->stashstats.cellelisions * 100.0) / (nc->stashstats.cellemissions + nc->stashstats.cellelisions),
                 (nc->stashstats.defaultemissions + nc->stashstats.defaultelisions) == 0 ? 0 :
                 (nc->stashstats.defaultelisions * 100.0) / (nc->stashstats.defaultemissions + nc->stashstats.defaultelisions),
                 (nc->stashstats.fgemissions + nc->stashstats.fgelisions) == 0 ? 0 :
                 (nc->stashstats.fgelisions * 100.0) / (nc->stashstats.fgemissions + nc->stashstats.fgelisions),
                 (nc->stashstats.bgemissions + nc->stashstats.bgelisions) == 0 ? 0 :
                 (nc->stashstats.bgelisions * 100.0) / (nc->stashstats.bgemissions + nc->stashstats.bgelisions));
-        fprintf(stderr, "Cell emits:elides: %ju/%ju (%.2f%%)\n",
-                nc->stashstats.cellemissions, nc->stashstats.cellelisions,
-                (nc->stashstats.cellemissions + nc->stashstats.cellelisions) == 0 ? 0 :
-                (nc->stashstats.cellelisions * 100.0) / (nc->stashstats.cellemissions + nc->stashstats.cellelisions));
       }
     }
     del_curterm(cur_term);

src/lib/render.c

@@ -100,16 +100,21 @@ blocking_write(int fd, const char* buf, size_t buflen){
 // update timings for writeout. only call on success.
 static void
 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;
+                   ncstats* stats, int bytes){
+  if(bytes >= 0){
+    const int64_t elapsed = timespec_to_ns(time1) - timespec_to_ns(time0);
+    if(elapsed > 0){ // don't count clearly incorrect information, egads
+      ++stats->writeouts;
+      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;
+      }
     }
+  }else{
+    ++stats->failed_writeouts;
   }
 }
 
@@ -1118,11 +1123,11 @@ int ncpile_rasterize(ncplane* n){
   int bytes = notcurses_rasterize(nc, pile, nc->rstate.mstreamfp);
   // accepts -1 as an indication of failure
   update_render_bytes(&nc->stats, bytes);
+  clock_gettime(CLOCK_MONOTONIC, &writedone);
+  update_write_stats(&writedone, &start, &nc->stats, bytes);
   if(bytes < 0){
     return -1;
   }
-  clock_gettime(CLOCK_MONOTONIC, &writedone);
-  update_write_stats(&writedone, &start, &nc->stats);
   return 0;
 }