add raster timing stats #1324

USAGE.md

@@ -3018,9 +3018,12 @@ typedef struct ncstats {
   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
-  uint64_t render_ns;        // nanoseconds spent in render+raster
+  uint64_t render_ns;        // nanoseconds spent rendering
   int64_t render_max_ns;     // max ns spent in render+raster for a frame
   int64_t render_min_ns;     // min ns spent in render+raster for a frame
+  uint64_t raster_ns;        // nanoseconds spent rasterizing
+  int64_t raster_max_ns;     // max ns spent in raster for a frame
+  int64_t raster_min_ns;     // min ns spent in raster for a frame
   uint64_t writeout_ns;      // nanoseconds spent writing frames to terminal
   int64_t writeout_max_ns;   // max ns spent writing out a frame
   int64_t writeout_min_ns;   // min ns spent writing out a frame

doc/man/man3/notcurses_stats.3.md

@@ -20,9 +20,12 @@ typedef struct ncstats {
   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
-  uint64_t render_ns;        // nanoseconds spent in render+raster
+  uint64_t render_ns;        // nanoseconds spent rendering
   int64_t render_max_ns;     // max ns spent for a frame
   int64_t render_min_ns;     // min ns spent for a frame
+  uint64_t raster_ns;        // nanoseconds spent rasterizing
+  int64_t raster_max_ns;     // max ns spent in raster for a frame
+  int64_t raster_min_ns;     // min ns spent in raster for a frame
   uint64_t writeout_ns;      // ns spent writing frames to terminal
   int64_t writeout_max_ns;   // max ns spent writing out a frame
   int64_t writeout_min_ns;   // min ns spent writing out a frame
@@ -73,15 +76,19 @@ existing terminal state. As a first approximation, the time a terminal takes to
 ingest and reflect a frame is dependent on the size of the rasterized frame.
 
 **render_ns**, **render_max_ns**, and **render_min_ns** track the total
-amount of time spent rendering and rasterizing frames in nanoseconds. Rendering
-and rasterizing takes place in **notcurses_render(3)**, and is the entirety of
-**notcurses_render_to_buffer(3)**. These steps are independent of the terminal.
+amount of time spent rendering frames in nanoseconds. Rendering
+takes place in **ncpile_render** (called by **notcurses_render(3)** and
+**notcurses_render_to_buffer**). This step is independent of the terminal.
+
+**raster_ns**, **raster_max_ns**, and **raster_min_ns** track the total
+amount of time spent rasterizing frames in nanoseconds. Rasterizing
+takes place in **ncpile_raster** (called by **notcurses_raster(3)** and
+**notcurses_render_to_buffer**). This step depends on the terminal definitions.
+The same frame might not rasterize to the same bytes for different terminals.
 
 **writeout_ns**, **writeout_max_ns**, and **writeout_min_ns** track the total
-amount of time spent writing frames to the terminal. This takes place in only
-**notcurses_render(3)**. If **notcurses_render_to_buffer(3)** is used, the
-user is responsible for writing out the frame, and it will not be tracked by
-any stat.
+amount of time spent writing frames to the terminal. This takes place in
+**ncpile_rasterize** (called by **notcurses_render(3)**).
 
 **cellemissions** reflects the number of EGCs written to the terminal.
 **cellelisions** reflects the number of cells which were not written, due to

include/notcurses/notcurses.h

@@ -620,7 +620,7 @@ typedef struct nccell {
   uint64_t channels;          // + 8B == 16B
 } nccell;
 
-typedef nccell cell; // FIXME backwards-compat, remove in 3.0
+typedef nccell cell; // FIXME backwards-compat, remove in ABI3
 
 #define CELL_TRIVIAL_INITIALIZER { .gcluster = 0, .gcluster_backstop = 0, .width = 0, .stylemask = 0, .channels = 0, }
 // do *not* load invalid EGCs using these macros! there is no way for us to
@@ -1137,8 +1137,8 @@ API struct ncplane* ncplane_create(struct ncplane* n, const ncplane_options* nop
 // be the top, bottom, and root of this new pile.
 API struct ncplane* ncpile_create(struct notcurses* nc, const ncplane_options* nopts);
 
-// This function will be removed in 3.0 in favor of ncplane_create().
-// It persists in 2.0 only for backwards compatibility.
+// This function will be removed in ABI3 in favor of ncplane_create().
+// It persists in ABI2 only for backwards compatibility.
 API struct ncplane* ncplane_new(struct ncplane* n, int rows, int cols, int y, int x, void* opaque, const char* name)
   __attribute__ ((deprecated));
 
@@ -1237,12 +1237,13 @@ typedef struct ncstats {
   uint64_t writeouts;        // successful ncpile_rasterize() runs
   uint64_t failed_renders;   // aborted renders, should be 0
   uint64_t failed_writeouts; // aborted writes
+  // FIXME these next three all ought be "writeout" or "raster"
   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
-  uint64_t render_ns;        // nanoseconds spent in render+raster
-  int64_t render_max_ns;     // max ns spent in render+raster for a frame
-  int64_t render_min_ns;     // min ns spent in render+raster for a frame
+  uint64_t render_ns;        // nanoseconds spent rendering
+  int64_t render_max_ns;     // max ns spent in render for a frame
+  int64_t render_min_ns;     // min ns spent in render for a frame
   uint64_t writeout_ns;      // nanoseconds spent writing frames to terminal
   int64_t writeout_max_ns;   // max ns spent writing out a frame
   int64_t writeout_min_ns;   // min ns spent writing out a frame
@@ -1259,6 +1260,11 @@ typedef struct ncstats {
   // current state -- these can decrease
   uint64_t fbbytes;          // total bytes devoted to all active framebuffers
   unsigned planes;           // number of planes currently in existence
+
+  // FIXME placed here for ABI compatibility; move up for ABI3
+  uint64_t raster_ns;        // nanoseconds spent rasterizing
+  int64_t raster_max_ns;     // max ns spent in raster for a frame
+  int64_t raster_min_ns;     // min ns spent in raster for a frame
 } ncstats;
 
 // Allocate an ncstats object. Use this rather than allocating your own, since

src/demo/demo.c

@@ -412,20 +412,18 @@ summary_table(struct ncdirect* nc, const char* spec, bool canimage, bool canvide
   table_segment(nc, "             runtime", "│");
   table_segment(nc, " frames", "│");
   table_segment(nc, "output(B)", "│");
-  table_segment(nc, "rendering", "│");
   table_segment(nc, "    FPS", "│");
   table_segment(nc, "%r", "│");
+  table_segment(nc, "%a", "│");
   table_segment(nc, "%w", "│");
-  table_segment(nc, "TheoFPS", "║\n══╤════════╤════════╪═══════╪═════════╪═════════╪═══════╪══╪══╪═══════╣\n");
+  table_segment(nc, "TheoFPS", "║\n══╤════════╤════════╪═══════╪═════════╪═══════╪══╪══╪══╪═══════╣\n");
   char timebuf[PREFIXSTRLEN + 1];
   char tfpsbuf[PREFIXSTRLEN + 1];
   char totalbuf[BPREFIXSTRLEN + 1];
-  char rtimebuf[PREFIXSTRLEN + 1];
   uint64_t nsdelta = 0;
   for(size_t i = 0 ; i < strlen(spec) ; ++i){
     nsdelta += results[i].timens;
     qprefix(results[i].timens, NANOSECS_IN_SEC, timebuf, 0);
-    qprefix(results[i].stats.render_ns, NANOSECS_IN_SEC, rtimebuf, 0);
     bprefix(results[i].stats.render_bytes, 1, totalbuf, 0);
     if(results[i].stats.renders){
       qprefix((uintmax_t)results[i].stats.renders * NANOSECS_IN_SEC * 1000 /
@@ -451,13 +449,15 @@ summary_table(struct ncdirect* nc, const char* spec, bool canimage, bool canvide
     ncdirect_set_fg_rgb(nc, rescolor);
     printf("%8s", demos[results[i].selector - 'a'].name);
     ncdirect_set_fg_rgb8(nc, 178, 102, 255);
-    printf("│%*ss│%7ju│%*s│ %*ss│%7.1f│%2jd│%2jd│%*s║",
+    printf("│%*ss│%7ju│%*s│%7.1f│%2jd│%2jd│%2jd│%*s║",
            PREFIXFMT(timebuf), (uintmax_t)(results[i].stats.renders),
-           BPREFIXFMT(totalbuf), PREFIXFMT(rtimebuf),
+           BPREFIXFMT(totalbuf),
            results[i].timens ?
             results[i].stats.renders / ((double)results[i].timens / NANOSECS_IN_SEC) : 0.0,
            (uintmax_t)(results[i].timens ?
             results[i].stats.render_ns * 100 / results[i].timens : 0),
+           (uintmax_t)(results[i].timens ?
+            results[i].stats.raster_ns * 100 / results[i].timens : 0),
            (uintmax_t)(results[i].timens ?
             results[i].stats.writeout_ns * 100 / results[i].timens : 0),
            PREFIXFMT(tfpsbuf));
@@ -475,13 +475,13 @@ summary_table(struct ncdirect* nc, const char* spec, bool canimage, bool canvide
   }
   qprefix(nsdelta, NANOSECS_IN_SEC, timebuf, 0);
   bprefix(totalbytes, 1, totalbuf, 0);
-  qprefix(totalrenderns, NANOSECS_IN_SEC, rtimebuf, 0);
-  table_segment(nc, "", "══╧════════╧════════╪═══════╪═════════╪═════════╪═══════╪══╧══╧═══════╝\n");
+  //qprefix(totalrenderns, NANOSECS_IN_SEC, rtimebuf, 0);
+  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, "│", " %*ss", PREFIXFMT(rtimebuf));
   table_printf(nc, "│", "%7.1f", nsdelta ? totalframes / ((double)nsdelta / NANOSECS_IN_SEC) : 0);
   printf("\n");
   ncdirect_set_fg_rgb8(nc, 0xff, 0xb0, 0xb0);

src/lib/notcurses.c

@@ -712,6 +712,7 @@ static void
 stash_stats(notcurses* nc){
   nc->stashstats.renders += nc->stats.renders;
   nc->stashstats.render_ns += nc->stats.render_ns;
+  nc->stashstats.raster_ns += nc->stats.raster_ns;
   nc->stashstats.writeouts += nc->stats.writeouts;
   nc->stashstats.writeout_ns += nc->stats.writeout_ns;
   nc->stashstats.failed_renders += nc->stats.failed_renders;
@@ -735,6 +736,12 @@ stash_stats(notcurses* nc){
   if(nc->stashstats.writeout_min_ns > nc->stats.writeout_min_ns){
     nc->stashstats.writeout_min_ns = nc->stats.writeout_min_ns;
   }
+  if(nc->stashstats.raster_max_ns < nc->stats.raster_max_ns){
+    nc->stashstats.raster_max_ns = nc->stats.raster_max_ns;
+  }
+  if(nc->stashstats.raster_min_ns > nc->stats.raster_min_ns){
+    nc->stashstats.raster_min_ns = nc->stats.raster_min_ns;
+  }
   nc->stashstats.cellelisions += nc->stats.cellelisions;
   nc->stashstats.cellemissions += nc->stats.cellemissions;
   nc->stashstats.fgelisions += nc->stats.fgelisions;
@@ -1154,6 +1161,13 @@ 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.raster_ns, NANOSECS_IN_SEC, totalbuf, 0);
+        qprefix(nc->stashstats.raster_min_ns, NANOSECS_IN_SEC, minbuf, 0);
+        qprefix(nc->stashstats.raster_max_ns, NANOSECS_IN_SEC, maxbuf, 0);
+        qprefix(nc->stashstats.raster_ns / nc->stashstats.writeouts, NANOSECS_IN_SEC, avgbuf, 0);
+        fprintf(stderr, "%ju raster%s, %ss total (%ss min, %ss max, %ss avg)\n",
+                nc->stashstats.writeouts, nc->stashstats.writeouts == 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);