feat(pipe): add timing information and clean up function name reporting

src/defaults/html.pipe.js

@@ -35,6 +35,7 @@ const rewriteLinks = require('../html/static-asset-links');
 const tohast = require('../html/html-to-hast');
 const tohtml = require('../html/stringify-hast');
 const addHeaders = require('../html/add-headers');
+const timing = require('../utils/timing');
 
 /* eslint newline-per-chained-call: off */
 
@@ -46,9 +47,11 @@ const htmlpipe = (cont, payload, action) => {
   action.logger = action.logger || log;
   action.logger.log('debug', 'Constructing HTML Pipeline');
   const pipe = new Pipeline(action);
+  const timer = timing();
   pipe
     .every(dump).when(() => !production())
     .every(validate).when(() => !production())
+    .every(timer.update)
     .before(fetch).expose('fetch').when(hascontent)
     .before(parse).expose('parse')
     .before(parseFrontmatter)
@@ -70,6 +73,7 @@ const htmlpipe = (cont, payload, action) => {
     .after(addHeaders)
     .after(tohtml) // end HTML post-processing
     .after(flag).expose('esi').when(esi) // flag ESI when there is ESI in the response
+    .after(timer.report)
     .error(selectStatus);
 
   action.logger.log('debug', 'Running HTML pipeline');

src/defaults/json.pipe.js

@@ -24,16 +24,19 @@ const validate = require('../utils/validate.js');
 const emit = require('../json/emit-json.js');
 const { selectStatus } = require('../json/set-json-status.js');
 const parseFrontmatter = require('../html/parse-frontmatter.js');
+const timing = require('../utils/timing');
 
 /* eslint newline-per-chained-call: off */
 
 const jsonpipe = (cont, payload, action) => {
   action.logger = action.logger || log;
   action.logger.log('debug', 'Constructing JSON Pipeline');
   const pipe = new Pipeline(action);
+  const timer = timing();
   pipe
     .every(dump).when(() => !production())
     .every(validate).when(() => !production())
+    .every(timer.update)
     .before(fetch).expose('fetch')
     .before(parse).expose('parse')
     .before(parseFrontmatter)
@@ -43,6 +46,7 @@ const jsonpipe = (cont, payload, action) => {
     .once(cont)
     .after(emit).expose('json')
     .after(type('application/json'))
+    .after(timer.report)
     .error(selectStatus(production()));
 
   action.logger.log('debug', 'Running JSON pipeline');

src/defaults/xml.pipe.js

@@ -28,16 +28,19 @@ const emit = require('../xml/emit-xml.js');
 const selectStatus = require('../xml/set-xml-status.js');
 const check = require('../xml/check-xml');
 const parseFrontmatter = require('../html/parse-frontmatter');
+const timing = require('../utils/timing');
 
 /* eslint newline-per-chained-call: off */
 
 const xmlpipe = (cont, payload, action) => {
   action.logger = action.logger || log;
   action.logger.log('debug', 'Constructing XML Pipeline');
   const pipe = new Pipeline(action);
+  const timer = timing();
   pipe
     .every(dump).when(() => !production())
     .every(validate).when(() => !production())
+    .every(timer.update)
     .before(fetch).expose('fetch')
     .before(parse).expose('parse')
     .before(parseFrontmatter)
@@ -52,6 +55,7 @@ const xmlpipe = (cont, payload, action) => {
     .when(uncached)
     .after(key)
     .after(flag).expose('esi').when(esi) // flag ESI when there is ESI in the response
+    .after(timer.report)
     .error(selectStatus);
 
   action.logger.log('debug', 'Running XML pipeline');

src/pipeline.js

@@ -231,6 +231,7 @@ class Pipeline {
         return args[0];
       };
       wrappedfunc.alias = lastfunc.alias;
+      wrappedfunc.title = lastfunc.title;
       wrappedfunc.ext = lastfunc.ext;
       this._last.push(wrappedfunc);
     } else {
@@ -274,6 +275,7 @@ class Pipeline {
     const wrapped = errorWrapper(f);
     // ensure proper alias
     wrapped.alias = f.alias;
+    wrapped.title = f.title;
     this._last.push(wrapped);
     return this;
   }
@@ -289,17 +291,17 @@ class Pipeline {
   // eslint-disable-next-line class-methods-use-this
   describe(f) {
     if (f.alias) {
-      return f.alias;
+      return;
     }
 
     f.alias = f.name || f.ext || 'anonymous';
+    f.title = f.alias;
 
     const [current, injector, caller] = callsites();
-    if (current.getFunctionName() === 'describe') {
-      f.alias = `${injector.getFunctionName()}:${f.alias} from ${caller.getFileName()}:${caller.getLineNumber()}`;
+    if (current.getFunctionName() === 'describe' && caller) {
+      f.title = `${injector.getFunctionName()}:${f.alias}`;
+      f.alias = `${f.title} from ${caller.getFileName()}:${caller.getLineNumber()}`;
     }
-
-    return f.alias;
   }
 
   /**
@@ -314,8 +316,6 @@ class Pipeline {
     // register all custom attachers to the pipeline
     this.attach(this._oncef);
 
-    const getident = (fn, classifier, idx) => `${classifier}-#${idx}/${this.describe(fn)}`;
-
     /**
      * Executes the taps of the current function.
      * @param {Function[]} taps the taps
@@ -324,10 +324,10 @@ class Pipeline {
      */
     const execTaps = async (taps, fnIdent, fnIdx) => {
       for (const [idx, t] of iter(taps)) {
-        const ident = getident(t, 'tap', idx);
-        logger.silly(`exec ${ident} before ${fnIdent}`);
+        const ident = `#${String(fnIdx).padStart(2, '0')}/${fnIdent}/tap-#${idx}`;
+        logger.silly(`exec ${ident}`);
         try {
-          await t(context, this._action, fnIdx);
+          await t(context, this._action, fnIdx, fnIdent);
         } catch (e) {
           logger.error(`Exception during ${ident}:\n${e.stack}`);
           throw e;
@@ -338,25 +338,22 @@ class Pipeline {
     /**
      * Executes the pipeline functions
      * @param {Function[]} fns the functions
-     * @param {number} startIdx offset of the function's index in the entire pipeline.
-     * @param {string} classifier type of function (for logging)
      */
-    const execFns = async (fns, startIdx, classifier) => {
-      for (const [i, f] of enumerate(fns)) {
-        const idx = i + startIdx;
-        const ident = getident(f, classifier, idx);
+    const execFns = async (fns) => {
+      for (const [idx, f] of enumerate(fns)) {
+        const ident = `#${String(idx).padStart(2, '0')}/${f.alias}`;
 
         // skip if error and no error handler (or no error and error handler)
         if ((!context.error) === (!!f.errorHandler)) {
           logger.silly(`skip ${ident}`, {
-            function: this.describe(f),
+            function: f.alias,
           });
           // eslint-disable-next-line no-continue
           continue;
         }
 
         try {
-          await execTaps(enumerate(this._taps), ident, idx);
+          await execTaps(enumerate(this._taps), f.title, idx);
         } catch (e) {
           if (!context.error) {
             context.error = e;
@@ -368,7 +365,7 @@ class Pipeline {
         }
         try {
           logger.silly(`exec ${ident}`, {
-            function: this.describe(f),
+            function: f.alias,
           });
           await f(context, this._action);
         } catch (e) {
@@ -381,9 +378,7 @@ class Pipeline {
     };
 
     try {
-      await execFns(this._pres, 0, 'pre');
-      await execFns([this._oncef], this._pres.length, 'once');
-      await execFns(this._posts, this._pres.length + 1, 'post');
+      await execFns([...this._pres, this._oncef, ...this._posts]);
     } catch (e) {
       logger.error(`Unexpected error during pipeline execution: \n${e.stack}`);
       if (!context.error) {

src/utils/timing.js

@@ -0,0 +1,73 @@
+/*
+ * Copyright 2019 Adobe. All rights reserved.
+ * This file is licensed to you under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License. You may obtain a copy
+ * of the License at http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software distributed under
+ * the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR REPRESENTATIONS
+ * OF ANY KIND, either express or implied. See the License for the specific language
+ * governing permissions and limitations under the License.
+ */
+
+/**
+ * Computes the time delta in seconds from HR timestamps
+ * @param {int[]} t0 first HR timestamp
+ * @param {int[]} t1 second HR timestamp
+ * @returns {number} delta in seconds
+ */
+function delta(t0, t1) {
+  const ds = t0[0] - t1[0]; // seconds
+  const dn = t0[1] - t1[1]; // nanoseconds
+  return ds * 1000 + dn / 1000000;
+}
+
+/**
+ * Creates a timing object that records the timestamps using process.hrtime() and can set the
+ * 'Server-Timing' response header accordingly.
+ */
+function create() {
+  const startTime = process.hrtime();
+  const times = [];
+
+  /**
+   * Update the timestamps. The 'taps' are executed before the pipeline step functions. Just record
+   * the name and the timestamps for now.
+   */
+  function update(context, action, idx, name) {
+    times.push({
+      name: name ? name.split(':').pop() : 'undef',
+      time: process.hrtime(),
+    });
+  }
+
+  /**
+   * Create the timing report and set the 'Server-Timing' header
+   */
+  function report(context, { logger }) {
+    update();
+    const total = delta(process.hrtime(), startTime);
+    logger.debug(`total processing time: ${total}ms`);
+
+    // calculate the deltas between 2 the timestamps of 2 steps and generate the metric string.
+    const metrics = [];
+    for (let i = 0; i < times.length - 1; i += 1) {
+      const d = delta(times[i + 1].time, times[i].time);
+      metrics.push(`p${String(i).padStart(2, '0')};dur=${d};desc=${times[i].name}`);
+    }
+    const timing = metrics.join(' ,');
+    logger.debug(`timing: ${timing}`);
+
+    context.response.headers['Server-Timing'] = [
+      timing,
+      `total;dur=${total}`,
+    ];
+  }
+
+  return {
+    update,
+    report,
+  };
+}
+
+module.exports = create;

test/testPipeline.js

@@ -497,7 +497,7 @@ describe('Testing Pipeline', () => {
       .run();
     const output = await logger.getOutput();
     assert.deepEqual(order, ['pre0']);
-    assert.ok(output.indexOf('Exception during post-#5/error:anonymous') > 0);
+    assert.ok(output.indexOf('Exception during #05/error:anonymous') > 0);
   });
 
   it('handles generic pipeline error', async () => {