Node js 非线程/进程安全的 较为高效的简单可用的日志模块

日志实现模块

#! /usr/bin/env node
/***********************************************
 * @Author: Frodo Cheng
 * @Time: 2020-07-10 15:55:00
***********************************************/
let fs = require('fs');
let os = require('os');
let process = require('process');

const LOG_LVL_NONE = 0;
const LOG_LVL_ERROR = 1 << 0;
const LOG_LVL_CRIT = 1 << 1;
const LOG_LVL_WARN = 1 << 2;
const LOG_LVL_DBG = 1 << 3;
const LOG_LVL_INFO = 1 << 4;
const LOG_LVL_VBS = 1 << 5;

const LOG_LVL_LOW = LOG_LVL_ERROR | LOG_LVL_CRIT | LOG_LVL_WARN;
const LOG_LVL_ALL = -1;

const LOG_LVL_TAG_ERROR = '[ERR]';
const LOG_LVL_TAG_CRIT = '[CRI]';
const LOG_LVL_TAG_WARN = '[WRN]';
const LOG_LVL_TAG_DBG = '[DBG]';
const LOG_LVL_TAG_INFO = '[INF]';
const LOG_LVL_TAG_VBS = '[VBS]';

const LOG_MAX_FILE_SIZE = 1024 * 1024 * 10; // 10 MB
const LOG_MAX_BUF_SIZE = 1024 * 4 * 2;
const LOG_MAX_BLOCK_SIZE = 1024 * 6;

let gOpen = false;
let process_tag;
let gLogLevel = LOG_LVL_NONE;
let gLogPath;
let gLogMode;
let gWriterStream;
let gbf = Buffer.alloc(LOG_MAX_BUF_SIZE);
let glen = 0;
let gTotalSize = 0;
let s = "";

function get_time_stamp() {
    let day = new Date();
    let mon = day.getMonth() + 1;
    let s_mon = "";
    if (mon < 10) {
        s_mon = "0" + mon;
    } else {
        s_mon += mon;
    }
    let date = day.getDate();
    let s_date = "";
    if (date < 10) {
        s_date = "0" + date;
    }
    else {
        s_date += date;
    }
    let hour = day.getHours();
    let s_hour = "";
    if (hour < 10) {
        s_hour = "0" + hour;
    } else {
        s_hour += hour;
    }
    let min = day.getMinutes();
    let s_min = "";
    if (min < 10) {
        s_min = "0" + min;
    } else {
        s_min += min;
    }
    let sec = day.getSeconds();
    let s_sec = "";
    if (sec < 10) {
        s_sec = "0" + sec;
    } else {
        s_sec += sec;
    }
    let ms = day.getMilliseconds();
    let s_ms = "";
    if (ms < 10) {
        s_ms = "00" + ms;
    } else if (ms < 100) {
        s_ms = "0" + ms;
    } else {
        s_ms += ms;
    }

    var s = day.getFullYear() + "-" + s_mon + "-" + s_date + " " + s_hour + ":"
        + s_min + ":" + s_sec + "." + s_ms;
    return s;
}

function log_open(name, lvl, append) {
    gLogLevel = lvl;
    gLogMode = append;
    gLogPath = name;
    gTotalSize = 0;
    if (gLogLevel == LOG_LVL_NONE || !name || name === "") {
        return;
    }
    let f = 'a';
    if (!append)
    {
        f = 'w';
    }
    gOpen = true;
    let option = {
        flags: f,           // 指定用什么模式打开文件，’w’代表写，’r’代表读，类似的还有’r+’、’w+’、’a’等
        encoding: 'utf8',   // 指定打开文件时使用编码格式，默认就是“utf8”，你还可以为它指定”ascii”或”base64”
        fd: null,           // fd属性默认为null，当你指定了这个属性时，createReadableStream会根据传入的fd创建一个流，忽略path。
                            // 另外你要是想读取一个文件的特定区域，可以配置start、end属性，指定起始和结束（包含在内）的字节偏移
        mode: 0664,
        autoClose: true     // autoClose属性为true（默认行为）时，当发生错误或文件读取结束时会自动关闭文件描述符
    };
    process_tag = '[' + process.pid + ']';
    gWriterStream = fs.createWriteStream(name, option);
    let head = "*********************************************************"
        + "\n * \t@platform: " + os.platform()
        + "\n * \t@arch: " + os.arch()
        + "\n * \t@pid: " + process.pid
        + "\n * \t@filename: " + name
        + "\n * \t@time: " + get_time_stamp()
        + "\n * \t@operation: open"
        + "\n*********************************************************\n";
    
    gWriterStream.write(head, 'utf8');
}

function log_close() {
    if (!gOpen) {
        return;
    }
    if (glen > 0) {
        gWriterStream.write(gbf.toString('utf8', 0, glen), 'utf8');
        glen = 0;
    }
    gOpen = false;
    let tail = "*********************************************************\n"
        + " * \t@time: " + get_time_stamp()
        + "\n * \t@operation: close"
        + "\n*********************************************************\n";

    gWriterStream.write(tail, 'utf8');
    gWriterStream.end();
    gWriterStream.close();
}

function log_backup() {
    log_close();
    let bak_ts = get_time_stamp();
    bak_ts = bak_ts.replace(new RegExp(":", 'g'), "");
    bak_ts = bak_ts.replace(new RegExp("-", 'g'), "");
    bak_ts = bak_ts.replace(new RegExp(" ", 'g'), "");
    bak_ts = "bak_"+bak_ts;
    if (!fs.existsSync("backup"))
    {
        fs.mkdirSync("backup");
    }
    fs.renameSync(gLogPath, "backup/" + bak_ts + gLogPath);
    log_open(gLogPath, gLogLevel, gLogMode);
}

// 过长 backup
function stream_write_msg(msg) {
    let len = gbf.write(msg, glen, 'utf8');
    gTotalSize += len;
    glen += len;
    if (glen > LOG_MAX_BLOCK_SIZE) {
        gWriterStream.write(gbf.toString('utf8', 0, glen), 'utf8');
        glen = 0;
    }
    if (gTotalSize >= LOG_MAX_FILE_SIZE) {
        log_backup();
    }
}

exports.LogError = function (msg) {
    if (msg == null || msg == undefined || msg === "" || !gOpen) {
        return;
    }
    if (gLogLevel & LOG_LVL_ERROR) {
        s = '[' + get_time_stamp() + ']' + process_tag + LOG_LVL_TAG_ERROR;
        stream_write_msg(s + msg + '\n');
    }
}

exports.LogCrit = function (msg) {
    if (msg == null || msg == undefined || msg === "" || !gOpen) {
        return;
    }
    if (gLogLevel & LOG_LVL_CRIT) {
        s = '[' + get_time_stamp() + ']' + process_tag + LOG_LVL_TAG_CRIT;
        stream_write_msg(s + msg + '\n');
    }
}

exports.LogWarn = function (msg) {
    if (msg == null || msg == undefined || msg === "" || !gOpen) {
        return;
    }
    if (gLogLevel & LOG_LVL_WARN) {
        s = '[' + get_time_stamp() + ']' + process_tag + LOG_LVL_TAG_WARN;
        stream_write_msg(s + msg + '\n');
    }
}

exports.LogDbg = function (msg) {
    if (msg == null || msg == undefined || msg === "" || !gOpen) {
        return;
    }
    if (gLogLevel & LOG_LVL_DBG) {
        s = '[' + get_time_stamp() + ']' + process_tag + LOG_LVL_TAG_DBG;
        stream_write_msg(s + msg + '\n');
    }
}

exports.LogInfo = function (msg) {
    if (msg == null || msg == undefined || msg === "" || !gOpen) {
        return;
    }
    if (gLogLevel & LOG_LVL_INFO) {
        s = '[' + get_time_stamp() + ']' + process_tag + LOG_LVL_TAG_INFO;
        stream_write_msg(s + msg + '\n');
    }
}

exports.LogVbs = function (msg) {
    if (msg == null || msg == undefined || msg === "" || !gOpen) {
        return;
    }
    if (gLogLevel & LOG_LVL_VBS) {
        s = '[' + get_time_stamp() + ']' + process_tag + LOG_LVL_TAG_VBS;
        stream_write_msg(s + msg + '\n');
    }
}

exports.LogOpen = function (name = "default.log", lvl = LOG_LVL_LOW, append = true) {
    log_open(name, lvl, append);
}

exports.LogClose = function () {
    log_close();
}

exports.LOG_LVL_ALL = LOG_LVL_ALL;
exports.LOG_LVL_LOW = LOG_LVL_LOW;
exports.LOG_LVL_HIGH = LOG_LVL_LOW | LOG_LVL_DBG;

测试代码

#! /usr/bin/env node
/***********************************************
 * @Author: Frodo Cheng
 * @Time: 2020-07-10 15:55:00
***********************************************/
var CSLogger = require('./CSLogger');

CSLogger.LogOpen('output.log', CSLogger.LOG_LVL_ALL);

var beg = Date.now();
var loop_cnt = 100*100*100;

for (let i = 0; i < loop_cnt; i++)
{
    CSLogger.LogError("hello, World !");
    CSLogger.LogCrit("hello, World !");
    CSLogger.LogWarn("hello, World !");
    CSLogger.LogDbg("hello, World !");
    CSLogger.LogInfo("hello, World !");
    CSLogger.LogVbs("hello, World !");
    CSLogger.LogVbs("");
    CSLogger.LogVbs();
}

CSLogger.LogClose();
var end = Date.now();
console.log(end - beg);

测试结果

性能上，6秒钟，写了600万条“hello world”日志，带时间戳。而且，带日志大小超过设置阈值之后的backup功能。

本来打算时间戳要准备采用 moment的一个小插件，但是，自己实现的get_time_stamp函数，虽然功能比较简单，但是实测效果比 moment 插件要快 50%，而且，自己实现，无需install其他module去解决依赖，更加绿色一些。

说一下原理

其实Node.js 里面到底是怎么实现的，我并不知道。但是，如果跨平台的这种文件I/O，我们要知道不同层面的接口，内部大致的实现机制。要回到C语言。

在ISO C 中文件IO的操作，其实是 FILE 那一套系统，这一套系统的做法是：缓存用户的读写数据。以写为例，其在内存中会保持一个 buf，默认大小为4k。也就是说，在ISO C 中，fwrite 的每次，都是 写进 这个FILE* 的 buf中去了，达到4k之后，就会进行系统调用，将4k数据写入内核中，然后内核中，根据不同的文件设备系统，写进设备的驱动缓存中或者什么的，这个，我没系统的了解过块设备，不知道具体是怎么实现的。但是，从应用空间到内核空间，是进行了两次的数据拷贝。

那么为什么要这么干呢？

如果说，我们直接采用系统调用，比如Linux系统的 write 或者 windows系统的 WriteFile，每次的调用，那都是系统调用。

Linux 系统调用的过程就是用户API进入GLIBC中，GLIBC触发软中断，软中断号跳转到异常向量表，进程由用户空间切换至内核空间，触发异常向量表对应的系统调用等等等等吧。反正就是说，这一套流程，是相对繁琐的，不断的进行系统调用，那是非常耗时的。

所以，标准ISO，就进行了读写的缓存，而减少系统调用的次数。

所以，最傻写文件的做法是：每次的写，哪怕是1个字节，都是打开文件，写文件，然后close文件。这个不说了，本人亲测事件，用FILE那一套接口，fopen fwrite fclose，写100万次helloworld，耗时26秒。这个fwrite每一次其实并不会触发write系统调用，但是fclose就不一样了，这个接口会刷流。也就是说那个4k的buf中只要有数据，就会触发write系统调用。总之，这个做法是最傻的。如果是open，write，close这一套呢？没试过，但是可能性能反而会高于上面的做法，因为，少了一次数据拷贝，但是并不会提升多少。系统调用的次数的量级是一样的。

所以，一般的做法：

1. fopen，循环fwrite，最后fclose，甚至对于一些程序，fclose都不需要。比如server端程序，文件打开了就一直用着，或者桌面端程序，起来的时候fopen，退出，ISOC的exit函数，也会正常刷流。但是unistd.h 中的_exit，是不会刷流的，就会有遗留数据。

这种做法，其实相比第一种，26秒，能够直接降到2秒钟。一般的情况下，这种处理已经可以了。

2. open ，循环write，然后close，这样的做法，耗时8秒左右。

3. 但是，还有一种，自己仿 ISO C的做法，跳过ISO的接口，然后，直接调用系统调用。比如redis里面就这么干的。这样的做法，可控性极强。很多自实现的读写系统都是这么干的，典型的比如redis的文件IO中，就是这么自实现的。自实现主要控制的就是buf的大小，以及write的时机。redis中，无论是rdb或者aof，这个buf大小都是32M。其实是进一步减少了系统调用。但是，这样的做法，write，尤其是datasync的单次操作，那耗时就很长了。

以上1. 3 中，都是两次的数据拷贝，将用户层数据刷入了内核空间。1的系统调用次数数据颗粒度是4k，3中的数据颗粒度，自己调的，32m 64m 都可以。

2，直接就系统调用，数据拷贝次数减少了一次，但是系统调用次数大幅度增加。

所以，用户层来说，高效的日志系统，一般采用3的方法较多。