diff --git a/lib/render.js b/lib/render.js index a643c8d9..89f4953b 100644 --- a/lib/render.js +++ b/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); }; } diff --git a/lib/routes/_components.js b/lib/routes/_components.js index c1b052e8..4c9ef65b 100644 --- a/lib/routes/_components.js +++ b/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', diff --git a/lib/routes/_pages.js b/lib/routes/_pages.js index 70d14ea9..1ab17561 100644 --- a/lib/routes/_pages.js +++ b/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',