Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 1 commit into from
Feb 15, 2013

Conversation

NicolasPelletier
Copy link
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().

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().
@NicolasPelletier
Copy link
Contributor Author

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 pushed a commit that referenced this pull request Feb 15, 2013
Speed up file logging for high rate of logging.
@nomiddlename nomiddlename merged commit a15a628 into log4js-node:master Feb 15, 2013
@nomiddlename
Copy link
Collaborator

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

@NicolasPelletier
Copy link
Contributor Author

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

@nomiddlename
Copy link
Collaborator

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
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants