naugtur / blocked-at Goto Github PK
View Code? Open in Web Editor NEWDetects node eventloop block and reports where it started
License: MIT License
Detects node eventloop block and reports where it started
License: MIT License
Hi,
I am trying to implement this but getting an error. Not sure why
index.js in the server app
const blocked = require('blocked-at');
let result = [];
const { stop } = blocked((time, stack) => {
result = result.concat(stack)
console.log('blocked', time, stack);
});
getting the following error when i run the server locally
TypeError: Cannot set property 't0' of undefined
at AsyncHook.before (/Users/developer/Syook/syook-tnt-server/node_modules/blocked-at/index.js:30:27)
at emitBeforeNative (async_hooks.js:343:40)
at emitBeforeScript (async_hooks.js:378:5)
at process._tickDomainCallback (internal/process/next_tick.js:209:9)
at Function.Module.runMain (module.js:611:11)
at startup (bootstrap_node.js:158:16)
at bootstrap_node.js:598:3
node 10 will remove it entirely, so this library will cease to work. doubt they will change their mind at this point.
This library is not exactly what async hooks were designed for. While it's working for a few cases I investigated, there might be some edge cases out there. The worst case scenario being a false positive, where it'd report a function that's not blocking the event loop.
This needs some investigation.
If you're using this library, feel free to discuss examples of functions it detected.
Whenever I start the process, it triggers hundreds of errors, all nearly identical to the following:
7/12/2020, 12:49:30 AM [WARN] Blocked (51.30170703125ms) [
' at link (internal/modules/esm/module_job.js:42:32)',
' at new ModuleJob (internal/modules/esm/module_job.js:63:19)',
' at Loader.getModuleJob (internal/modules/esm/loader.js:242:11)'
]
It seems that blocked-at won't report blocking due to garbage collection. For example, I have the following in my code:
var beg = Date.now();
global.gc();
console.log(Date.now()-beg)
Which in my (crazy) case reports 200ms, but blocked-at seems silent about... Could I be misunderstanding something or is this a real deficiency?
Not sure what sort of information you would like, but right after it catches the first block, the application seems to hang
The LICENSE file states MIT, while package.json
declares "ISC". This confuses license-checking tools like license-checker.
Hi there,
first off, thank you for this package, it's come in handy several times and always does a great job.
Documentation, however, could be expanded, and I have a question regarding its use in an ExpressJs middleware.
I would like to use "blocked" to investigate the cause of some timeouts we are experiencing in a controller.
I was wondering if I could do something like:
import { Request, Response, NextFunction } from 'express';
import * as blocked from 'blocked-at';
export default (_req: Request, _res: Response, next: NextFunction): void => {
blocked(
(time: any, stack: any) => {
console.log(`Blocked for ${time}ms, operation started here:`, { stack });
},
{ threshold: 1000 },
);
next();
};
import { Router } from 'express';
import * as RestController from '.';
import ApiKeyAuth from '../../authorization/api-key-auth';
import blocked from '../../middleware/blocked';
router.post('/users', ApiKeyAuth, blocked, RestController.createUser);
I am testing this out with jMeter right now, and I have contrasting feelings on the effectiveness, what are your thoughts on this?
Using this method to monitor event loop lag causes additional load to memory and CPU in my case this was about ~15%.
I started with a rather large threshold value five seconds, could that cause just filling the cache map with stack traces and now cleaning up that fast https://github.com/naugtur/blocked-at/blob/master/index.js#L4L4 ?
Hey, I noticed that all my stack traces start with AsyncHook.init so I looked at the source code and the following regex:
const asyncHooksRegEx = /\((internal\/)?async_hooks\.js:/
at index.js:7
doesn't match my stack trace. In my stack traces there is no .js
extension for the async_hooks calls.
let result = [];
blocked((time, stack) => {
result = result.concat(stack);
console.log('engine.js blocked', time, stack);
}, { threshold: 20 });
engine.js blocked 23.87353503417969 [ ' at process.nextTick (internal/process/next_tick.js:270:7)',
' at handleOperationCallback (/home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/pool.js:468:24)',
' at /home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/pool.js:504:9',
' at authenticateStragglers (/home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/pool.js:443:16)',
' at Connection.messageHandler (/home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/pool.js:477:5)',
' at Socket.<anonymous> (/home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/connection.js:331:22)',
' at emitOne (events.js:115:13)',
' at Socket.emit (events.js:210:7)',
' at addChunk (_stream_readable.js:266:12)',
' at readableAddChunk (_stream_readable.js:253:11)',
' at Socket.Readable.push (_stream_readable.js:211:10)',
' at TCP.onread (net.js:585:20)' ]
engine.js blocked 24.23693408203125 [ ' at process.nextTick (internal/process/next_tick.js:270:7)',
' at handleOperationCallback (/home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/pool.js:468:24)',
' at /home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/pool.js:504:9',
' at authenticateStragglers (/home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/pool.js:443:16)',
' at Connection.messageHandler (/home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/pool.js:477:5)',
' at Socket.<anonymous> (/home/deploy/apps/syook-tnt-server/node_modules/mongodb-core/lib/connection/connection.js:331:22)',
' at emitOne (events.js:115:13)',
' at Socket.emit (events.js:210:7)',
' at addChunk (_stream_readable.js:266:12)',
' at readableAddChunk (_stream_readable.js:253:11)',
' at Socket.Readable.push (_stream_readable.js:211:10)',
' at TCP.onread (net.js:585:20)' ]
engine.js blocked 24.492054931640624 [ ' at internalConnect (net.js:939:26)',
' at GetAddrInfoReqWrap.emitLookup [as callback] (net.js:1098:7)',
' at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:98:10)' ]
engine.js blocked 24.613239013671876 [ ' at internalConnect (net.js:939:26)',
' at GetAddrInfoReqWrap.emitLookup [as callback] (net.js:1098:7)',
' at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:98:10)' ]
setTCPConnection true
new client connection from ::ffff:43.228.229.58:38268
connection data from ::ffff:43.228.229.58:38268: "|2017-09-23 16:09:40,D4:22:01:00:03:FD,01,001,00,-69,100,|2017-09-23 16:09:40,D4:22:01:00:03:F7,01,003,00,-88,100,|2017-09-23 16:09:40,D4:22:01:00:03:F3,02,001,00,-98,100,003,00,-88,100,|2017-09-23 16:09:40,D4:22:01:00:03:FC,02,001,00,-78,100,003,00,-94,100,|2017-09-23 16:09:40,D4:22:01:00:03:F2,01,003,00,-70,100,|2017-09-23 16:09:40,D4:22:01:00:03:F4,02,001,00,-89,100,003,00,-88,100,|2017-09-23 16:09:40,D4:22:01:00:03:F6,02,001,00,-87,100,003,00,-88,100,|2017-09-23 16:09:40,D4:22:01:00:03:FF,01,001,00,-47,100,|2017-09-23 16:09:40,D4:22:01:00:03:EB,01,001,00,-49,100,|2017-09-23 16:09:40,D4:22:01:00:03:EA,01,001,00,-58,100,|2017-09-23 16:09:40,D4:22:01:00:03:FA,01,001,00,-64,100,|2017-09-23 16:09:40,D4:22:01:00:03:E9,01,001,00,-49,100,|2017-09-23 16:09:40,D4:22:01:00:03:ED,01,001,00,-79,100,|2017-09-23 16:09:40,D4:22:01:00:03:EE,01,001,00,-79,100,|2017-09-23 16:09:40,D4:22:01:00:03:F9,01,001,00,-58,100,|2017-09-23 16:09:40,D4:22:01:00:04:00,01,001,00,-77,100,|2017-09-23 16:09:40,D4:22:01:00:03:F0,01,001,00,-59,100,"
data contains gatewayHandshakeMsg false
mode = IDLE
info: [Stream Log] D4:22:01:00:03:FD reader pings 001 00 -69 100
info: [Stream Log] D4:22:01:00:03:F7 reader pings 003 00 -88 100
info: [Stream Log] D4:22:01:00:03:F3 reader pings 001 00 -98 100
info: [Stream Log] D4:22:01:00:03:F3 reader pings 003 00 -88 100
info: [Stream Log] D4:22:01:00:03:FC reader pings 001 00 -78 100
info: [Stream Log] D4:22:01:00:03:FC reader pings 003 00 -94 100
info: [Stream Log] D4:22:01:00:03:F2 reader pings 003 00 -70 100
info: [Stream Log] D4:22:01:00:03:F4 reader pings 001 00 -89 100
info: [Stream Log] D4:22:01:00:03:F4 reader pings 003 00 -88 100
info: [Stream Log] D4:22:01:00:03:F6 reader pings 001 00 -87 100
info: [Stream Log] D4:22:01:00:03:F6 reader pings 003 00 -88 100
info: [Stream Log] D4:22:01:00:03:FF reader pings 001 00 -47 100
info: [Stream Log] D4:22:01:00:03:EB reader pings 001 00 -49 100
info: [Stream Log] D4:22:01:00:03:EA reader pings 001 00 -58 100
info: [Stream Log] D4:22:01:00:03:FA reader pings 001 00 -64 100
info: [Stream Log] D4:22:01:00:03:E9 reader pings 001 00 -49 100
info: [Stream Log] D4:22:01:00:03:ED reader pings 001 00 -79 100
info: [Stream Log] D4:22:01:00:03:EE reader pings 001 00 -79 100
info: [Stream Log] D4:22:01:00:03:F9 reader pings 001 00 -58 100
info: [Stream Log] D4:22:01:00:04:00 reader pings 001 00 -77 100
info: [Stream Log] D4:22:01:00:03:F0 reader pings 001 00 -59 100
TypeError: Cannot read property 'includes' of undefined
at cleanStack (/home/deploy/apps/syook-tnt-server/node_modules/blocked-at/index.js:9:38)
at AsyncHook.after (/home/deploy/apps/syook-tnt-server/node_modules/blocked-at/index.js:42:28)
at emitAfterNative (async_hooks.js:375:40)
Sorry the error was on my part, feel free to delete this
npm test fails. Looking a bit closer, .\test\index.js is the failing component (not .\test\runtime.js, which I ran on its own & it passed).
PS C:\Working\blocked-at> node .\test\index.js
slow: 99.777ms
slow: 99.666ms
101.79732501220703 [ ' at new Immediate (timers.js:816:5)',
' at createImmediate (timers.js:858:19)',
' at setImmediate (timers.js:845:10)',
' at Object.<anonymous> (C:\\Working\\blocked-at\\test\\index.js:17:1)',
' at Module._compile (module.js:635:30)',
' at Object.Module._extensions..js (module.js:646:10)',
' at Module.load (module.js:554:32)',
' at tryModuleLoad (module.js:497:12)',
' at Function.Module._load (module.js:489:3)',
' at Function.Module.runMain (module.js:676:10)',
' at startup (bootstrap_node.js:187:16)',
' at bootstrap_node.js:608:3' ]
101.19250700378419 [ ' at Promise.then (<anonymous>)',
' at Immediate.start (C:\\Working\\blocked-at\\test\\cases\\promise.js:9:6)',
' at runCallback (timers.js:789:20)',
' at tryOnImmediate (timers.js:751:5)',
' at processImmediate [as _immediateCallback] (timers.js:722:5)' ]
318.04360400390624 [ ' at Object.lookup (dns.js:182:19)',
' at lookupAndListen (net.js:1496:7)',
' at Server.listen (net.js:1472:7)',
' at Immediate.start (C:\\Working\\blocked-at\\test\\cases\\http.js:11:10)',
' at runCallback (timers.js:789:20)',
' at tryOnImmediate (timers.js:751:5)',
' at processImmediate [as _immediateCallback] (timers.js:722:5)' ]
slow: 99.807ms
100.34066600036621 [ ' at Object.fs.read (fs.js:664:11)',
' at C:\\Working\\blocked-at\\test\\cases\\example.js:20:10',
' at FSReqWrap.oncomplete (fs.js:135:15)' ]
slow: 99.063ms
102.48495599365235 [ ' at Server.connectionListener (_http_server.js:309:10)',
' at emitOne (events.js:116:13)',
' at Server.emit (events.js:211:7)',
' at TCP.onconnection (net.js:1561:8)' ]
slow: 99.716ms
100.05577499389648 [ ' at new Immediate (timers.js:816:5)',
' at createImmediate (timers.js:858:19)',
' at setImmediate (timers.js:845:10)',
' at Immediate.recursive (C:\\Working\\blocked-at\\test\\cases\\recursive.js:6:5)',
' at runCallback (timers.js:791:20)',
' at tryOnImmediate (timers.js:751:5)',
' at processImmediate [as _immediateCallback] (timers.js:722:5)' ]
assert.js:42
throw new errors.AssertionError({
^
AssertionError [ERR_ASSERTION]: Expected test/index.js:17 in stack trace
at Timeout._ [as _onTimeout] (C:\Working\blocked-at\test\index.js:28:3)
at ontimeout (timers.js:475:11)
at tryOnTimeout (timers.js:310:5)
at Timer.listOnTimeout (timers.js:270:5)
PS C:\Working\blocked-at> git rev-parse HEAD
b5751e1fe465de0dfd43de19d42be3c82ed96d8a
PS C:\Working\blocked-at> git describe HEAD
v1.1.2
PS C:\Working\blocked-at> node --version
v8.9.1
PS C:\Working\blocked-at>
I did some independent testing and confirmed we are having the same performance issues as described in this post. Our CPU utilization spiked to 100% and the node fell over when I tried to use this to find blocking stack traces from a dev envionrment.
https://www.ashbyhq.com/blog/engineering/detecting-event-loop-blockers
I was running node:18.18.1-alpine in k8s with express 4.17.3
To see what happens to your code in Node.js 10, Greenkeeper has created a branch with the following changes:
.travis.yml
If you’re interested in upgrading this repo to Node.js 10, you can open a PR with these changes. Please note that this issue is just intended as a friendly reminder and the PR as a possible starting point for getting your code running on Node.js 10.
Greenkeeper has checked the engines
key in any package.json
file, the .nvmrc
file, and the .travis.yml
file, if present.
engines
was only updated if it defined a single version, not a range..nvmrc
was updated to Node.js 10.travis.yml
was only changed if there was a root-level node_js
that didn’t already include Node.js 10, such as node
or lts/*
. In this case, the new version was appended to the list. We didn’t touch job or matrix configurations because these tend to be quite specific and complex, and it’s difficult to infer what the intentions were.For many simpler .travis.yml
configurations, this PR should suffice as-is, but depending on what you’re doing it may require additional work or may not be applicable at all. We’re also aware that you may have good reasons to not update to Node.js 10, which is why this was sent as an issue and not a pull request. Feel free to delete it without comment, I’m a humble robot and won’t feel rejected 🤖
There is a collection of frequently asked questions. If those don’t help, you can always ask the humans behind Greenkeeper.
Your Greenkeeper Bot 🌴
Blocked for 2928.1773420104983ms:
at Function.runHooks (~/Projects/staeco/node_modules/sequelize/lib/hooks.js:116:20)
at InstanceValidator._validateAndRunHooks (~/Projects/staeco/node_modules/sequelize/lib/instance-validator.js:108:12)
at InstanceValidator.validate (~/Projects/staeco/node_modules/sequelize/lib/instance-validator.js:93:38)
at model.validate (~/Projects/staeco/node_modules/sequelize/lib/model.js:3733:49)
at Promise.try (~/Projects/staeco/node_modules/sequelize/lib/model.js:3510:21)
at model.save (~/Projects/staeco/node_modules/sequelize/lib/model.js:3507:23)
at model.update (~/Projects/staeco/node_modules/sequelize/lib/model.js:3767:17)
at ~/Projects/staeco/server/endpoints/importer/job/updateById.js:34:14
at Generator.next (<anonymous>)
at step (~/Projects/staeco/server/endpoints/importer/job/updateById.js:16:191)
at ~/Projects/staeco/server/endpoints/importer/job/updateById.js:16:361
at <anonymous>
<--- Last few GCs --->
[729:0x102802200] 2320969 ms: Mark-sweep 1518.7 (2703.1) -> 1518.0 (2703.1) MB, 386.3 / 0.0 ms allocation failure GC in old space requested
[729:0x102802200] 2321334 ms: Mark-sweep 1518.0 (2703.1) -> 1517.9 (2657.1) MB, 364.9 / 0.0 ms last resort
[729:0x102802200] 2321698 ms: Mark-sweep 1517.9 (2657.1) -> 1517.9 (2652.1) MB, 364.2 / 0.0 ms last resort
<--- JS stacktrace --->
==== JS stack trace =========================================
Security context: 0x11b70a71cef1 <JSObject>
0: builtin exit frame: Function(aka Function)(this=0x11b70a702241 <undefined>,0xc57a3ffd2b1 <Very long string[3348]>,0x34426c74e3f1 <String[7]: rowData>,0x2ec7a023ad39 <String[7]: parsers>)
2: addFields [/Users/contra/Projects/staeco/node_modules/pg/lib/result.js:110] [bytecode=0x383cc25ff129 offset=180](this=0x3e19048f5ee1 <Result map = 0x3932693dff81>,fieldDescriptions=0x37c73025c619 ...
FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
1: node::Abort() [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
2: node::FatalException(v8::Isolate*, v8::Local<v8::Value>, v8::Local<v8::Message>) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
3: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
4: v8::internal::Factory::NewFixedArray(int, v8::internal::PretenureFlag) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
5: v8::internal::HashTable<v8::internal::StringTable, v8::internal::StringTableShape, v8::internal::HashTableKey*>::EnsureCapacity(v8::internal::Handle<v8::internal::StringTable>, int, v8::internal::HashTableKey*, v8::internal::PretenureFlag) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
6: v8::internal::StringTable::LookupKey(v8::internal::Isolate*, v8::internal::HashTableKey*) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
7: v8::internal::AstValueFactory::Internalize(v8::internal::Isolate*) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
8: v8::internal::parsing::ParseProgram(v8::internal::ParseInfo*, v8::internal::Isolate*, bool) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
9: v8::internal::(anonymous namespace)::CompileToplevel(v8::internal::CompilationInfo*) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
10: v8::internal::Compiler::GetFunctionFromEval(v8::internal::Handle<v8::internal::String>, v8::internal::Handle<v8::internal::SharedFunctionInfo>, v8::internal::Handle<v8::internal::Context>, v8::internal::LanguageMode, v8::internal::ParseRestriction, int, int, int, int, int, v8::internal::Handle<v8::internal::Object>, v8::ScriptOriginOptions) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
11: v8::internal::Compiler::GetFunctionFromString(v8::internal::Handle<v8::internal::Context>, v8::internal::Handle<v8::internal::String>, v8::internal::ParseRestriction, int) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
12: v8::internal::(anonymous namespace)::CreateDynamicFunction(v8::internal::Isolate*, v8::internal::BuiltinArguments, char const*) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
13: v8::internal::Builtin_FunctionConstructor(int, v8::internal::Object**, v8::internal::Isolate*) [/Users/contra/.nvm/versions/node/v8.4.0/bin/node]
14: 0x14d94aabc8dd
commenting out the code gets rid of the issue, so i'm 100% sure its coming from blocked-at.
code:
import blocked from 'blocked-at'
import cleanStack from 'clean-stack'
import createLogger from 'lib/log'
// debug event loop blocks
const debug = createLogger({ name: 'server:event-loop' })
if (process.env.NODE_ENV === 'development') {
blocked((time, stack) => {
if (time < 500) return
// filter out worthless bluebird stuff
const filtered = stack.filter((msg) => msg.indexOf('node_modules/bluebird') === -1)
if (filtered.length === 0) return
// filter out more worthless crap
const nstack = cleanStack(filtered.join('\n'), { pretty: true })
if (nstack.length === 0) return
const msg = `Blocked for ${time}ms:\n${nstack}`
if (time > 10000) return debug.error(msg)
if (time > 1000) return debug.warn(msg)
debug(msg)
})
}
Hi,
If you're using this library, post links to stacktraces here. The more examples we have, the better!
I am surprised to see that fs.exists() blocks. Please clarify. Thanks
blocked-at V1.1.2
Node JS V8.9.4
[2018/07/03 11:25:45.933] [INFO] { blockedFor: 1054.224799987793,
stack:
[ ' at Object.fs.exists (fs.js:310:11)',
' at getXYZ (C:\dev\prj1\routes\XYZ.js:122:10)',
' at h.XYZ (C:\dev\prj1\routes\XYZ.js:69:37)',
' at Layer.handle [as handle_request] (C:\dev\prj1\node_modules\express\lib\router\layer.js:95:5)',
' at trim_prefix (C:\dev\prj1\node_modules\express\lib\router\index.js:312:13)',
' at C:\dev\prj1\node_modules\express\lib\router\index.js:280:7',
' at Function.process_params (C:\dev\prj1\node_modules\express\lib\router\index.js:330:12)',
' at next (C:\dev\prj1\node_modules\express\lib\router\index.js:271:10)',
' at SendStream.error (C:\dev\prj1\node_modules\serve-static\index.js:121:7)',
' at emitOne (events.js:116:13)',
' at SendStream.emit (events.js:211:7)',
' at SendStream.error (C:\dev\prj1\node_modules\send\index.js:275:17)',
' at SendStream.onStatError (C:\dev\prj1\node_modules\send\index.js:392:12)',
' at onstat (C:\dev\prj1\node_modules\send\index.js:674:26)',
' at FSReqWrap.oncomplete (fs.js:152:21)' ] }
A declarative, efficient, and flexible JavaScript library for building user interfaces.
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
An Open Source Machine Learning Framework for Everyone
The Web framework for perfectionists with deadlines.
A PHP framework for web artisans
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
Some thing interesting about web. New door for the world.
A server is a program made to process requests and deliver data to clients.
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
Some thing interesting about visualization, use data art
Some thing interesting about game, make everyone happy.
We are working to build community through open source technology. NB: members must have two-factor auth.
Open source projects and samples from Microsoft.
Google ❤️ Open Source for everyone.
Alibaba Open Source for everyone
Data-Driven Documents codes.
China tencent open source team.