Composition Time Message (#515)

* Adding a composition time message to rendering

* adding in jsdoc

lib/render.js

@@ -2,7 +2,8 @@
 
 var uriRoutes, renderers,
   log = require('./services/logger').setup({
-    file: __filename
+    file: __filename,
+    action: 'render'
   });
 const _ = require('lodash'),
   schema = require('./schema'),
@@ -171,9 +172,10 @@ function findRenderer(extension) {
  * @param  {Object} req
  * @param  {Object} res
  * @param  {Object} options
+ * @param  {Object} hrStart
  * @return {Promise}
  */
-function renderComponent(req, res, options) {
+function renderComponent(req, res, options, hrStart) {
   var extension = getExtension(req), // Get the extension for the request
     renderer = findRenderer(extension), // Determine which renderer we are using
     uri = req.uri,
@@ -194,6 +196,7 @@ function renderComponent(req, res, options) {
 
       return formDataForRenderer(options, locals);
     })
+    .tap(logTime(hrStart, req.uri))
     .then(state => renderer.render(state, res));
 }
 
@@ -211,9 +214,10 @@ function getDBObject(uri) {
  * @param  {String} uri
  * @param  {Object} req
  * @param  {Object} res
+ * @param  {Object} hrStart
  * @return {Promise}
  */
-function renderPage(uri, req, res) {
+function renderPage(uri, req, res, hrStart) {
   const locals = res.locals,
     extension = getExtension(req),
     renderer = findRenderer(extension);
@@ -227,6 +231,7 @@ function renderPage(uri, req, res) {
   // look up page alias' component instance
   return getDBObject(uri)
     .then(formDataFromLayout(locals, uri))
+    .tap(logTime(hrStart, uri))
     .then(state => renderer.render(state, res));;
 }
 
@@ -301,9 +306,12 @@ function getExpressRoutePrefix(site) {
  * @param {string} uri
  * @param {object} req
  * @param {object} res
+ * @param {object} hrStart
  * @returns {Promise}
  */
-function renderUri(uri, req, res) {
+function renderUri(uri, req, res, hrStart) {
+  hrStart = hrStart || process.hrtime(); // Check if we actually have a start time
+
   return db.get(uri).then(function (result) {
     const route = _.find(uriRoutes, function (item) {
       return result.match(item.when);
@@ -322,11 +330,29 @@ function renderUri(uri, req, res) {
       log('info', `Redirecting to ${newUrl}`);
       res.redirect(301, newUrl);
     } else {
-      return route.default(result, req, res);
+      return route.default(result, req, res, hrStart);
     }
   });
 }
 
+/**
+ * Log the timing for data composition
+ *
+ * @param  {Object} hrStart
+ * @param  {String} uri
+ * @return {Function}
+ */
+function logTime(hrStart, uri) {
+  return () => {
+    const diff = process.hrtime(hrStart),
+      ms = Math.floor((diff[0] * 1e9 + diff[1]) / 1000000);
+
+    log('info', `composed data for: ${uri} (${ms}ms)`, {
+      composeTime: ms,
+      uri
+    });
+  };
+}
 
 /**
  * Run composer by translating url to a "page" by base64ing it.  Errors are handled by Express.
@@ -337,11 +363,12 @@ function renderUri(uri, req, res) {
  * @return {Promise}
  */
 function renderExpressRoute(req, res, next) {
-  var site = res.locals.site,
+  var hrStart = process.hrtime(),
+    site = res.locals.site,
     prefix = `${getExpressRoutePrefix(site)}/_uris/`,
     pageReference = `${prefix}${buf.encode(req.hostname + req.baseUrl + req.path)}`;
 
-  return module.exports.renderUri(pageReference, req, res)
+  return module.exports.renderUri(pageReference, req, res, hrStart)
     .catch((error) => {
       if (error.name === 'NotFoundError') {
         log('error', `could not find resource ${req.uri}`, {
@@ -363,13 +390,13 @@ function renderExpressRoute(req, res, next) {
  * @returns {function}
  */
 function assumePublishedUnlessEditing(fn) {
-  return function (uri, req, res) {
+  return function (uri, req, res, hrStart) {
     // ignore version if they are editing; default to 'published'
     if (!_.get(res, 'req.query.edit')) {
       uri = clayUtils.replaceVersion(uri, uri.split('@')[1] || 'published');
     }
 
-    return fn(uri, req, res);
+    return fn(uri, req, res, hrStart);
   };
 }
 

lib/routes/_components.js

@@ -185,7 +185,7 @@ route = _.bindAll({
    *
    */
   render(req, res) {
-    render.renderComponent(req, res, _.pick(req.query, queryStringOptions));
+    render.renderComponent(req, res, _.pick(req.query, queryStringOptions), process.hrtime());
   }
 }, [
   'get',

lib/routes/_pages.js

@@ -94,7 +94,7 @@ let route = _.bindAll({
    * @param {object} res
    */
   render(req, res) {
-    render.renderPage(req.uri, req, res);
+    render.renderPage(req.uri, req, res, process.hrtime());
   }
 }, [
   'post',