Speed up file logging for high rate of logging. #115

Merged
merged 1 commit into from Feb 15, 2013

Projects

None yet

2 participants

Contributor

This is in response to my own #114.

During an evaluation of multiple loggers, I saw a slow down when trying to
quickly log more than 100,000 messages to a file:

    counter = 150000;
    while (counter) {
        logger.info('Message[' + counter + ']');
        counter -= 1;
    }

My detailed test can be found here:

The test demonstrate that writing 150,000 lines straight in a FileStream
takes about 22 seconds until the file content stabilizes. When calling
logger.debug() 150,000 times, the file stabilizes to its final content
after 229s ( almost 4 minutes ! ).

After investigation, it turns out that the problem is using an Array() to
accumulate the data. Pushing the data in the Array with Array.push() is
quick, but the code flushing the buffer uses Array.shift(), which forces
re-indexing of all 149,999 elements remaining in the Array. This is
exponentially slower as the buffer grows.

The solution is to use something else than an Array to accumulate the
messages. The fix was made using a package called Dequeue
( https://github.com/lleo/node-dequeue ). By replacing the Array with
a Dequeue object, it brought the logging of 150,000 messages back down to
31s. Seven times faster than the previous 229s.

There is a caveat that each log event is slightly longer due to the need
to create an object to put in the double-ended queue inside the Dequeue
object. According to a quick test, it takes about 4% more time per call
to logger.debug().

Nicolas Pelletier Speed up file logging for high rate of logging.
During an evaluation of multiple loggers, I saw a slow down when trying to
quickly log more than 100,000 messages to a file:
```javascript
    counter = 150000;
    while (counter) {
        logger.info('Message[' + counter + ']');
        counter -= 1;
    }
```

My detailed test can be found here:
 - https://gist.github.com/NicolasPelletier/4773843

The test demonstrate that writing 150,000 lines straight in a FileStream
takes about 22 seconds until the file content stabilizes. When calling
logger.debug() 150,000 times, the file stabilizes to its final content
after 229s ( almost 4 minutes ! ).

After investigation, it turns out that the problem is using an Array() to
accumulate the data. Pushing the data in the Array with Array.push() is
quick, but the code flushing the buffer uses Array.shift(), which forces
re-indexing of all 149,999 elements remaining in the Array. This is
exponentially slower as the buffer grows.

The solution is to use something else than an Array to accumulate the
messages. The fix was made using a package called Dequeue
( https://github.com/lleo/node-dequeue ). By replacing the Array with
a Dequeue object, it brought the logging of 150,000 messages back down to
31s. Seven times faster than the previous 229s.

There is a caveat that each log event is slightly longer due to the need
to create an object to put in the double-ended queue inside the Dequeue
object. According to a quick test, it takes about 4% more time per call
to logger.debug().
b75e366
Contributor

This is the first time I do a Pull Request in a package which required a change in dependencies... If I did something wrong, please let me know and I'll fix it.

@nomiddlename nomiddlename merged commit a15a628 into nomiddlename:master Feb 15, 2013

1 check passed

default The Travis build passed
Details
Owner

Nice, simple change. I like it, thanks! I'll push out a new version to npm very soon.

Contributor

Glad you like it. I will close issue #114 now that this is delivered.

Owner

Released in 0.5.7 in npm.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment