diff options
Diffstat (limited to 'lib')
| -rw-r--r-- | lib/cli/build.js | 7 | ||||
| -rw-r--r-- | lib/cli/options.js | 9 | ||||
| -rw-r--r-- | lib/output/callHook.js | 45 | ||||
| -rw-r--r-- | lib/output/generatePage.js | 76 | ||||
| -rw-r--r-- | lib/parse/listAssets.js | 26 | ||||
| -rw-r--r-- | lib/parse/parseBook.js | 8 | ||||
| -rw-r--r-- | lib/parse/parsePagesList.js | 46 | ||||
| -rw-r--r-- | lib/plugins/findForBook.js | 27 | ||||
| -rw-r--r-- | lib/plugins/loadPlugin.js | 3 | ||||
| -rw-r--r-- | lib/utils/timing.js | 89 |
10 files changed, 233 insertions, 103 deletions
diff --git a/lib/cli/build.js b/lib/cli/build.js index e64ab44..023901e 100644 --- a/lib/cli/build.js +++ b/lib/cli/build.js @@ -1,5 +1,6 @@ var Parse = require('../parse'); var Output = require('../output'); +var timing = require('../utils/timing'); var options = require('./options'); var getBook = require('./getBook'); @@ -11,7 +12,8 @@ module.exports = { description: 'build a book', options: [ options.log, - options.format + options.format, + options.timing ], exec: function(args, kwargs) { var book = getBook(args, kwargs); @@ -24,6 +26,9 @@ module.exports = { return Output.generate(Generator, resultBook, { root: outputFolder }); + }) + .fin(function() { + if (kwargs.timing) timing.dump(book.getLogger()); }); } }; diff --git a/lib/cli/options.js b/lib/cli/options.js index 26581cb..ddcb5c5 100644 --- a/lib/cli/options.js +++ b/lib/cli/options.js @@ -17,7 +17,14 @@ var formatOption = { defaults: 'website' }; +var timingOption = { + name: 'timing', + description: 'Print timing debug information', + defaults: false +}; + module.exports = { log: logOptions, - format: formatOption + format: formatOption, + timing: timingOption }; diff --git a/lib/output/callHook.js b/lib/output/callHook.js index 1ff1a41..4914e52 100644 --- a/lib/output/callHook.js +++ b/lib/output/callHook.js @@ -1,4 +1,5 @@ var Promise = require('../utils/promise'); +var timing = require('../utils/timing'); var Api = require('../api'); function defaultGetArgument() { @@ -30,26 +31,30 @@ function callHook(name, getArgument, handleResult, output) { // Create the JS context for plugins var context = Api.encodeGlobal(output); - // Get the arguments - return Promise(getArgument(output)) - - // Call the hooks in serie - .then(function(arg) { - return Promise.reduce(plugins, function(prev, plugin) { - var hook = plugin.getHook(name); - if (!hook) { - return prev; - } - - return hook.call(context, prev); - }, arg); - }) - - // Handle final result - .then(function(result) { - output = Api.decodeGlobal(output, context); - return handleResult(output, result); - }); + return timing.measure( + 'call.hook.' + name, + + // Get the arguments + Promise(getArgument(output)) + + // Call the hooks in serie + .then(function(arg) { + return Promise.reduce(plugins, function(prev, plugin) { + var hook = plugin.getHook(name); + if (!hook) { + return prev; + } + + return hook.call(context, prev); + }, arg); + }) + + // Handle final result + .then(function(result) { + output = Api.decodeGlobal(output, context); + return handleResult(output, result); + }) + ); } module.exports = callHook; diff --git a/lib/output/generatePage.js b/lib/output/generatePage.js index 30a798a..a93d4b0 100644 --- a/lib/output/generatePage.js +++ b/lib/output/generatePage.js @@ -1,5 +1,6 @@ var Promise = require('../utils/promise'); var error = require('../utils/error'); +var timing = require('../utils/timing'); var Parse = require('../parse'); var Templating = require('../templating'); @@ -18,50 +19,53 @@ function generatePage(output, page) { var book = output.getBook(); var engine = createTemplateEngine(output); - return Parse.parsePage(book, page) - .then(function(resultPage) { - var file = resultPage.getFile(); - var filePath = file.getPath(); - var parser = file.getParser(); - var context = JSONUtils.encodeBookWithPage(book, resultPage); + return timing.measure( + 'page.generate', + Parse.parsePage(book, page) + .then(function(resultPage) { + var file = resultPage.getFile(); + var filePath = file.getPath(); + var parser = file.getParser(); + var context = JSONUtils.encodeBookWithPage(book, resultPage); - if (!parser) { - return Promise.reject(error.FileNotParsableError({ - filename: filePath - })); - } + if (!parser) { + return Promise.reject(error.FileNotParsableError({ + filename: filePath + })); + } - // Call hook "page:before" - return callPageHook('page:before', output, resultPage) + // Call hook "page:before" + return callPageHook('page:before', output, resultPage) - // Escape code blocks with raw tags - .then(function(currentPage) { - return parser.page.prepare(currentPage.getContent()); - }) + // Escape code blocks with raw tags + .then(function(currentPage) { + return parser.page.prepare(currentPage.getContent()); + }) - // Render templating syntax - .then(function(content) { - return Templating.render(engine, filePath, content, context); - }) + // Render templating syntax + .then(function(content) { + return Templating.render(engine, filePath, content, context); + }) - // Render page using parser (markdown -> HTML) - .then(parser.page).get('content') + // Render page using parser (markdown -> HTML) + .then(parser.page).get('content') - // Post processing for templating syntax - .then(function(content) { - return Templating.postRender(engine, content); - }) + // Post processing for templating syntax + .then(function(content) { + return Templating.postRender(engine, content); + }) - // Return new page - .then(function(content) { - return resultPage.set('content', content); - }) + // Return new page + .then(function(content) { + return resultPage.set('content', content); + }) - // Call final hook - .then(function(currentPage) { - return callPageHook('page', output, currentPage); - }); - }); + // Call final hook + .then(function(currentPage) { + return callPageHook('page', output, currentPage); + }); + }) + ); } module.exports = generatePage; diff --git a/lib/parse/listAssets.js b/lib/parse/listAssets.js index a0dbbc9..c43b054 100644 --- a/lib/parse/listAssets.js +++ b/lib/parse/listAssets.js @@ -1,3 +1,4 @@ +var timing = require('../utils/timing'); /** List all assets in a book @@ -16,17 +17,20 @@ function listAssets(book, pages) { var glossary = book.getGlossary(); var glossaryFile = glossary.getFile().getPath(); - return fs.listAllFiles() - .then(function(files) { - return files.filterNot(function(file) { - return ( - book.isContentFileIgnored(file) || - pages.has(file) || - file !== summaryFile || - file !== glossaryFile - ); - }); - }); + return timing.measure( + 'parse.listAssets', + fs.listAllFiles() + .then(function(files) { + return files.filterNot(function(file) { + return ( + book.isContentFileIgnored(file) || + pages.has(file) || + file !== summaryFile || + file !== glossaryFile + ); + }); + }) + ); } module.exports = listAssets; diff --git a/lib/parse/parseBook.js b/lib/parse/parseBook.js index 69cd66e..84a4038 100644 --- a/lib/parse/parseBook.js +++ b/lib/parse/parseBook.js @@ -1,4 +1,5 @@ var Promise = require('../utils/promise'); +var timing = require('../utils/timing'); var Book = require('../models/book'); var parseIgnore = require('./parseIgnore'); @@ -57,7 +58,9 @@ function parseMultilingualBook(book) { @return {Promise<Book>} */ function parseBook(book) { - return Promise(book) + return timing.measure( + 'parse.book', + Promise(book) .then(parseIgnore) .then(parseConfig) .then(parseLanguages) @@ -67,7 +70,8 @@ function parseBook(book) { } else { return parseBookContent(resultBook); } - }); + }) + ); } module.exports = parseBook; diff --git a/lib/parse/parsePagesList.js b/lib/parse/parsePagesList.js index e356e88..a3a52f8 100644 --- a/lib/parse/parsePagesList.js +++ b/lib/parse/parsePagesList.js @@ -1,5 +1,6 @@ var Immutable = require('immutable'); +var timing = require('../utils/timing'); var Page = require('../models/page'); var walkSummary = require('./walkSummary'); @@ -14,27 +15,30 @@ function parsePagesList(book) { var summary = book.getSummary(); var map = Immutable.OrderedMap(); - return walkSummary(summary, function(article) { - if (!article.isPage()) return; - - var filepath = article.getPath(); - - // Is the page ignored? - if (book.isContentFileIgnored(filepath)) return; - - return fs.statFile(filepath) - .then(function(file) { - map = map.set( - filepath, - Page.createForFile(file) - ); - }, function() { - // file doesn't exist - }); - }) - .then(function() { - return map; - }); + return timing.measure( + 'parse.listPages', + walkSummary(summary, function(article) { + if (!article.isPage()) return; + + var filepath = article.getPath(); + + // Is the page ignored? + if (book.isContentFileIgnored(filepath)) return; + + return fs.statFile(filepath) + .then(function(file) { + map = map.set( + filepath, + Page.createForFile(file) + ); + }, function() { + // file doesn't exist + }); + }) + .then(function() { + return map; + }) + ); } diff --git a/lib/plugins/findForBook.js b/lib/plugins/findForBook.js index 47b8fc4..14ccc05 100644 --- a/lib/plugins/findForBook.js +++ b/lib/plugins/findForBook.js @@ -2,6 +2,7 @@ var path = require('path'); var Immutable = require('immutable'); var Promise = require('../utils/promise'); +var timing = require('../utils/timing'); var findInstalled = require('./findInstalled'); /** @@ -11,18 +12,22 @@ var findInstalled = require('./findInstalled'); @return {Promise<OrderedMap<String:Plugin>>} */ function findForBook(book) { - return Promise.all([ - findInstalled(path.resolve(__dirname, '../..')), - findInstalled(book.getRoot()) - ]) + return timing.measure( + 'plugins.findForBook', - // Merge all plugins - .then(function(results) { - return Immutable.List(results) - .reduce(function(out, result) { - return out.merge(result); - }, Immutable.OrderedMap()); - }); + Promise.all([ + findInstalled(path.resolve(__dirname, '../..')), + findInstalled(book.getRoot()) + ]) + + // Merge all plugins + .then(function(results) { + return Immutable.List(results) + .reduce(function(out, result) { + return out.merge(result); + }, Immutable.OrderedMap()); + }) + ); } diff --git a/lib/plugins/loadPlugin.js b/lib/plugins/loadPlugin.js index a1c41b4..400146e 100644 --- a/lib/plugins/loadPlugin.js +++ b/lib/plugins/loadPlugin.js @@ -4,6 +4,7 @@ var Immutable = require('immutable'); var Promise = require('../utils/promise'); var error = require('../utils/error'); +var timing = require('../utils/timing'); var validatePlugin = require('./validatePlugin'); @@ -72,6 +73,8 @@ function loadPlugin(book, plugin) { .then(validatePlugin); + p = timing.measure('plugin.load', p); + logger.info('loading plugin "' + name + '"... '); return logger.info.promise(p); } diff --git a/lib/utils/timing.js b/lib/utils/timing.js new file mode 100644 index 0000000..21a4b91 --- /dev/null +++ b/lib/utils/timing.js @@ -0,0 +1,89 @@ +var Immutable = require('immutable'); +var is = require('is'); + +var timers = {}; +var startDate = Date.now(); + +/** + Mesure an operation + + @parqm {String} type + @param {Promise} p + @return {Promise} +*/ +function measure(type, p) { + timers[type] = timers[type] || { + type: type, + count: 0, + total: 0, + min: undefined, + max: 0 + }; + + var start = Date.now(); + + return p + .fin(function() { + var end = Date.now(); + var duration = (end - start); + + timers[type].count ++; + timers[type].total += duration; + + if (is.undefined(timers[type].min)) { + timers[type].min = duration; + } else { + timers[type].min = Math.min(timers[type].min, duration); + } + + timers[type].max = Math.max(timers[type].max, duration); + }); +} + +/** + Return a milliseconds number as a second string + + @param {Number} ms + @return {String} +*/ +function time(ms) { + if (ms < 1000) { + return (ms.toFixed(0)) + 'ms'; + } + + return (ms/1000).toFixed(2) + 's'; +} + +/** + Dump all timers to a logger + + @param {Logger} logger +*/ +function dump(logger) { + var prefix = ' > '; + var measured = 0; + var totalDuration = Date.now() - startDate; + + Immutable.Map(timers) + .valueSeq() + .sortBy(function(timer) { + measured += timer.total; + return timer.total; + }) + .forEach(function(timer) { + logger.debug.ln('Timer "' + timer.type + '" (' + timer.count + ' times) :'); + logger.debug.ln(prefix + 'Total: ' + time(timer.total)); + logger.debug.ln(prefix + 'Average: ' + time(timer.total / timer.count)); + logger.debug.ln(prefix + 'Min: ' + time(timer.min)); + logger.debug.ln(prefix + 'Max: ' + time(timer.max)); + logger.debug.ln('---------------------------'); + }); + + + logger.debug.ln(time(totalDuration - measured) + ' spent in non-mesured sections'); +} + +module.exports = { + measure: measure, + dump: dump +}; |