naugtur/blocked-at

Detects node eventloop block and reports where it started

blocked-at's Issues

hey, you. Post stacktrace examples

Hi,

If you're using this library, post links to stacktraces here. The more examples we have, the better!

Import triggers false positive

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)'
]

Hangs application after first block

Not sure what sort of information you would like, but right after it catches the first block, the application seems to hang

Additional load caused by library

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 ?

Stack trace is always undefined

Sorry the error was on my part, feel free to delete this

TypeError: Cannot set property 't0' of undefined

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

Doesn't report garbage collector

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?

async hooks deprecated :(

nodejs/node#16972

node 10 will remove it entirely, so this library will cease to work. doubt they will change their mind at this point.

Reports fs.exists() to be blocking with Node V8.x

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)' ] }

Version 10 of node.js has been released

Version 10 of Node.js (code name Dubnium) has been released! 🎊

To see what happens to your code in Node.js 10, Greenkeeper has created a branch with the following changes:

• Added the new Node.js version to your .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.

More information on this issue

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 🤖

---

FAQ and help

There is a collection of frequently asked questions. If those don’t help, you can always ask the humans behind Greenkeeper.

---

Your Greenkeeper Bot 🌴

Use in Express middleware

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:

• create a middleware 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();
};

• and append this to our route handler

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?

Look for potential false-positives

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.

failing test: Expected test/index.js:17 in stack trace

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>

getting OOM errors since using this

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)
  })
}

TypeError: Cannot read property 'includes' of undefined

Node Version - 8.5.0

1. Getting this TypeError when I am running this not sure how and why..?
2. Could you provide some usage examples?
3. Any specific reason as to why the default threshold is set at 20ms?

Code Implementation

let result = [];

blocked((time, stack) => {
  result = result.concat(stack);
  console.log('engine.js blocked', time, stack);
}, { threshold: 20 });

Below is my log when I start my app.

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)

asyncHooksRegEx doesn't match the correct traces

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.