How to write a large number of logs with log4j or winston? Not enough memory

Question

NodeJS Magazine Registration

As a pauper nodejs, I wrote test code, for example, the following. But memory is increasing more and more, and sometimes nothing is displayed (changing it in several ways).

There are 2 famous logging modules, log4js and winston . Take log4js as an example.

1. main.js

(function(){
    "use strict";

    let log4js = require("./log4js-config.js");
    let logger = log4js.getLogger("log4js_main");

    for(let i = 0; i < 10000000 ; i++){

            logger.log("info", "info message " + i + ".");

    }

})();

2.log4js-config.js

module.exports = (function(){
    "use strict";
    let Log4js = require("log4js");
    Log4js.configure(
        {
             "appenders" : [
                 {   "type" : "logLevelFilter"
                     ,"level" : "ALL"
                     ,"appender" : {
                         "type" : "console"
                     }
                 }
                 ,{  "type" : "logLevelFilter"
                     ,"level" : "ALL"
                     ,"appender" : {
                         "type" : "dateFile"
                         ,"filename" : "./logs/log4js_date"
                         ,"pattern" : "-yyyyMMdd.log"
                         ,"alwaysIncludePattern" : false
                         ,"maxLogSize" : 209715200
                         ,"_maxLogSize" : "200M = 200 * 1024 * 1024 = 209715200"
                         ,"category" : "log4js.dateFile" 
                     }
                 }
                 ,{  "type" : "logLevelFilter"
                     ,"level" : "ALL"
                     ,"appender" : {
                         "type" : "file"
                         ,"filename" : "./logs/log4js_size.log"
                         ,"maxLogSize" : 209715200
                         ,"_maxLogSize" : "200M = 200 * 1024 * 1024 = 209715200"
                         ,"alwaysIncludePattern" : false
                         ,"backups" : 10
                         ,"category" : "log4js.file" 
                     }
                 }
             ]
             ,"replaceConsole" : true
        }
    );

    return Log4js;
})();

When the cycle time was short, although the memory increased and never fell, it worked well. But when the time has come for more than 10,000,000, he will fail and offer the following:

...
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525074.
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525075.
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525076.
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525077.
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525078.
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525079.
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525080.
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525081.
[2015-12-14 11:23:12.480] [INFO] log4js_main - info message 2525082.

<--- Last few GCs --->

  420299 ms: Scavenge 1399.0 (1457.4) -> 1399.0 (1457.4) MB, 2.3 / 0 ms (+ 0.0 ms in 1 steps since l
ast GC) [allocation failure] [incremental marking delaying mark-sweep].
  421110 ms: Mark-sweep 1399.0 (1457.4) -> 1399.0 (1457.4) MB, 814.3 / 0 ms (+ 15.0 ms in 2 steps si
nce start of marking, biggest step 15.0 ms) [last resort gc].
  421937 ms: Mark-sweep 1399.0 (1457.4) -> 1399.0 (1457.4) MB, 828.6 / 0 ms [last resort gc].


<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 0000019446CE3AD1 <JS Object>
    1: nextTick [node.js:~491] [pc=0000037DBBD17738] (this=0000012811B14929 <a process with map 0000
02F23C011991>,callback=0000017AB4E49C01 <JS Function afterWrite (SharedFunctionInfo 000002DC70230AF1
)>)
    2: arguments adaptor frame: 5->1
    3: onwrite(aka onwrite) [_stream_writable.js:~315] [pc=0000037DBB93CC17] (this=0000019446C04189
<undefined>,stream=000000727BB2BEE1 <a WriteStream wit...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory

PS

Like my first question at stackoverflow.com, I want to share things that bothered me for a long time. So comes to this question.

Answer 1

TL;DR

- setImmediate() 'for' , .

nodejs, bool ev_run (loop, int flags), it :

idle -> I/O -> check

" " " process.nextTick()" , logger -. .

, .

main.js log4js

(function(){
    "use strict";

    const WORK_DONE_EVENT_NAME = "work-done";
    const WORK_TIMES = 100 * 1000 * 1000;

    let evem = new (require("events").EventEmitter)();

    // Explicitly listening on the event.
    evem.on(WORK_DONE_EVENT_NAME, function(){
        // setImmediate: after I/O operations
        setImmediate(doWork);
    });

    let log4js = require("./log4js-config.js");
    let logger = log4js.getLogger("log4js_main");

    let idx = 0;
    function doWork(){
        idx++;
        if(idx >= WORK_TIMES){
            console.timeEnd(WORK_DONE_EVENT_NAME);
            return;
        }
        logger.info(idx);
        setImmediate(function(){
            evem.emit(WORK_DONE_EVENT_NAME);
        });
    }

    console.time(WORK_DONE_EVENT_NAME);
    doWork();
})();

log4js-config.js( )

main.js winston

(function(){
    "use strict";

    const WORK_DONE_EVENT_NAME = "work-done";
    const WORK_TIMES = 100 * 1000 * 1000;

    let evem = new (require("events").EventEmitter)();
    let logger = require("./winston-config");

    // Explicitly listening on the event.
    evem.on(WORK_DONE_EVENT_NAME, function(){
        // setImmediate: after I/O operations
        setImmediate(doWork);
    });

    let idx = 0;
    function doWork(){
        idx++;
        if(idx >= WORK_TIMES){
            console.timeEnd(WORK_TIMES);
            return;
        }
        logger.silly(idx, function(err, level, msg, meta){
            if(err){
                throw err;
            }
            evem.emit(WORK_DONE_EVENT_NAME);
        });
    }

    console.time(WORK_TIMES);
    doWork();
})();

< > Winston-config.js

module.exports = (function(){
    "use strict";
    let Winston = require("winston");
    let WinstonDailyRotateFile = require("winston-daily-rotate-file");
    let transports = [
            new (Winston.transports.Console)({
                "colorize" : true
                ,"timestamp" : true
                ,"showLevel": true
                ,"level" : "silly"
            })
            ,new (Winston.transports.File)({
                "name" : "winston-file"
                ,"filename" : "./logs/winston_size.log"
                ,"maxsize" : 209715200
                , "_maxsize" : "200M = 200 * 1024 * 1024 = 209715200"
                ,"maxFiles" : 1024
                ,"timestamp" : true
                ,"showLevel": true
                ,"level": "silly"
            })
            ,new (WinstonDailyRotateFile)({
              "name" : "winston-daily-file"
              ,"filename" : "./logs/winston_date"
              ,"datePattern" : "-yyyyMMdd.log"
              ,"maxsize" : 209715200
              , "_maxsize" : "200M = 200 * 1024 * 1024 = 209715200"
              ,"maxFiles" : 10
              ,"timestamp" : true
              ,"level": "silly"
            })
        ];
    let logger = new (Winston.Logger)({
        "transports" : transports
    });
    return logger;
})();