Log4js takes hours to write logfile

Question

I am using log4js in my code to log the results and errors. The program runs for about 2,5 hours before the final console output is made and afterwards needs several hours to complete writing the logfile. The log is writing for 6 hours now (since the algorithm itself finished) and the filesize is 100mb. The log will be about 1,5 million lines (when done).

Is it normal for the log to be written as slow as this? Are there "standard" mistakes to make when using log4js that I could check?

In case you want to know: The program is running on an Intel i5 with 8gb RAM and an SSD drive, so the hardware shouldn't be the problem I guess.

I am not sure what other information I can give you, just ask ahead if you need to know something.

No it probably shouldn't take that long. Most SSD's should be able to write over 100MiB a second. What OS? What else is the OS doing? Are any of your log statements running complex code? Can you see a large delay between specific log lines? — Matt, Aug 24 '14 at 20:10
Its Win 7 (64bit) for the OS. There is nothing special running in the background and the log lines only write down informations, no code of there own. The log has finally finished over night. It is now 181mb of size and contains 1,365 mio. lines. The only thing that comes to my mind, is that I save the logfile in the cloud (local Dropbox file) maybe the syncing of Dropbox somehow devastates my performance? — user3599232, Aug 25 '14 at 05:27
Dropbox is certainly where I would look first... I'll put some steps into an answer. — Matt, Aug 25 '14 at 07:18
Thank you. I will try again tonight with a local logfile, and post the result tomorrow morning. — user3599232, Aug 25 '14 at 08:07
can I ask you what do your program do to run 2.5 hs in node? I'm developing a compile-to-js, compile-to-c lang -in beta-. Syntax is so close to js that translation is trivial. I'm getting a 7x performance when compiled-to-c, so your code could -theoretically- run in 20 minutes instead of 2.5 hours. check: https://github.com/luciotato/LiteScript and contact me if you think it can be useful — Lucio M. Tato, Aug 26 '14 at 02:18
Hi Lucio, sry but I am not allowed to show my code to anyone (I signed an NDA) and I do not have enough time myself to get into your compile-to-js script. I really hope you can find some other testcodes, this sounds really interesting :) — user3599232, Aug 26 '14 at 12:14

score 0 · Answer 1 · answered Aug 25 '14 at 08:19

Dropbox sounds like a good candidate. Any anti virus software could also interfere.

Firstly I would confirm what your system is capable of by creating a mini log4js benchmark for the various configurations available on your PC, then compare that to your application performance.

var Benchmark = require('benchmark');
var log4js    = require('log4js');

log4js.clearAppenders();
log4js.loadAppender('file');

log4js.addAppender(log4js.appenders.file('NUL'), 'nulnulnul');
var lognul    = log4js.getLogger('nulnulnul');

log4js.addAppender(log4js.appenders.file('c:/your_dropbox/test.log'), 'normallog');
var lognorm   = log4js.getLogger('normallog');

log4js.addAppender(log4js.appenders.file('c:/tmp/test.log'), 'nodropbox');
var lognodr   = log4js.getLogger('nodropbox');

log4js.addAppender(log4js.appenders.file('c:/virus-exception/test.log'), 'nodropvir');
var lognodv   = log4js.getLogger('nodropvir');


var suite     = new Benchmark.Suite;

// add tests
suite.add('Log#Nul', function() {
  lognul.info("Some lengthy nulnulnul info messages");
})
.add('Log#normal', function() {
  lognorm.info("Some lengthy normallog info messages");
})
.add('Log#NoDropbox', function() {
  lognodr.info("Some lengthy nodropbox info messages");
})
.add('Log#NoVirusOrDropbox', function() {
  lognodv.info("Some lengthy nodropvir info messages");
})
// add listeners
.on('cycle', function(event) {
  console.log(String(event.target));
})
.on('complete', function() {
  console.log('Fastest is ' + this.filter('fastest').pluck('name'));
})
// run async
.run({ 'async': false });

If Dropbox or Virus software doesn't turn out to be the problem there are two Windows Sysinternal tools that will help you see what is going on your system when your process is running.

Process Explorer - Overall task manager/performance viewer

Gives you an overall view of your system so you can see which processes are doing what. You can also drill down into specific processes as well (right click/properties)

Process Monitor - Event profiler for processes.

Process Monitor is like a log file of all the system calls any process makes. You can filter down to specific processes or calls so in your case you would be able to monitor Dropbox and your Node.js process and see if their access to the file in question is interleaved while Dropbox does it's work.

I have relocated the logfile onto my desktop, but it still writes very slowly. I have written a small benchmarktest, which logs 100.000 lines of an array with random integers in it (with log4js). This took about 15 sec at most. I have run Process Explorer, which tells me, that node.js is currently using ~25% of my CPU, the rest is more or less idle. This matches my understanding that node runs on a single core (without programming different threads). But still, the mini test I wrote should only have used one core as well and it was way faster. So it has to be a problem with my code has'nt it? — user3599232, Aug 26 '14 at 12:11
Sounds like it's something with your code. You may need to profile a cut down run to see where it's spending most of it's time during the logging. Last time I tried this I got to a web agent that you connect to with Chrome which uses the chrome dev tools. It never worked very well. I think it was node inspector or node agent from [this answer](http://stackoverflow.com/a/16512303/1318694) — Matt, Aug 26 '14 at 13:10
Very curious. I saved more than 90% of the loglines in an array and tried to write those lines with log4js in one bulk at the end of the program, but it still takes the same time. — user3599232, Aug 26 '14 at 13:13

Log4js takes hours to write logfile

1 Answers1