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

util: refactor format method. #12407

Closed
wants to merge 8 commits into from
Closed

Conversation

jseijas
Copy link

@jseijas jseijas commented Apr 14, 2017

Method format refactored to make it more maintenable, replacing the
switch by a function factory, that returns the appropiated function
given the character (d, i , f, j, s).

Also, performance when formatting an string that contains several
consecutive % symbols is improved. The test:

const numSamples = 10000000;
const strPercents = '%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%s%%%%%%%%%%%%%%%%%i%%%%%%%%%%%%%%%%%%%%%%%%%%';
var s;
console.time('Percents');
for (let i = 0; i < numSamples; i++) {
  s = util.format(strPercents, 'test', 12);
}
console.timeEnd('Percents');

Original time: 28399.708ms
After refactor: 23763.788ms
Improved: 16%

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • tests and/or benchmarks are included
  • commit message follows commit guidelines
Affected core subsystem(s)

Method format refactored to make it more maintenable, replacing the
switch by a function factory, that returns the appropiated function
given the character (d, i , f, j, s).

Also, performance when formatting an string that contains several
consecutive % symbols is improved. The test:
`const numSamples = 10000000;
const strPercents = '%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%s%%%%%%%%%%%%%%%%%i%%%%%%%%%%%%%%%%%%%%%%%%%%';
var s;
console.time('Percents');
for (let i = 0; i < numSamples; i++) {
  s = util.format(strPercents, 'test', 12);
}
console.timeEnd('Percents');`

Original time:   28399.708ms
After refactor:  23763.788ms
Improved: 16%
@nodejs-github-bot nodejs-github-bot added the util Issues and PRs related to the built-in util module. label Apr 14, 2017
@vsemozhetbyt
Copy link
Contributor

Thank you for the contribution!

CI: https://ci.nodejs.org/job/node-test-pull-request/7390/

lib/util.js Outdated
break;
if (lastPos < i)
str += f.slice(lastPos, i);
str += tryStringify(arguments[a++]);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It seems this function was used only here (linter reports 'tryStringify' is defined but never used)

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed. I commited the changes. Also passed all tests.

lib/util.js Outdated
lastPos = i = i + 2;
continue;
}
}
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Linter: Trailing spaces not allowed

@vsemozhetbyt
Copy link
Contributor

vsemozhetbyt commented Apr 14, 2017

test/parallel/test-util-format.js fails with TypeError: Converting circular structure to JSON. See now abandoned tryStringify().

Did you run tests for a new build with your fix?

@hiroppy
Copy link
Member

hiroppy commented Apr 14, 2017

Thanks for your pull request.

I think you should write a test before refactoring.
Required lines: L91, 93, 99, 101
coverage: https://coverage.nodejs.org/coverage-d0cd8c8589173da1/root/util.js.html

@mscdex
Copy link
Contributor

mscdex commented Apr 14, 2017

These changes as-is introduce performance regressions:

                                           improvement confidence      p.value
 util/format.js type="number" n=10000000       2.32 %        *** 1.138891e-05
 util/format.js type="object" n=10000000      -5.17 %        *** 1.038111e-06
 util/format.js type="string" n=10000000      -2.35 %        *** 2.043293e-07
 util/format.js type="unknown" n=10000000     -8.66 %        *** 4.520538e-26

I didn't bother running with type=no-replace because it takes considerably longer than the others.

I believe similar changes had been suggested in the past (although with a lookup table instead of a function with a switch) and there were performance regressions back then as well. I'm not sure if (or how much) inlining the helper function would make a positive difference.

@vsemozhetbyt
Copy link
Contributor

CI: https://ci.nodejs.org/job/node-test-pull-request/7399/

@jseijas
Copy link
Author

jseijas commented Apr 14, 2017

I updated the PR with these changes:

  • Added unit tests for having full coverage before refactor, as asked by @abouthiroppy
  • Added tryStringify and run the unit tests, as asked by @vsemozhetbyt (Sorry! It was my fault!)

About performance asked by @mscdex:
I tried with the benchmark in both Linux (Ubuntu 64) and Windows (Windows 7 64). The results with previous master and this PR are pretty similar.

Previous master:

util/format.js type="string" n=1000000: 1,855,295.8547256442
util/format.js type="number" n=1000000: 1,830,136.1041657394
util/format.js type="object" n=1000000: 253,222.17449454102
util/format.js type="unknown" n=1000000: 3,623,680.543628614
util/format.js type="no-replace" n=1000000: 30,053.1634236955

This PR

util/format.js type="string" n=1000000: 1,891,075.1743455955
util/format.js type="number" n=1000000: 1,564,578.625822645
util/format.js type="object" n=1000000: 236,045.4131518764
util/format.js type="unknown" n=1000000: 3,472,115.0568377078
util/format.js type="no-replace" n=1000000: 30,129.379419319466

Also I checked with my own script to compare between current master and this PR. This is the script that I used:

const util = require('util');
const numSamples = 10000000;

const strShort = 'a';
const strNormal = 'Name is %s number is %i. Done.';
const strPercents = '%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%s%%%%%%%%%%%%%%%%%i%%%%%%%%%%%%%%%%%%%%%%%%%%';
var s;

console.time('Short');
for (let i = 0; i < numSamples; i++) {
  s = util.format(strShort);
}
console.log(s);
console.log('Time for '+numSamples+' samples of Short');
console.timeEnd('Short');

console.time('Normal');
for (let i = 0; i < numSamples; i++) {
  s = util.format(strNormal, 'test', 12);
}
console.log(s);
console.log('Time for '+numSamples+' samples of Normal');
console.timeEnd('Normal');

console.time('Percents');
for (let i = 0; i < numSamples; i++) {
  s = util.format(strPercents, 'test', 12);
}
console.timeEnd('Percents');

console.time('Less Parameters');
for (let i = 0; i < numSamples; i++) {
  s = util.format(strNormal, 'test');
}
console.log(s);
console.log('Time for '+numSamples+' samples of Less Parameters');
console.timeEnd('Less Parameters');

And these are the results with my script:

Previous master

Time for 10000000 samples of Short
Short: 382.084ms
Time for 10000000 samples of Normal
Normal: 11162.574ms
Percents: 27439.185ms
Time for 10000000 samples of Less Parameters
Less Parameters: 8967.359ms

This PR:

Time for 10000000 samples of Short
Short: 389.939ms
Time for 10000000 samples of Normal
Normal: 11141.138ms
Percents: 23552.820ms
Time for 10000000 samples of Less Parameters
Less Parameters: 8914.957ms

After 10 different runs, I always get similar times for the Short, Normal, and Less Parameters, but for the Percents (use of '%%%%%%%%%%' inside the string) I'm getting always best performance with the PR code.

assert.strictEqual(util.format('o: %j, a: %j', {}, []), 'o: {}, a: []');
assert.strictEqual(util.format('o: %j, a: %j', {}), 'o: {}, a: %j');
assert.strictEqual(util.format('o: %j, a: %j'), 'o: %j, a: %j');


Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: unneccesary newline.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed!

Copy link
Contributor

@silverwind silverwind left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM if perf is the same.

Copy link
Member

@benjamingr benjamingr left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changes LGTM, I'm fine with a ~5% regression in perf of util.format since it's not used in "hot paths" of node apps anyway and I think the new code is a lot more readable.

@mscdex
Copy link
Contributor

mscdex commented Apr 14, 2017

@benjamingr I wouldn't say it's not in a "hot path." I would bet at least logging modules and such make use of it. I would also bet that having consecutive %'s like that is uncommon.

@jseijas
Copy link
Author

jseijas commented Apr 14, 2017

@mscdex You're right, consecutive %'s is uncommon. But the objective of this PR is not to improve the performance, as you can read in the description the objective is to make it more maintenable. I checked the perf in a Linux, a Windows and a docker, and I'm not able to reproduce the -5%. If you provide me a way to reproduce it I will put my hands on it! :)

Also, the final target of this PR is, perhaps in the future, add more usable formats (%u, %o, %x, %X, %e and %E) without having duplicated code go total nightmare.

@benjamingr
Copy link
Member

@mscdex

@benjamingr I wouldn't say it's not in a "hot path." I would bet at least logging modules and such make use of it.

I was under the impression logging modules are never in hot paths anyway - but I'm ready to be educated :)

@mscdex
Copy link
Contributor

mscdex commented Apr 14, 2017

@benjamingr Obviously it depends on the application. It could easily be a bigger issue when you enable extensive debugging in your application in production (even temporarily). You could make a similar argument for other node core modules/functions that may/may not be directly used by core itself (e.g. querystring or url) but are used extensively in userland.

@jseijas Here's what I used:

node benchmark/compare.js --new ./node --old ./node-master --filter format.js --set n=10000000 --set type=unknown --set type=number --set type=object --set type=string util | Rscript benchmark/compare.R

Where ./node is a node master binary with the changes from this PR and node-master is current master without these changes. You will need R installed.

Improved performance
@jseijas
Copy link
Author

jseijas commented Apr 15, 2017

@mscdex Changed the way of doing the refactor. With the new way:

                                           improvement confidence      p.value
 util/format.js type="number" n=10000000      15.02 %        *** 3.135523e-13
 util/format.js type="object" n=10000000      -4.93 %        *** 2.037599e-31
 util/format.js type="string" n=10000000      14.36 %        *** 1.535491e-23
 util/format.js type="unknown" n=10000000      6.60 %        *** 1.233373e-30

I don't understand why for %j the performance is decreased. But also while refactoring I found some odd behaviours with the performance, example: if (f.charCodeAt(i+1) === 37 || a < argLen) if I swap the order of the conditions then the performance is decreased.

@mscdex
Copy link
Contributor

mscdex commented Apr 15, 2017

@jseijas It's hard to say why offhand without running the benchmark with type=object through irhydra2 to see what V8 is doing compared to the other types.

I would expect it to be somewhat slower (but not necessarily a regression) because the object type case is farther down in the switch and V8 matches each in order.

@vsemozhetbyt
Copy link
Contributor

lib/util.js Outdated
str += '%';
lastPos = i = i + 2;
continue;
if (f.charCodeAt(i+1) === 37 || a < argLen) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Linter: Infix operators must be spaced

Fix lint error: Infix operators must be spaced
@benjamingr
Copy link
Member

@mscdex

Obviously it depends on the application. It could easily be a bigger issue when you enable extensive debugging in your application in production (even temporarily).

I don't know - I just want to see a case where the performance is meaningful in util.format. Even a single telemetry tool that logs requests and uses util.format would convince me. I admit I have far less experience with these sort of workloads though.

You could make a similar argument for other node core modules/functions that may/may not be directly used by core itself (e.g. querystring or url) but are used extensively in userland.

I might be seeing this the wrong way - but util.format is a debugging utility whereas the querystring/url modules are typically used per request in every request in most http servers I've seen.

@jseijas

if (f.charCodeAt(i+1) === 37 || a < argLen) if I swap the order of the conditions then the performance is decreased.

charCodeAt is special and optimized to a simple value check. Remember that in == when the first condition is true it can skip the other condition. In this case it is possible the left hand side is true a lot more often then the right hand side in the benchmark and a conditional check is saved - even if the JIT is being stupid.

Of course, a faster implementation would parse the format string once and then compile it to a function with Function and store it in a cache (so the parsing only happens once in the first util.inspect call with the format string) and then subsequent calls don't need to do any parsing. This is what templating engines typically do - but I doubt it's worth it since I'm still not convinced performance matters here.

@vsemozhetbyt
Copy link
Contributor

@jseijas
Copy link
Author

jseijas commented Apr 15, 2017

@benjamingr Well, I just was doing several changes and learning how they affect to the performance. I'm with you, I never considered util.format as critical, I consider it more like an utility, and I think that could be interesting to evolve it to take into account the different formats of "printf". I think that can be interesting to have at least %e and %x provided by the core, without installing any other package. Even more interesting to have things like "%8.2f", but in this case a deeper modification of the function is needed.

But if we think "ok, it's critical, we are using it for the logs of the app", then we can see that we got it improved a 15% for numbers and strings (the usual case of logs). For those that wants to stringify objects inside the messages, we are talking of a -5% performance, in my laptop it means 0.0001ms per message... then I have to store this log, so I don't think that this time is really relevant if we consider the I/O operation for storing. We can consider it relevant if our system is storing huge amounts of logs per second, but in this case I think there are a bunch of problems at architecture level of the app before even looking to this 5%.

But well, is my point of view ^^

@evanlucas
Copy link
Contributor

I would prefer we not knowingly allow a performance regression to util.format(). It is used in things like debug (which is used in various places throughout the ecosystem). If we can make this have at least the same performance, then +1.

@jseijas
Copy link
Author

jseijas commented Apr 16, 2017

Ok, I changed the code to focus on performance. Is still more readable than the original one, but now the performance is:

                                           improvement confidence      p.value
 util/format.js type="number" n=10000000       8.08 %        *** 1.032080e-10
 util/format.js type="object" n=10000000       8.37 %        *** 6.609044e-38
 util/format.js type="string" n=10000000       4.28 %        *** 6.155360e-08
 util/format.js type="unknown" n=10000000      4.08 %        *** 5.374915e-20

So we have more readable code, and with better performance. Yay!

Even with that, I'm not happy. I want to say:

  1. If we consider it critical because is used to log, then we should measure the performance using the console.log(util.format(...)). A 5% of performance in util.format() means a 0.3% over console.log(util.format()).

  2. The problem with performance at this granularity level is that something so simple as creating a variable has an impact in the performance, because we are measuring a very small process that is pretty fast. Several examples at this code:

  • I removed the variable argLen, because the code is faster;
  • At the line if (f.charCodeAt(i + 1) !== 37 && a >= arguments.length), if you swap the parameters, you have a ~5% less performance
  • If you look at each case of the switch you'll see the same repeated code: if (i > lastPos) str += f.slice(lastPos, i);. If this code is extracted out of the switch to avoid repeating it, you get a -10% penalization in the %j. This is a bit weird.
  1. Forgive me Robert Cecil Martin, because I have sinned.

@jseijas
Copy link
Author

jseijas commented Apr 16, 2017

One thing that I don't understand:

There is a real problem with the no-replace performance, and is due to the fact that the behaviour of util.format(1,2) is totally different from util.format('', 1, 2), even returning the same result. If we take a look into the code the first is resolved with

  const objects = new Array(arguments.length);
    for (var index = 0; index < arguments.length; index++) {
      objects[index] = inspect(arguments[index]);
    }
    return objects.join(' ');

and the second one with:

  while (a < argLen) {
    const x = arguments[a++];
    if (x === null || (typeof x !== 'object' && typeof x !== 'symbol')) {
      str += ' ' + x;
    } else {
      str += ' ' + inspect(x);
    }
  }

Where we see that the inspect is only called when the object is not null, and is an object or symbol, so no inspect will be called for strings or numbers.

That's the reason why no-replace benchmark takes so much time compared with the other options.

Replacing the first part of the util.format with this:

  var a = 0;
  var str = '';
  if (typeof f !== 'string') {
    while (a < arguments.length) {
      if (a > 0) 
        str += ' ';
      const x = arguments[a++];
      if (x === null || (typeof x !== 'object' && typeof x !== 'symbol')) {
        str += x;
      } else {
        str += inspect(x);
      }
    }
    return str;
  }

then we get this benchmark result for no-replace:

                                           improvement confidence      p.value
util/format.js type="no-replace" n=1000000  16651.20 %        *** 1.225682e-52

@mscdex Is this fix good, or it something that I'm not taking into account and there is a good reason for doing inspect for all the parameters only at the no-replace part? I think that the differences should be the stylize, the "-0" case, and the replacements done in strings. But if we are defending that util.format is a so critical part, then performance should go before beauty. And we are talking about 16651% of performance.

@aqrln
Copy link
Contributor

aqrln commented Apr 16, 2017

@refack
Copy link
Contributor

refack commented Apr 16, 2017

[Silly comment] how about adding util.formatEx for more formats, with the implicit assumption it will be less performant than util.format?
@jseijas does that make sense code-reuse-wise?

@mscdex
Copy link
Contributor

mscdex commented Apr 16, 2017

@jseijas I think backwards compatibility should be preferred since then more branches can receive at least some amount of increased performance, but if backwards compatibility can't be met and you feel the performance improvement is great enough and is worth marking as semver-major, then so be it.

@refack I don't think getting into that kind of habit with the node API is a good goal. If anything it's usually a sign that the changes should just go into a userland module instead.

@jseijas
Copy link
Author

jseijas commented Apr 16, 2017

@mscdex Ok, then I'll make this change ina new PR, if this one is merged, because currently this one has not backwards impact. And also are different topics. To give more information about how critical is the impact that this have, running console.log(util.format(1,2,3,4)); 1M times, takes 109664ms with the current master, and 44367ms after patching this code, generating exactly the same log. This means that currently the util.format is taking more time than the I/O operation.

@jasnell
Copy link
Member

jasnell commented Apr 17, 2017

LGTM but I'd like @mscdex to sign off before it lands

Copy link
Member

@addaleax addaleax left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fresh CI: https://ci.nodejs.org/job/node-test-commit/9516/

I’m good with landing this as it is once CI comes back good.

@addaleax addaleax requested a review from mscdex April 30, 2017 00:02
@jseijas
Copy link
Author

jseijas commented May 23, 2017

Hi @mscdex! Do you need more changes to be made, or you are ok with this? Or any other suggestion.

lib/util.js Outdated

var str = '';
var a = 1;
var lastPos = 0;
for (var i = 0; i < f.length;) {
if (f.charCodeAt(i) === 37/*'%'*/ && i + 1 < f.length) {
if (f.charCodeAt(i) === 37/*'%'*/ && f.length > i + 1) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think having the "static" portion on the right-hand side is more traditional.

lib/util.js Outdated

var str = '';
var a = 1;
var lastPos = 0;
for (var i = 0; i < f.length;) {
if (f.charCodeAt(i) === 37/*'%'*/ && i + 1 < f.length) {
if (f.charCodeAt(i) === 37/*'%'*/ && f.length > i + 1) {
if (f.charCodeAt(i + 1) !== 37 && a >= arguments.length) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The /*'%'*/ is missing here for consistency.

lib/util.js Outdated
@@ -143,7 +131,6 @@ exports.format = function(f) {
return str;
};


Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unintended whitespace change?

lib/util.js Outdated
switch (f.charCodeAt(i + 1)) {
case 100: // 'd'
if (a >= argLen)
break;
if (lastPos < i)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I prefer this style because lastPos will always be either less than or equal to i.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry, I didn't understand this point. You meain only remain lastPos < i instead of i > lastPos ? Thank you!

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I mean I prefer lastPos < i

- Correct whitespace
- Static parts of if before unstatic.
@jseijas
Copy link
Author

jseijas commented May 31, 2017

@mscdex Changes done!

@jseijas
Copy link
Author

jseijas commented May 31, 2017

After rebase:

                                           improvement confidence      p.value
 util/format.js type="number" n=10000000       6.58 %        *** 5.428519e-11
 util/format.js type="object" n=10000000       0.18 %            6.416948e-01
 util/format.js type="string" n=10000000      10.19 %        *** 3.134553e-23
 util/format.js type="unknown" n=10000000      9.45 %        *** 6.444361e-28

@silverwind
Copy link
Contributor

@mscdex
Copy link
Contributor

mscdex commented Jun 1, 2017

LGTM

@silverwind
Copy link
Contributor

Thanks! Landed in 4191962.

@silverwind silverwind closed this Jun 2, 2017
silverwind pushed a commit that referenced this pull request Jun 2, 2017
Method format refactored to make it more maintenable, replacing the
switch by a function factory, that returns the appropiated function
given the character (d, i , f, j, s).

Also, performance when formatting an string that contains several
consecutive % symbols is improved. The test:
`const numSamples = 10000000;
const strPercents = '%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%s%%%%%%%%%%%%%%%%%i%%%%%%%%%%%%%%%%%%%%%%%%%%';
var s;
console.time('Percents');
for (let i = 0; i < numSamples; i++) {
  s = util.format(strPercents, 'test', 12);
}
console.timeEnd('Percents');`

Original time:   28399.708ms
After refactor:  23763.788ms
Improved: 16%

PR-URL: #12407
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Roman Reiss <me@silverwind.io>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Brian White <mscdex@mscdex.net>
jasnell pushed a commit that referenced this pull request Jun 5, 2017
Method format refactored to make it more maintenable, replacing the
switch by a function factory, that returns the appropiated function
given the character (d, i , f, j, s).

Also, performance when formatting an string that contains several
consecutive % symbols is improved. The test:
`const numSamples = 10000000;
const strPercents = '%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%s%%%%%%%%%%%%%%%%%i%%%%%%%%%%%%%%%%%%%%%%%%%%';
var s;
console.time('Percents');
for (let i = 0; i < numSamples; i++) {
  s = util.format(strPercents, 'test', 12);
}
console.timeEnd('Percents');`

Original time:   28399.708ms
After refactor:  23763.788ms
Improved: 16%

PR-URL: #12407
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Roman Reiss <me@silverwind.io>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Brian White <mscdex@mscdex.net>
@jasnell jasnell mentioned this pull request Jun 5, 2017
@mscdex mscdex added the semver-major PRs that contain breaking changes and should be released in the next major version. label Jun 13, 2017
@mscdex
Copy link
Contributor

mscdex commented Jun 13, 2017

FWIW it looks like this could be causing issues due to the change in behavior (see #13665), so I've marked this as semver-major now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
semver-major PRs that contain breaking changes and should be released in the next major version. util Issues and PRs related to the built-in util module.
Projects
None yet
Development

Successfully merging this pull request may close these issues.