diff --git a/package-lock.json b/package-lock.json index 6c5153e..075e7f3 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,20 +1,20 @@ { "name": "@hibas123/nodelogging", - "version": "3.0.10", + "version": "3.1.2", "lockfileVersion": 2, "requires": true, "packages": { "": { "name": "@hibas123/nodelogging", - "version": "3.0.10", + "version": "3.1.2", "license": "MIT", "dependencies": { - "@hibas123/logging": "^3.1.0", + "@hibas123/logging": "^3.1.1", "@hibas123/utils": "^2.2.18" }, "devDependencies": { - "@types/node": "^15.0.2", - "concurrently": "^6.0.2", + "@types/node": "^15.3.0", + "concurrently": "^6.1.0", "nodemon": "^2.0.7", "typescript": "^4.2.4" } @@ -107,9 +107,9 @@ } }, "node_modules/@hibas123/logging": { - "version": "3.1.0", - "resolved": "https://npm.hibas123.de/@hibas123%2flogging/-/logging-3.1.0.tgz", - "integrity": "sha512-iUFXdkuSYcxiIChOccTC84xldwKXJ0vdNruTiVTrU07x69BL9DvuvJ6e3CBTIy2HKgT1K1q1VChTModKPEus7A==", + "version": "3.1.1", + "resolved": "https://npm.hibas123.de/@hibas123%2flogging/-/logging-3.1.1.tgz", + "integrity": "sha512-A1zUOdczajpCURqX0JAoTeadLLSZsLBQg9dQV1DK5zVcyrLBbFqt3fkE41tvE097bm8sjjYkx9v+HSRzvqzGRg==", "license": "MIT" }, "node_modules/@hibas123/utils": { @@ -140,9 +140,9 @@ } }, "node_modules/@types/node": { - "version": "15.0.2", - "resolved": "https://npm.hibas123.de/@types%2fnode/-/node-15.0.2.tgz", - "integrity": "sha512-p68+a+KoxpoB47015IeYZYRrdqMUcpbK8re/zpFB8Ld46LHC1lPEbp3EXgkEhAYEcPvjJF6ZO+869SQ0aH1dcA==", + "version": "15.3.0", + "resolved": "https://npm.hibas123.de/@types%2fnode/-/node-15.3.0.tgz", + "integrity": "sha512-8/bnjSZD86ZfpBsDlCIkNXIvm+h6wi9g7IqL+kmFkQ+Wvu3JrasgLElfiPgoo8V8vVfnEi0QVS12gbl94h9YsQ==", "dev": true, "license": "MIT" }, @@ -573,9 +573,9 @@ "dev": true }, "node_modules/concurrently": { - "version": "6.0.2", - "resolved": "https://npm.hibas123.de/concurrently/-/concurrently-6.0.2.tgz", - "integrity": "sha512-u+1Q0dJG5BidgUTpz9CU16yoHTt/oApFDQ3mbvHwSDgMjU7aGqy0q8ZQyaZyaNxdwRKTD872Ux3Twc6//sWA+Q==", + "version": "6.1.0", + "resolved": "https://npm.hibas123.de/concurrently/-/concurrently-6.1.0.tgz", + "integrity": "sha512-jy+xj49pvqeKjc2TAVXRIhrgPG51eBKDZti0kZ41kaWk9iLbyWBjH6KMFpW7peOLkEymD+ZM83Lx6UEy3N/M9g==", "dev": true, "license": "MIT", "dependencies": { @@ -2179,9 +2179,9 @@ } }, "@hibas123/logging": { - "version": "3.1.0", - "resolved": "https://npm.hibas123.de/@hibas123%2flogging/-/logging-3.1.0.tgz", - "integrity": "sha512-iUFXdkuSYcxiIChOccTC84xldwKXJ0vdNruTiVTrU07x69BL9DvuvJ6e3CBTIy2HKgT1K1q1VChTModKPEus7A==" + "version": "3.1.1", + "resolved": "https://npm.hibas123.de/@hibas123%2flogging/-/logging-3.1.1.tgz", + "integrity": "sha512-A1zUOdczajpCURqX0JAoTeadLLSZsLBQg9dQV1DK5zVcyrLBbFqt3fkE41tvE097bm8sjjYkx9v+HSRzvqzGRg==" }, "@hibas123/utils": { "version": "2.2.18", @@ -2204,9 +2204,9 @@ } }, "@types/node": { - "version": "15.0.2", - "resolved": "https://npm.hibas123.de/@types%2fnode/-/node-15.0.2.tgz", - "integrity": "sha512-p68+a+KoxpoB47015IeYZYRrdqMUcpbK8re/zpFB8Ld46LHC1lPEbp3EXgkEhAYEcPvjJF6ZO+869SQ0aH1dcA==", + "version": "15.3.0", + "resolved": "https://npm.hibas123.de/@types%2fnode/-/node-15.3.0.tgz", + "integrity": "sha512-8/bnjSZD86ZfpBsDlCIkNXIvm+h6wi9g7IqL+kmFkQ+Wvu3JrasgLElfiPgoo8V8vVfnEi0QVS12gbl94h9YsQ==", "dev": true }, "@types/normalize-package-data": { @@ -2542,9 +2542,9 @@ "dev": true }, "concurrently": { - "version": "6.0.2", - "resolved": "https://npm.hibas123.de/concurrently/-/concurrently-6.0.2.tgz", - "integrity": "sha512-u+1Q0dJG5BidgUTpz9CU16yoHTt/oApFDQ3mbvHwSDgMjU7aGqy0q8ZQyaZyaNxdwRKTD872Ux3Twc6//sWA+Q==", + "version": "6.1.0", + "resolved": "https://npm.hibas123.de/concurrently/-/concurrently-6.1.0.tgz", + "integrity": "sha512-jy+xj49pvqeKjc2TAVXRIhrgPG51eBKDZti0kZ41kaWk9iLbyWBjH6KMFpW7peOLkEymD+ZM83Lx6UEy3N/M9g==", "dev": true, "requires": { "chalk": "^4.1.0", diff --git a/package.json b/package.json index 18d6ddf..6151408 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@hibas123/nodelogging", - "version": "3.1.0", + "version": "3.1.2", "description": "", "main": "out/index.js", "types": "out/index.d.ts", @@ -11,6 +11,7 @@ "watch-js": "nodemon out/test.js", "watch": "concurrently npm:watch-*", "test": "npm run build && node out/test.js", + "benchmark": "npm run build && node out/benchmark.js", "live": "nodemon out/test.js" }, "repository": { @@ -26,13 +27,13 @@ "readme.md" ], "devDependencies": { - "@types/node": "^15.0.2", - "concurrently": "^6.0.2", + "@types/node": "^15.3.0", + "concurrently": "^6.1.0", "nodemon": "^2.0.7", "typescript": "^4.2.4" }, "dependencies": { - "@hibas123/logging": "^3.1.0", + "@hibas123/logging": "^3.1.1", "@hibas123/utils": "^2.2.18" } } diff --git a/src/benchmark.ts b/src/benchmark.ts new file mode 100644 index 0000000..b854b38 --- /dev/null +++ b/src/benchmark.ts @@ -0,0 +1,50 @@ +import { Formatted, LoggingBase, LoggingTypes } from "@hibas123/logging"; +import { once } from "events"; +import { createWriteStream } from "fs"; +import { FileAdapter } from "./filewriter"; + +let results = {}; + +async function benchmark( + name: string, + count: number, + runner: (cnt: number) => Promise +) { + console.log("Benchmark starting:", name); + const start = process.hrtime.bigint(); + + await runner(count); + + const diffNS = process.hrtime.bigint() - start; + const diffMS = Number(diffNS / BigInt(1000 * 1000)); + + console.log("Benchmark ended:", name); + + results[name] = { + count, + time: diffMS, + timePerI: (diffMS / count).toFixed(4), + }; +} + +Promise.resolve().then(async () => { + const largeText = "hallowelt!".repeat(250); + + const lg = new LoggingBase({ + console: false, + }); + const fs = new FileAdapter("logs/benchmark", Number.MAX_SAFE_INTEGER); + await lg.addAdapter(fs); + + await benchmark("large data", 100000, async (cnt) => { + console.time("Logging"); + for (let i = 0; i < cnt; i++) { + lg.log(largeText); + } + console.timeEnd("Logging"); + + await fs.close(); + await lg.close(); + }); + console.table(results); +}); diff --git a/src/filewriter.ts b/src/filewriter.ts index 3cec483..f1bc639 100644 --- a/src/filewriter.ts +++ b/src/filewriter.ts @@ -1,29 +1,33 @@ -import { Lock } from "@hibas123/utils"; +import { AwaitStore, Lock } from "@hibas123/utils"; import * as fs from "fs"; import * as path from "path"; import { Adapter, Message, Formatted, LoggingTypes } from "@hibas123/logging"; +import { once } from "events"; const MAX_FILE_SIZE = 500000000; -export class LoggingFiles implements Adapter { +export class FileAdapter implements Adapter { level = LoggingTypes.Debug; file: Files; + isInit = new AwaitStore(false); constructor(private filename: string, private maxFileSize = MAX_FILE_SIZE) {} setLevel(level: LoggingTypes) { this.level = level; } - init() { + async init() { if (!this.file) { this.file = Files.getFile(this.filename); - this.file.init(this.maxFileSize); + await this.file + .init(this.maxFileSize) + .then(() => this.isInit.send(true)); } } flush(sync: boolean) { - this.file.flush(sync); + // return this.file.flush(sync); } onMessage(message: Message) { @@ -31,9 +35,12 @@ export class LoggingFiles implements Adapter { this.file.write(msg); } - close() { - this.file.close(); - this.file = undefined; + async close() { + if (this.file) { + await this.file.close(); + this.file = undefined; + } + this.isInit.send(false); } } @@ -61,8 +68,6 @@ const Debounce = (callback: () => void, iv = 500, max = 100) => { }; export class Files { - private open = 0; - private static files = new Map(); static getFile(filename: string): Files { filename = path.resolve(filename); @@ -75,13 +80,15 @@ export class Files { return file; } - private maxFileSize = MAX_FILE_SIZE; - private size: number = 0; - private stream: fs.WriteStream = undefined; - private lock = new Lock(); - private debounce = Debounce(this.checkQueue.bind(this)); + private open = 0; + #maxFileSize = MAX_FILE_SIZE; + #size: number = 0; + #stream: fs.WriteStream = undefined; + #lock = new Lock(); + #debounce = Debounce(this.checkQueue.bind(this)); #initialized = false; + #queue: Buffer[] = []; public get initlialized() { return this.#initialized; @@ -91,30 +98,38 @@ export class Files { public async init(maxFileSize: number) { if (this.#initialized) return; - let lock = await this.lock.getLock(); - this.maxFileSize == maxFileSize; + this.#maxFileSize = maxFileSize; + + let lock = await this.#lock.getLock(); + + const folder = path.dirname(this.file); + if (folder) { + if (!(await fsExists(folder))) { + await fsMkDir(folder).catch(() => {}); //Could happen, if two seperate instances want to create the same folder so ignoring + } + } + await this.initializeFile(); this.#initialized = true; + await this.checkQueue(true); lock.release(); - this.checkQueue(); } private async initializeFile(new_file = false) { + console.time("init"); try { - if (this.stream) { - this.stream.close(); - } - const folder = path.dirname(this.file); - if (folder) { - if (!(await fsExists(folder))) { - await fsMkDir(folder).catch(() => {}); //Could happen, if two seperate instances want to create the same folder so ignoring - } + if (this.#stream) { + const closePrms = once(this.#stream, "close"); + + this.#stream.end(); + + await closePrms; } let size = 0; if (await fsExists(this.file)) { let stats = await fsStat(this.file); - if (new_file || stats.size >= this.maxFileSize) { + if (new_file || stats.size >= this.#maxFileSize) { if (await fsExists(this.file + ".old")) await fsUnlink(this.file + ".old"); await fsMove(this.file, this.file + ".old"); @@ -123,62 +138,77 @@ export class Files { } } - this.stream = fs.createWriteStream(this.file, { flags: "a" }); - this.size = size; + this.#stream = fs.createWriteStream(this.file, { flags: "a" }); + this.#size = size; } catch (e) { console.log(e); - //TODO: is this the right behavior? + //TODO: is this the right behavior? Probably not... process.exit(1); } + console.timeEnd("init"); } - private queue: Buffer[] = []; - - async checkQueue() { - if (this.lock.locked) return; - let lock = await this.lock.getLock(); - let msg: Buffer; - while ((msg = this.queue.shift())) { - await this.write_to_file(msg); + private async checkQueue(nolock: boolean = false) { + let lock: any; + if (nolock == false) { + if (this.#lock.locked) return; + lock = await this.#lock.getLock(); } - lock.release(); + + let entry: Buffer; + console.log("Check queue with", this.#queue.length); + let c = 0; + let buffer = Buffer.alloc(1024 * 128); + let ci = 0; + while ((entry = this.#queue.shift())) { + if (entry.length > buffer.length) { + this.write_to_file(entry.slice(0, ci)); + ci = 0; + this.write_to_file(entry); + } else if (entry.length + ci > buffer.length) { + this.write_to_file(entry.slice(0, ci)); + ci = 0; + entry.copy(buffer, ci); + ci += entry.length; + } else { + entry.copy(buffer, ci); + ci += entry.length; + } + } + + if (ci > 0) { + await this.write_to_file(buffer.slice(0, ci)); + } + + console.log("Check queue real", c); + + if (lock) lock.release(); } public async close() { - await this.flush(false); + //TODO: maybe some raceconditions when open collides with close + const lock = await this.#lock.getLock(); + await this.checkQueue(true); this.open--; if (this.open <= 0) { - this.stream.close(); + const a = once(this.#stream, "close"); + this.#stream.close(); + await a; Files.files.delete(this.file); } - } - - public flush(sync: boolean) { - if (sync) { - // if sync flush, the process most likely is in failstate, so checkQueue stopped its work. - let msg: Buffer; - while ((msg = this.queue.shift())) { - this.stream.write(msg); - } - } else { - return Promise.resolve().then(async () => { - const lock = await this.lock.getLock(); - lock.release(); - await this.checkQueue(); - }); - } + lock.release(); } private async write_to_file(data: Buffer) { try { if ( - data.byteLength < this.maxFileSize && - this.size + data.byteLength > this.maxFileSize + data.byteLength < this.#maxFileSize && + this.#size + data.byteLength > this.#maxFileSize ) { await this.initializeFile(true); } - this.size += data.byteLength; - this.stream.write(data); + this.#size += data.byteLength; + this.#stream.write(data); } catch (err) { // TODO: Better error handling! console.error(err); @@ -188,14 +218,15 @@ export class Files { } public write(data: Buffer) { - this.queue.push(data); - this.debounce.trigger(); + this.#queue.push(data); + this.#debounce.trigger(); } - - public dispose() {} } -function fsUnlink(path) { +function fsUnlink(path: string) { + if (fs.promises?.unlink) { + return fs.promises.unlink(path); + } return new Promise((resolve, reject) => { fs.unlink(path, (err) => { if (err) reject(err); @@ -205,6 +236,9 @@ function fsUnlink(path) { } function fsStat(path: string) { + if (fs.promises?.stat) { + return fs.promises.stat(path); + } return new Promise((resolve, reject) => { fs.stat(path, (err, stats) => { if (err) reject(err); @@ -243,7 +277,7 @@ function fsMove(oldPath: string, newPath: string) { function fsExists(path: string) { return new Promise((resolve, reject) => { - fs.exists(path, resolve); + fs.access(path, (err) => resolve(!err)); }); } diff --git a/src/index.ts b/src/index.ts index 5aee69b..00dbd50 100644 --- a/src/index.ts +++ b/src/index.ts @@ -1,5 +1,5 @@ -export { LoggingFiles } from "./filewriter"; -import { LoggingFiles } from "./filewriter"; +export { FileAdapter } from "./filewriter"; +import { FileAdapter } from "./filewriter"; import { LoggingBase } from "@hibas123/logging"; import Logging from "@hibas123/logging"; @@ -21,8 +21,8 @@ LoggingBase.nativeFunctions = { }, }; -export const DefaultLoggingFile = new LoggingFiles("./logs/all.log"); +export const DefaultFileAdapter = new FileAdapter("./logs/all.log"); -Logging.addAdapter(DefaultLoggingFile); +Logging.addAdapter(DefaultFileAdapter); export default Logging; diff --git a/src/test.ts b/src/test.ts index f3ea692..d1b678a 100644 --- a/src/test.ts +++ b/src/test.ts @@ -1,7 +1,7 @@ import { randomBytes } from "crypto"; import * as fs from "fs"; import { LoggingBase } from "@hibas123/logging"; -import Logging, { DefaultLoggingFile } from "."; +import Logging, { DefaultFileAdapter, FileAdapter } from "."; const deleteFolderRecursive = function (path: string) { if (fs.existsSync(path)) { @@ -52,19 +52,32 @@ cus2.log("Hello from custom Logger 2"); cus22.log("Hello from custom Logger 22"); cus2.log("Hello from custom Logger 2"); -const BenchmarkLogger = new LoggingBase({ - console: false, - name: "bench", -}); - -BenchmarkLogger.addAdapter(DefaultLoggingFile); - async function benchmark(count: number, message_size: number) { - const randData = randomBytes(message_size).toString("hex"); + const BenchmarkLogger = new LoggingBase({ + console: false, + name: "bench", + }); + + if (fs.existsSync("logs/benchmark")) { + fs.unlinkSync("logs/benchmark"); + } + + if (fs.existsSync("logs/benchmark.old")) { + fs.unlinkSync("logs/benchmark.old"); + } + + const BenchmarkFile = new FileAdapter("logs/benchmark"); + + BenchmarkLogger.addAdapter(BenchmarkFile); + + const randData = randomBytes(message_size / 2).toString("hex"); const t = process.hrtime(); for (let i = 0; i < count; i++) { BenchmarkLogger.log(randData); } + await BenchmarkFile.flush(false); + await BenchmarkLogger.close(); + const diff = process.hrtime(t); const NS_PER_SEC = 1e9; const ns = diff[0] * NS_PER_SEC + diff[1]; @@ -79,12 +92,12 @@ async function benchmark(count: number, message_size: number) { const benchTimer = Logging.time("benchmark"); Promise.resolve().then(async () => { console.log("Large data benchmark:"); - await benchmark(7000, 50000); + await benchmark(70000, 50000); console.log("Realdata data benchmark:"); await benchmark(100000, 100); benchTimer.end(); -}); -const timer = Logging.time("Test Timer"); -setTimeout(() => timer.end(), 1000); + const timer = Logging.time("Test Timer"); + setTimeout(() => timer.end(), 1000); +});