hey, you. Post stacktrace examples #5
Comments
|
Since you've asked for it :-). Just tried this library and got lots of blocked messages in bluebird apparently? I am a bit confused about this.
Another one warning about blocked-at itself:
|
|
The second one may be because of IO on printing the first one. With the first one it's hard to tell. Looks like it could be a false positive. Could you please post these in a gist and link in here? We could discuss in the gist and leave this place for a list of references to examples. |
|
Hmm I use winston for logging. 3150ms seems pretty high for printing a log message too, but it might have been because of too high CPU. Here there are two gists:
By the way I get tons of bluebird stacktraces in my application. |
|
You kinda hijacked this thread to talk about false positives, but that's ok. |
|
Hmm, i have some interesting ones. It often looks like the async_hooks is the cause of the blockage, is that correct? Or am i reading it wrong? |
|
Yup, that makes a lot of sense, as whatever you're doing in async hooks has to be totally synchronous, so even writing a log has to be synchronous. I can't guarantee the blocked time measurements are valid for this case, because blocked-at uses asunc hooks to do the measurements, so it's an unusual situation. Some of the async hooks performance aspects are still being discussed eg. nodejs/diagnostics#248 Measuring async hooks with async hooks doesn't sound reliable, so this could be ignored. But you might need to apply other measurements. Check out if tracing helps |
|
Hi, here would be another example: |
|
Is this really blocking? Blocked for 2849.4091750030516ms, operation started here: [ ' at process.nextTick (internal/process/next_tick.js:270:7)', |
|
@Sebs030 I'm surprised it's blocking on a file upload and even more surprised with your suggested workaround. Await on setImmeeiate shouldn't do anything afaik. What you really need to do is get rid of the body parser middleware, skip all the blob magic and pass req as a stream, which it is, to whatever stream accepting function for uploads. Post to stack overflow and edit your comment with a link if you need more. |
|
@BrandonCopley looks like it shouldn't. Possible explanation is that async hooks are not yet implemented for the asynchronous primitive used here. |
|
I'm getting these locally and on Heroku with node.js v12.8.0. It's an app using express. Any ideas what to make of it? edit: It looks like this means that event loop was blocked while handling an incoming request. |
|
Yes, it looks like it detected a delay on reading the static file content. Which is weird, as it's generally well implemented. Might be a false positive. Have you tried with |
|
Here's a weird one that took 630ms. The resource type is Maybe DNS is getting back an enormous number of records!? (Amaaaazing tool by the way. This is extremely helpful) Update: I think I must have misinterpreted this. Would that mean that the thing that responded to the lookup having completed took that 630ms, not the DNS code itself? |
|
Most precisely, it means the last function you see in the stacktrace contained code that took that 630ms to do something that wasn't visible as a new asynchronous action to async hooks. One of two things is possible - 1. event loop did not continue for 600ms due to emitLookup causing a blocking operation OR 2. something in emitLookup is an async operation but is not yet instrumented. If you have a way to reproduce it predictably, it'd be very interesting to explore. |
|
Here is one that I can't seem to decipher Blocked for 87.84227299499511ms, operation started here: [ |
|
@nmaves this looks fairly normal. You'd get a better hint if you wrapped your code in named functions you pass to then. |
|
Getting a bunch of these: Any idea about what this might imply? |
|
68ms is not a lot. The slowdown was pinned down to a http request handler. |
|
Hey @naugtur . Really appreciate the response! It's true that 68ms "every now and then" is not that bad. However, my server is processing 1000s of requests per second. Throw a few of these in the mix and we have a problem. :) I did a bit of google searching and found your own article with this particular example ( Thanks again! |
|
This thread is not the most comfortable place to dig in further. Mail me :) |
|
It looks like express-hbs using After inspecting this stacktrace with resources, it looks really weird. Because this talks about an fs.readFile(filename, 'utf8', function(err, source) {
if (err) return cb(err);
var template = self.compile(source, filename);
if (options.cache) {
self.cache[filename] = {
source: source,
template: template
};
}
return cb(null, source, template);
});that's the incriminated function. Looks like a pretty common |
|
@DanielVip3 Looks like a false positive at first glance, but it might not be the readFile itself. |
|
Here's one. This is in a web application using Sequelize (which uses Bluebird as its Promise implementation). This comes from a request that led to a db query that returned a sizable result which got stringified and sent out. I was wondering if there'd be blocking and it looks like there is, but from the stack trace I'm not sure where. JSON.stringify definitely blocks, so that's one possibility, but nothing in this stack trace suggests it's the culprit to my eyes. Based on what I've seen, node-mysql2, which Sequelize uses, shouldn't be blocking on parsing the query result from mysql, but I'm not 100% that it's not. I also wondered if GCs could be happening that could look like blocking. |
|
Yeah, this stack is not helpful. I expect bluebird is the reason here. Async hooks sometimes don't work with custom promise libs. If not, I'd like to get more details from this if it reproduces, maybe there's something I can do with stack traces parsing. If you're interested in working on this a bit, get in touch over email and we'll see what I can fix. |
|
Thanks for the response! I upgrade bluebird to latest, now I'm seeing this: The lines from query.js files in mysql2 and sequelize stand out. Type is Immediate and resource is undefined. |
|
To me the top lines stand out because I was supposed to parser them out. Looks like something changed and my code is no longer catching those. Which node version are you on? Also, try with asynchronous stack traces on (it's a command line flag) |
|
I'm on node 12.16.1. I'll give async stack traces a shot. Thanks! |
|
[2024-06-07T15:13:41.679] [ERROR] crtp - Event loop was blockled for 417380.51623339846 ms, operation started here: For me stack trace wasn't exactly correct. The code was hanging on a next line call but stacktrace was pointing to a previous line. |
Hi,
If you're using this library, post links to stacktraces here. The more examples we have, the better!
The text was updated successfully, but these errors were encountered: