perf: use Map instead of Object for fields

Since the log object's properties get set, updated, deleted a lot
the object qualifies as hot object/hash table mode, making it less
performant. Maps fit in this situation as they enable the usage of
hash maps efficiently.

lib/Logger.js

@@ -83,7 +83,8 @@ class Logger {
 
     _doLog(levelName, msg, data) {
         const bLogger = Config.logger;
-        const finalData = { name: this.name };
+        const finalData = new Map();
+        finalData.set('name', this.name);
         if (!LogLevel.shouldLog(levelName, Config.level)) {
             return;
         }
@@ -98,7 +99,7 @@ class Logger {
         }
         if (data) {
             Object.keys(data).forEach((k) => {
-                finalData[k] = data[k];
+                finalData.set(k, data[k]);
             });
         }
         const args = [ finalData, msg ];

lib/RequestLogger.js

@@ -6,6 +6,7 @@ const LogLevel = require('./LogLevel.js');
 const Utils = require('./Utils.js');
 const serializeUids = Utils.serializeUids;
 const generateUid = Utils.generateUid;
+const copyFields = Utils.copyFields;
 
 function ensureUidValidity(uid) {
     if (uid.indexOf(':') !== -1) {
@@ -17,16 +18,18 @@ function ensureUidValidity(uid) {
 class EndLogger {
     constructor(reqLogger) {
         this.logger = reqLogger;
-        this.fields = {};
+        this.fields = Object.create(null);
     }
 
     augmentedLog(level, msg, data) {
         assert.strictEqual(this.logger.elapsedTime, null, 'The logger\'s'
                            + 'end() wrapper should not be called more than'
                            + ' once.');
-        // We can alter current instance, as it won't be usable after this
-        // call.
-        this.fields = Object.assign(this.fields, data || {});
+        if (data) {
+            Object.keys(data).forEach(k => {
+                this.fields[k] = data[k];
+            });
+        }
         return this.logger.log(level, msg, this.fields, true);
     }
 
@@ -45,7 +48,11 @@ class EndLogger {
      */
     addDefaultFields(fields) {
         const oldFields = this.fields;
-        this.fields = Object.assign({}, this.fields, fields);
+        if (fields) {
+            Object.keys(fields).forEach((k) => {
+                this.fields[k] = fields[k];
+            });
+        }
         return oldFields;
     }
 
@@ -193,7 +200,7 @@ class RequestLogger {
         this.uids = uidList || [ generateUid() ];
 
         this.entries = [];
-        this.fields = {};
+        this.fields = new Map();
         this.logLevel = logLevel;
         this.dumpThreshold = dumpThreshold;
         this.endLevel = endLevel;
@@ -248,7 +255,7 @@ class RequestLogger {
      */
     addDefaultFields(fields) {
         const oldFields = this.fields;
-        this.fields = Object.assign({}, this.fields, fields);
+        copyFields(this.fields, fields);
         return oldFields;
     }
 
@@ -433,24 +440,22 @@ class RequestLogger {
                 });
             return;
         }
-        const fields = Object.assign({}, logFields || {});
+        let elapsedMs = 0;
         const endFlag = isEnd || false;
-
-        /*
-        * Even though this is added automatically by bunyan, it uses an
-        * expensive regex to figure out the native Date function. By adding
-        * timestamp here avoids that expensive call.
-        */
-        if (fields.time === undefined) {
-            fields.time = new Date();
-        }
-
-        fields.req_id = serializeUids(this.uids);
         if (endFlag) {
             this.elapsedTime = process.hrtime(this.startTime);
-            fields.elapsed_ms = this.elapsedTime[0] * 1000
+            elapsedMs = this.elapsedTime[0] * 1000
                 + this.elapsedTime[1] / 1000000;
         }
+
+        const fields = new Map();
+        fields.set('time', new Date().toJSON());
+        fields.set('req_id', serializeUids(this.uids));
+        fields.set('elapsed_ms', elapsedMs);
+        this.fields.forEach((v, k) => {
+            fields.set(k, v);
+        });
+        copyFields(fields, logFields || {});
         const logEntry = {
             level,
             fields,
@@ -484,30 +489,9 @@ class RequestLogger {
      * @returns {undefined}
      */
     doLogIO(logEntry) {
-        const fields = Object.assign({}, this.fields, logEntry.fields);
+        LogLevel.throwIfInvalid(logEntry.level);
 
-        switch (logEntry.level) {
-        case 'trace':
-            this.bLogger.trace(fields, logEntry.msg);
-            break;
-        case 'debug':
-            this.bLogger.debug(fields, logEntry.msg);
-            break;
-        case 'info':
-            this.bLogger.info(fields, logEntry.msg);
-            break;
-        case 'warn':
-            this.bLogger.warn(fields, logEntry.msg);
-            break;
-        case 'error':
-            this.bLogger.error(fields, logEntry.msg);
-            break;
-        case 'fatal':
-            this.bLogger.fatal(fields, logEntry.msg);
-            break;
-        default:
-            throw new Error(`Unexpected log level: ${logEntry.level}`);
-        }
+        this.bLogger[logEntry.level](logEntry.fields, logEntry.msg);
     }
 }
 

lib/Utils.js

@@ -40,8 +40,22 @@ function unserializeUids(stringdata) {
     return stringdata.split(':');
 }
 
+/**
+* This function copies the properties from the source object to the fields map
+* @param {map} fields - Map of log entry fields
+* @param {object} source - object to copy from
+* @returns {map} - map object containing the copied fields
+*/
+function copyFields(fields, source) {
+    Object.keys(source).forEach(f => {
+        fields.set(f, source[f]);
+    });
+    return fields;
+}
+
 module.exports = {
     generateUid,
     serializeUids,
     unserializeUids,
+    copyFields,
 };

tests/Utils.js

@@ -19,33 +19,36 @@ class DummyLogger {
     }
 
     trace(obj, msg) {
-        this.ops.push(['trace', [obj, msg]]);
-        this.counts.trace += 1;
+        this.doLog('trace', obj, msg);
     }
 
     debug(obj, msg) {
-        this.ops.push(['debug', [obj, msg]]);
-        this.counts.debug += 1;
+        this.doLog('debug', obj, msg);
     }
 
     info(obj, msg) {
-        this.ops.push(['info', [obj, msg]]);
-        this.counts.info += 1;
+        this.doLog('info', obj, msg);
     }
 
     warn(obj, msg) {
-        this.ops.push(['warn', [obj, msg]]);
-        this.counts.warn += 1;
+        this.doLog('warn', obj, msg);
     }
 
     error(obj, msg) {
-        this.ops.push(['error', [obj, msg]]);
-        this.counts.error += 1;
+        this.doLog('error', obj, msg);
     }
 
     fatal(obj, msg) {
-        this.ops.push(['fatal', [obj, msg]]);
-        this.counts.fatal += 1;
+        this.doLog('fatal', obj, msg);
+    }
+
+    doLog(level, obj, msg) {
+        const fields = Object.create(null);
+        if (obj instanceof Map) {
+            obj.forEach((v, k) => fields[k] = v);
+        }
+        this.ops.push([ level, [ fields, msg]]);
+        this.counts[level] += 1;
     }
 }
 

tests/unit/Utils.js

@@ -5,6 +5,7 @@ const Utils = require('../../lib/Utils.js');
 const generateUid = Utils.generateUid;
 const serializeUids = Utils.serializeUids;
 const unserializeUids = Utils.unserializeUids;
+const copyFields = Utils.copyFields;
 
 describe('Utils: generateUid', () => {
     it('generates a string-typed ID', (done) => {
@@ -42,3 +43,19 @@ describe('Utils: serializeUids', () => {
         done();
     });
 });
+
+describe('Utils: copyFields', () => {
+    it('copies all the properties from source to target object', (done) => {
+        const target = new Map();
+        target.set('foo', 'bar');
+        const source = { id: 1, name: 'demo', value: { a: 1, b: 2, c: 3 } };
+        const result = new Map();
+        result.set('foo', 'bar');
+        result.set('id', 1);
+        result.set('name', 'demo');
+        result.set('value', { a: 1, b: 2, c: 3 });
+        copyFields(target, source);
+        assert.deepStrictEqual(target, result, 'target should have the same properties as source');
+        done();
+    });
+});