From 79211781654c0b8532142516d2f220463df68ea1 Mon Sep 17 00:00:00 2001
From: baldo <baldo@toppoint.de>
Date: Fri, 29 Jul 2016 12:53:20 +0200
Subject: [PATCH] Added support for writing profiling logs.

For now it supports profiling database queries and
job execution time.
---
 README.md                |  1 +
 config.json.example      |  1 +
 server/config.js         |  1 +
 server/db/database.js    |  4 ++++
 server/jobs/scheduler.js |  2 ++
 server/logger.js         | 21 +++++++++++++--------
 6 files changed, 22 insertions(+), 8 deletions(-)

diff --git a/README.md b/README.md
index 90026b5..9a82730 100644
--- a/README.md
+++ b/README.md
@@ -116,6 +116,7 @@ Dann die `config.json` anpassen nach belieben. Es gibt die folgenden Konfigurati
 
 * **`server.logging.directory`** Verzeichnis unter dem Log-Files abgelegt werden, z. B.: `"$FFFFNG_HOME/logs"`
 * **`server.logging.debug`** Gibt an, ob Debug-Output geloggt werden soll (Achtung, viel!), z. B.: `false`
+* **`server.logging.profile`** Gibt an, ob Profiling-Output geloggt werden soll (Achtung, viel!), z. B.: `false`
 * **`server.logging.logRequests`** Gib an, ob HTTP-Requests geloggt werden sollen (Achtung, Datenschutz!), z. B.: `false`
 
 * **`server.internal.active`** Gibt an, ob interne URLs, wie Admin-Panel und Logging-Interface, erreichbar sein sollen,
diff --git a/config.json.example b/config.json.example
index 9cc3f3c..ce2c693 100644
--- a/config.json.example
+++ b/config.json.example
@@ -9,6 +9,7 @@
         "logging": {
             "directory": "/tmp/logs",
             "debug": false,
+            "profile": false,
             "logRequests": false
         },
 
diff --git a/server/config.js b/server/config.js
index 02b738e..5cae933 100644
--- a/server/config.js
+++ b/server/config.js
@@ -63,6 +63,7 @@ var defaultConfig = {
         logging: {
             directory: '/tmp/logs',
             debug: false,
+            profile: false,
             logRequests: false
         },
 
diff --git a/server/db/database.js b/server/db/database.js
index e4c7a9a..f40f1e7 100644
--- a/server/db/database.js
+++ b/server/db/database.js
@@ -91,6 +91,10 @@ module.exports = {
             throw error;
         }
 
+        db.on('profile', function (sql, time) {
+            Logger.tag('database').profile('[%sms]\t%s', time, sql);
+        });
+
         applyMigrations(db, function (err) {
             if (err) {
                 Logger.tag('database').error('Error migrating database:', err);
diff --git a/server/jobs/scheduler.js b/server/jobs/scheduler.js
index 7c5961d..e4efbc1 100644
--- a/server/jobs/scheduler.js
+++ b/server/jobs/scheduler.js
@@ -53,6 +53,8 @@ angular.module('ffffng').factory('Scheduler', function ($injector, Logger, confi
             task.state = 'running';
 
             job.run(function () {
+                var now = moment();
+                Logger.tag('jobs').profile('[%sms]\t%s', now.diff(task.runningSince), task.name);
                 task.runningSince = false;
                 task.state = 'idle';
             });
diff --git a/server/logger.js b/server/logger.js
index 718a479..23ba3cb 100644
--- a/server/logger.js
+++ b/server/logger.js
@@ -18,16 +18,21 @@ var scribe = require('scribe-js')({
     rootPath: config.server.logging.directory,
 });
 
-if (config.server.logging.debug) {
-    process.console.addLogger('debug', 'grey', {
-        logInConsole: false
-    });
-} else {
-    process.console.debug = function () {
-        this._reset(); // forget tags, etc. for this logging event
-    };
+function addLogger(name, color, active) {
+    if (active) {
+        process.console.addLogger(name, color, {
+            logInConsole: false
+        });
+    } else {
+        process.console[name] = function () {
+            this._reset(); // forget tags, etc. for this logging event
+        };
+    }
 }
 
+addLogger('debug', 'grey', config.server.logging.debug);
+addLogger('profile', 'blue', config.server.logging.profile);
+
 angular.module('ffffng').factory('Logger', function (app) {
     if (config.server.logging.logRequests) {
         app.use(scribe.express.logger());