stats: gather startup stats

src/node/hooks/express.js

@@ -181,9 +181,16 @@ exports.restartServer = async () => {
   app.use(exports.sessionMiddleware);
 
   app.use(cookieParser(settings.sessionKey, {}));
+  const expressHooksDurations = {};
+  stats.gauge('expressHooksDurations', () => expressHooksDurations);
 
+  const preExpressConfigure = Date.now();
   hooks.callAll('expressConfigure', {app});
+  expressHooksDurations.configure = Date.now() - preExpressConfigure;
+
+  const preExpressCreateServer = Date.now();
   hooks.callAll('expressCreateServer', {app, server: exports.server});
+  expressHooksDurations.createServer = Date.now() - preExpressCreateServer;
 
   await util.promisify(exports.server.listen).bind(exports.server)(settings.port, settings.ip);
 };

src/node/hooks/express/static.js

@@ -5,8 +5,12 @@ const plugins = require('../../../static/js/pluginfw/plugin_defs');
 const CachingMiddleware = require('../../utils/caching_middleware');
 const Yajsml = require('etherpad-yajsml');
 const _ = require('underscore');
+const stats = require('../../stats');
 
 exports.expressCreateServer = (hookName, args, cb) => {
+  const expressDurations = {};
+  stats.gauge('expressDurations', () => expressDurations);
+  const preMinification = Date.now();
   // Cache both minified and static.
   const assetCache = new CachingMiddleware();
   args.app.all(/\/javascripts\/(.*)/, assetCache.handle);
@@ -15,6 +19,9 @@ exports.expressCreateServer = (hookName, args, cb) => {
   // file-specific hacks for ace/require-kernel/etc.
   args.app.all('/static/:filename(*)', minify.minify);
 
+  expressDurations.minification = Date.now() - preMinification;
+  const preYajsml = Date.now();
+
   // Setup middleware that will package JavaScript files served by minify for
   // CommonJS loader on the client-side.
   // Hostname "invalid.invalid" is a dummy value to allow parsing as a URI.
@@ -33,6 +40,7 @@ exports.expressCreateServer = (hookName, args, cb) => {
   jsServer.setAssociator(associator);
 
   args.app.use(jsServer.handle.bind(jsServer));
+  expressDurations.yajsml = Date.now() - preYajsml;
 
   // serve plugin definitions
   // not very static, but served here so that client can do

src/node/server.js

@@ -108,6 +108,8 @@ exports.start = async () => {
 
     // start up stats counting system
     const stats = require('./stats');
+    const startDurations = {};
+    stats.gauge('startDurations', () => startDurations);
     stats.gauge('memoryUsage', () => process.memoryUsage().rss);
     stats.gauge('memoryUsageHeap', () => process.memoryUsage().heapUsed);
 
@@ -132,9 +134,18 @@ exports.start = async () => {
       });
     }
 
+    const preNpmLoad = Date.now();
     await util.promisify(npm.load)();
+    startDurations.npmLoad = Date.now() - preNpmLoad;
+
+    const preDbInit = Date.now();
     await db.init();
+    startDurations.dbInit = Date.now() - preDbInit;
+
+    const prePluginsUpdate = Date.now();
     await plugins.update();
+    startDurations.loadPlugins = Date.now() - prePluginsUpdate;
+
     const installedPlugins = Object.values(pluginDefs.plugins)
         .filter((plugin) => plugin.package.name !== 'ep_etherpad-lite')
         .map((plugin) => `${plugin.package.name}@${plugin.package.version}`)
@@ -142,7 +153,9 @@ exports.start = async () => {
     logger.info(`Installed plugins: ${installedPlugins}`);
     logger.debug(`Installed parts:\n${plugins.formatParts()}`);
     logger.debug(`Installed hooks:\n${plugins.formatHooks()}`);
+    const preLoadSettings = Date.now();
     await hooks.aCallAll('loadSettings', {settings});
+    startDurations.loadSettings = Date.now() - preLoadSettings;
     await hooks.aCallAll('createServer');
   } catch (err) {
     logger.error('Error occurred while starting Etherpad');