Add option "--timing" to mesure gitbook performances

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
+};