如何用log4j或winston写入大量日志？内存不足

Question

NodeJS 的日志记录

作为nodejs的初学者，我写了如下测试代码。但是内存越来越大，有时无输出（通过多种方式改变）。

有 2 个著名的日志记录模块，log4js and winston。以log4js为例

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;
})();

循环次数少的时候，虽然内存增加了，从来没有掉下来，效果很好。但是当时间被设置为更多超过10,000,000，就会失败，提示如下：

...
[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

作为我在 whosebug.com 中的第一个问题，我想分享一些东西困扰了我很久。那么问题来了。

Answer 1

tl;dr

有必要让记录器有机会完成 I/O 工作 setImmediate() 并使用事件而不是 'for' 来执行循环，或者它将内容保留在内存中，内存不足而死。

根本原因

这是由the event loop mechanisms of nodejs, bool ev_run (loop, int flags)引起的，它需要一个任务每次都按以下顺序来自观察者：

idle -> I/O -> check

'for' 和 'process.nextTick()' 是空闲观察者，所以 logger 没有机会做底层的 I/O 工作。而它导致内存运行耗尽。

解决方案

所以，我们需要给记录器一个机会来做底层工作。

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 温斯顿

(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();
})();

温斯顿-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;
})();

如何用log4j或winston写入大量日志？内存不足

How to write a large amount of logs with log4j or winston? Out of Memory

javascript

logging

out-of-memory

node.js