-
Notifications
You must be signed in to change notification settings - Fork 853
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
Question: CPU usage overhead vs console.log #1899
Comments
Generating JSON requires slightly more overhead than just strings. Specifically, your long strings must be escaped to be valid JSON. I see more CPU utilization in your graph but I hardly see a reason for extra pods and usage threshold. (If you keep Node.js CPU usage at anything lower than 70-80%, you are wasting a lot of money). |
Thanks for the quick reply! We've got utilization at 60% (I should bump that up), but this service is only asking for .5 CPU, which is why they're now hitting the horizontal autoscaler: If the answer is that this is not unexpected, I'm OK with needing using resources (or tweaking what we currently have to better utilize them) - I was just a bit surprised at how much overhead there was and thought it was worth asking. Thanks again. |
Can you please provide some numbers that show the discrepancy? The graphs are not very helpful. |
Sure! What numbers specifically would be useful? I can't take an actual CPU profile on the production instances, but I can share the numbers that underlie the charts. For this service, the k8s configuration is set to:
From the third chart I posted (which overlaps the instant where we deployed Pino), before Pino we were generally hovering between 4-6 replicas with ~60% of .5 CPU each for a total of 1.2 - 1.4 CPUs used. After the Pino change, we immediately scaled up to our max of 8, and the usage is at 2.5 CPUs. This is more than 60% of our max of 4 CPUs (8 max replicas * .5 CPU), but isn't scaling further because of the cap. I totally get that it's more expensive to use structured logging than a string to stdout, I was just a bit surprised that it's nearly doubling our CPU usage vs somewhere in the 10% overhead range. This isn't causing a noticeable delay in processing, however. I've measured wall time with this: let timeSpent = 0;
setInterval(() => {
console.log(`PINO_PERFORMANCE_PROFILING USE_PINO=[${USE_PINO}] timeSpent=[${timeSpent}]`);
timeSpent = 0;
}, 10_000);
...
const start = performance.now();
if (USE_PINO) {
LOG.debug(...);
} else {
console.log(...);
}
timeSpent += performance.now() - start; The actual time spent in both paths is the same, it's just that one path requires a lot more CPU. |
I'm still not understanding what "a lot more CPU" actually means. Something like: 'use strict'
const pino = require('pino')
const log = pino({ destination: '/dev/null' })
const { PerformanceObserver, performance } = require('node:perf_hooks');
const var1 = 'one'
const var2 = 'two'
const var3 = 'three'
const var4 = 'four'
const obs = new PerformanceObserver((items) => {});
obs.observe({ type: 'measure' });
const cpuMetrics = []
let cpu = process.cpuUsage()
cpuMetrics.push(cpu)
performance.mark('a', { detail: cpu })
for (let i = 0; i < 10_000; i += 1) {
console.log(`SomeString[${var1}][${new Date().toISOString()}][${var2}][${var3}][${var4}]`);
}
cpu = process.cpuUsage(cpu)
cpuMetrics.push(cpu)
performance.mark('b', { detail: cpu })
cpu = process.cpuUsage(cpu)
cpuMetrics.push(cpu)
performance.mark('c', { detail: cpu })
for (let i = 0; i < 10_000; i += 1) {
log.info(`SomeString[${var1}][${new Date().toISOString()}][${var2}][${var3}][${var4}]`)
}
cpu = process.cpuUsage(cpu)
cpuMetrics.push(cpu)
performance.mark('d', { detail: cpu })
performance.measure('console.log', 'a', 'b')
performance.measure('pino.info', 'c', 'd')
setTimeout(() => {
console.log('\n\n\n\n\n')
for (const entry of performance.getEntriesByType('mark')) {
console.log(entry)
}
const time1 = cpuMetrics[1].user - cpuMetrics[0].user
const time2 = cpuMetrics[3].user - cpuMetrics[2].user
console.log(`console.log cpu time: ${time1}µs`)
console.log(`pino.info cpu time: ${time2}µs`)
}, 2_000) Which on my system produces: PerformanceMark {
name: 'a',
entryType: 'mark',
startTime: 124.7484188079834,
duration: 0,
detail: { user: 38019, system: 34800 }
}
PerformanceMark {
name: 'b',
entryType: 'mark',
startTime: 179.44191932678223,
duration: 0,
detail: { user: 50136, system: 7629 }
}
PerformanceMark {
name: 'c',
entryType: 'mark',
startTime: 179.4865436553955,
duration: 0,
detail: { user: 38085, system: 34815 }
}
PerformanceMark {
name: 'd',
entryType: 'mark',
startTime: 194.47896003723145,
duration: 0,
detail: { user: 70935, system: 9116 }
}
console.log cpu time: 12117µs
pino.info cpu time: 32850µs |
I'll wrap the logs with A question from your example: since you're using
|
OK, I've got some updated numbers following the above suggestion achieved with: const USE_PINO = Math.random() > 0.5;
let timeSpentUser = 0;
let timeSpentSystem = 0;
let numCalls = 0;
setInterval(() => {
console.log(
`PINO_PERFORMANCE_PROFILING USE_PINO=[${USE_PINO}] timeSpentSystem=[${timeSpentSystem}] timeSpentUser=[${timeSpentUser}] numCalls=[${numCalls}]`
);
timeSpentUser = 0;
timeSpentSystem = 0;
numCalls = 0;
}, 30_000);
...
function doThing() {
...
const start = process.cpuUsage();
if (USE_PINO) {
LOG.debug(`SomeString[${var1}][${new Date().toISOString()}][${var2}][${var3}][${var4}]`);
} else {
console.log(`SomeString[${var1}][${new Date().toISOString()}][${var2}][${var3}][${var4}]`);
}
const end = process.cpuUsage(start); // tracks delta since we provided start
timeSpentUser += end.user;
timeSpentSystem += end.system;
numCalls++;
...
} Here's a sample of some of the results (sorted for easier scanning). Sometimes user CPU is higher with Pino, sometimes it's lower. The system time however is always quite a bit higher with Pino.
Here are the associated CPU charts for the two nodes Thanks for taking a look at this! I think a likely answer is that this is indeed just unavoidable overhead, but I really appreciate the sanity check. |
My script may not be accurate. I cobbled it together during a short downtime window. |
The overhead is likely the result of the escaping cost of the massive string. If you don’t care about it and you just want a faster console.log, you could use sonic-boom directly. |
This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs. |
Hi - I recently switched some semi-high-frequency logs (~50/second per pod) from
console.log
to Pino and have noticed that it's directly responsible for nearly doubling CPU utilization, which has resulted in the need for extra pods to come online to match our usage thresholds in GKE.I would have expected a small performance penalty, but not nearly 2x. The following two graphs come from pods running the same code, one from each of these two branches (where
USE_PINO
is assigned at random at boot time):where
LOG
is a global defined as(I know the string interpolation is not the best way to do this, but it should be equally bad in either branch)
Is this an expected amount of overhead? I've attempted some local profiling and load testing and am unable to discern the root cause, so wanted to ask if you had any ideas. Thank you!
The text was updated successfully, but these errors were encountered: