nodejs访问redis集群时，在同一秒中超时80毫秒以上的比较多，由于找不到超时原因，现将V8日志下载下来，麻烦各位大神给分析下V8日志中哪些地方造成服务阻塞，从而引起超时。
V8日志： Statistical profiling result from isolate-0x1fc41a0-v8.log, (3888 ticks, 187 unaccounted, 0 excluded). [Unknown]: ticks total nonlib name 187 4.8% [Shared libraries]: ticks total nonlib name 2055 52.9% 0.0% /lib64/libc-2.12.so 1402 36.1% 0.0% /usr/software/node-v6.7.0-linux-x64/bin/node 73 1.9% 0.0% /lib64/libpthread-2.12.so 21 0.5% 0.0% /usr/lib64/libstdc++.so.6.0.13 3 0.1% 0.0% [vdso] 3 0.1% 0.0% /lib64/librt-2.12.so
[JavaScript]: ticks total nonlib name 6 0.2% 1.8% LazyCompile: ~target._send internal/child_process.js:549:26 6 0.2% 1.8% Builtin: CallFunction_ReceiverIsNotNullOrUndefined 4 0.1% 1.2% LazyCompile: ~emit events.js:136:44 4 0.1% 1.2% LazyCompile: ~_tickCallback internal/process/next_tick.js:87:25 4 0.1% 1.2% KeyedStoreIC: A keyed store IC from the snapshot 3 0.1% 0.9% Stub: LoadConstantStub {2} 3 0.1% 0.9% Stub: FastNewClosureStub 3 0.1% 0.9% LazyCompile: ~channel.onread internal/child_process.js:438:28 3 0.1% 0.9% LazyCompile: *get native collection.js:239:16 2 0.1% 0.6% Stub: RecordWriteStub {6} 2 0.1% 0.6% Stub: RecordWriteStub {5} 2 0.1% 0.6% Stub: RecordWriteStub 2 0.1% 0.6% Stub: LoadConstantStub {1} 2 0.1% 0.6% Stub: JSEntryStub 2 0.1% 0.6% Stub: FastNewStrictArgumentsStub 2 0.1% 0.6% Stub: FastNewContextStub 2 0.1% 0.6% Stub: FastNewClosureStub {1} 2 0.1% 0.6% Stub: FastCloneShallowArrayStub 2 0.1% 0.6% Stub: ArraySingleArgumentConstructorStub 2 0.1% 0.6% LazyCompile: ~forEachMimeType /root/blog/node_modules/mime-types/index.js:158:52 2 0.1% 0.6% LazyCompile: ~Module._compile module.js:496:37 2 0.1% 0.6% KeyedLoadIC: A keyed load IC from the snapshot {1} 2 0.1% 0.6% Handler: length 2 0.1% 0.6% Handler: charCodeAt 2 0.1% 0.6% Handler: An IC handler from the snapshot {8} 2 0.1% 0.6% Handler: An IC handler from the snapshot {3} 2 0.1% 0.6% Builtin: Call_ReceiverIsAny 1 0.0% 0.3% Stub: ToStringStub 1 0.0% 0.3% Stub: ToIntegerStub 1 0.0% 0.3% Stub: ToBooleanICStub(Null) 1 0.0% 0.3% Stub: ToBooleanICStub 1 0.0% 0.3% Stub: SubStringStub 1 0.0% 0.3% Stub: StringAddStub_ConvertLeft_NotTenured 1 0.0% 0.3% Stub: StringAddStub_CheckNone_NotTenured 1 0.0% 0.3% Stub: StoreTransitionStub 1 0.0% 0.3% Stub: StoreFieldStub 1 0.0% 0.3% Stub: RecordWriteStub {4} 1 0.0% 0.3% Stub: RecordWriteStub {3} 1 0.0% 0.3% Stub: RecordWriteStub {2} 1 0.0% 0.3% Stub: NonNumberToNumberStub 1 0.0% 0.3% Stub: LoadFieldStub {1} 1 0.0% 0.3% Stub: LoadFieldStub 1 0.0% 0.3% Stub: LoadConstantStub 1 0.0% 0.3% Stub: InstanceOfStub 1 0.0% 0.3% Stub: FastNewObjectStub 1 0.0% 0.3% Stub: FastNewContextStub {1} 1 0.0% 0.3% Stub: FastCloneShallowObjectStub 1 0.0% 0.3% Stub: FastArrayPushStub 1 0.0% 0.3% Stub: CompareICStub {1} 1 0.0% 0.3% Stub: CompareICStub 1 0.0% 0.3% Stub: CallConstructStub 1 0.0% 0.3% Stub: CEntryStub {1} 1 0.0% 0.3% Stub: CEntryStub 1 0.0% 0.3% Stub: BinaryOpICStub 1 0.0% 0.3% Script: ~/root/blog/node_modules/flexbuffer/flexbuffer.js 1 0.0% 0.3% LazyCompile: ~tickDone internal/process/next_tick.js:30:20 1 0.0% 0.3% LazyCompile: ~slowToString buffer.js:413:22 1 0.0% 0.3% LazyCompile: ~set native collection.js:252:16 1 0.0% 0.3% LazyCompile: ~sendHelper cluster.js:743:20 1 0.0% 0.3% LazyCompile: ~resolve path.js:1133:28 1 0.0% 0.3% LazyCompile: ~realpathSync fs.js:1588:40 1 0.0% 0.3% LazyCompile: ~process.nextTick internal/child_process.js:743:20 1 0.0% 0.3% LazyCompile: ~handleMessage internal/child_process.js:731:23 1 0.0% 0.3% LazyCompile: ~get global native regexp.js:808:25 1 0.0% 0.3% LazyCompile: ~forEachCode /root/blog/node_modules/http-errors/index.js:190:38 1 0.0% 0.3% LazyCompile: ~extname path.js:1432:28 1 0.0% 0.3% LazyCompile: ~exec native regexp.js:116:30 1 0.0% 0.3% LazyCompile: ~emitTwo events.js:104:17 1 0.0% 0.3% LazyCompile: ~depd /root/blog/node_modules/depd/index.js:106:14 1 0.0% 0.3% LazyCompile: ~debug /root/blog/node_modules/debug/debug.js:62:15 1 0.0% 0.3% LazyCompile: ~NativeModule.exists bootstrap_node.js:447:33 1 0.0% 0.3% LazyCompile: ~Module._nodeModulePaths module.js:259:37 1 0.0% 0.3% LazyCompile: ~Module._findPath module.js:137:28 1 0.0% 0.3% LazyCompile: ~Deque /root/blog/node_modules/double-ended-queue/js/deque.js:23:15 1 0.0% 0.3% LazyCompile: ~<anonymous> internal/child_process.js:477:40 1 0.0% 0.3% LazyCompile: ~<anonymous> /root/blog/node_modules/send/node_modules/http-errors/index.js:6:38 1 0.0% 0.3% LazyCompile: ~<anonymous> /root/blog/node_modules/log4js/lib/log4js.js:395:62 1 0.0% 0.3% LazyCompile: ~<anonymous> /root/blog/node_modules/log4js/lib/log4js.js:172:38 1 0.0% 0.3% LazyCompile: ~<anonymous> /root/blog/node_modules/ioredis/lib/commander.js:55:30 1 0.0% 0.3% LazyCompile: tryModuleLoad module.js:429:23 1 0.0% 0.3% LazyCompile: *tickDone internal/process/next_tick.js:30:20 1 0.0% 0.3% LazyCompile: *target.send internal/child_process.js:522:25 1 0.0% 0.3% LazyCompile: *slice native string.js:246:21 1 0.0% 0.3% LazyCompile: *sendHelper cluster.js:743:20 1 0.0% 0.3% LazyCompile: *handleMessage internal/child_process.js:731:23 1 0.0% 0.3% LazyCompile: *charCodeAt native string.js:50:28 1 0.0% 0.3% LazyCompile: *StringDecoder.write string_decoder.js:49:41 1 0.0% 0.3% LazyCompile: *<anonymous> internal/child_process.js:477:40 1 0.0% 0.3% KeyedStoreIC: A keyed store IC from the snapshot {3} 1 0.0% 0.3% KeyedStoreIC: A keyed store IC from the snapshot {2} 1 0.0% 0.3% KeyedStoreIC: A keyed store IC from the snapshot {1} 1 0.0% 0.3% KeyedLoadIC: A keyed load IC from the snapshot 1 0.0% 0.3% Handler: writeUtf8String 1 0.0% 0.3% Handler: apply 1 0.0% 0.3% Handler: _checkModeProperty 1 0.0% 0.3% Handler: Array 1 0.0% 0.3% Handler: An IC handler from the snapshot {5} 1 0.0% 0.3% Handler: An IC handler from the snapshot {4} 1 0.0% 0.3% Handler: An IC handler from the snapshot {2} 1 0.0% 0.3% Handler: An IC handler from the snapshot {1} 1 0.0% 0.3% Handler: An IC handler from the snapshot 1 0.0% 0.3% Function: ~<anonymous> util.js:1:11 1 0.0% 0.3% Function: ~<anonymous> /root/blog/node_modules/express/lib/express.js:1:11 1 0.0% 0.3% Builtin: Construct 1 0.0% 0.3% Builtin: CallFunction_ReceiverIsAny 1 0.0% 0.3% Builtin: ArgumentsAdaptorTrampoline
[C++]: ticks total nonlib name
[GC]: ticks total nonlib name 39 1.0%
[Bottom up (heavy) profile]: Note: percentage shows a share of a particular caller in the total amount of its parent calls. Callers occupying less than 2.0% are not shown.
ticks parent name 2055 52.9% /lib64/libc-2.12.so 142 6.9% /usr/software/node-v6.7.0-linux-x64/bin/node 7 4.9% LazyCompile: ~<anonymous> /root/blog/node_modules/lodash/lodash.js:4825:22 7 100.0% LazyCompile: ~baseForOwn /root/blog/node_modules/lodash/lodash.js:2954:24 7 100.0% Function: ~<anonymous> /root/blog/node_modules/lodash/lodash.js:16625:28 7 100.0% Function: ~runInContext /root/blog/node_modules/lodash/lodash.js:1410:44 6 4.2% LazyCompile: ~module.exports /root/blog/node_modules/bluebird/js/release/promise.js:2:26 6 100.0% Function: ~<anonymous> /root/blog/node_modules/bluebird/js/release/bluebird.js:1:11 6 100.0% LazyCompile: ~Module._compile module.js:496:37 6 100.0% LazyCompile: ~Module._extensions…js module.js:563:37 5 3.5% LazyCompile: ~<anonymous> /root/blog/node_modules/redis-commands/index.js:16:31 5 100.0% LazyCompile: ~InnerArrayForEach native array.js:935:27 5 100.0% LazyCompile: ~forEach native array.js:954:22 5 100.0% Function: ~<anonymous> /root/blog/node_modules/redis-commands/index.js:1:11 5 3.5% LazyCompile: ~<anonymous> /root/blog/node_modules/lodash/lodash.js:2980:41 5 100.0% LazyCompile: ~arrayFilter /root/blog/node_modules/lodash/lodash.js:578:23 5 100.0% LazyCompile: ~baseFunctions /root/blog/node_modules/lodash/lodash.js:2979:27 5 100.0% LazyCompile: ~mixin /root/blog/node_modules/lodash/lodash.js:15475:19 4 2.8% LazyCompile: ~target._send internal/child_process.js:549:26 4 100.0% LazyCompile: ~target.send internal/child_process.js:522:25 4 100.0% LazyCompile: ~sendHelper cluster.js:743:20 4 100.0% LazyCompile: ~RoundRobinHandle.handoff cluster.js:184:46 4 2.8% LazyCompile: ~startup bootstrap_node.js:12:19 4 100.0% Function: ~<anonymous> bootstrap_node.js:10:10 3 2.1% LazyCompile: ~map native array.js:994:18 1 33.3% LazyCompile: ~getCurrentNodeMethods /root/blog/node_modules/methods/index.js:29:31 1 100.0% Function: ~<anonymous> /root/blog/node_modules/methods/index.js:1:11 1 100.0% LazyCompile: ~Module._compile module.js:496:37 1 33.3% LazyCompile: ~Range /root/blog/node_modules/semver/semver.js:718:15 1 100.0% LazyCompile: satisfies /root/blog/node_modules/semver/semver.js:1092:19 1 100.0% Function: ~<anonymous> /root/blog/node_modules/log4js/lib/streams/BaseRollingFileStream.js:1:11 1 33.3% Function: ~<anonymous> /root/blog/node_modules/serve-static/node_modules/statuses/index.js:1:11 1 100.0% LazyCompile: ~Module._compile module.js:496:37 1 100.0% LazyCompile: ~Module._extensions…js module.js:563:37 3 2.1% LazyCompile: ~InnerArrayForEach native array.js:935:27 3 100.0% LazyCompile: ~forEach native array.js:954:22 1 33.3% LazyCompile: ~populateMaps /root/blog/node_modules/mime-types/index.js:154:23 1 100.0% Function: ~<anonymous> /root/blog/node_modules/mime-types/index.js:1:11 1 33.3% Function: ~<anonymous> /root/blog/node_modules/express/lib/router/index.js:1:11 1 100.0% LazyCompile: ~Module._compile module.js:496:37 1 33.3% Function: <anonymous> fs.js:1:11 1 100.0% LazyCompile: NativeModule.compile bootstrap_node.js:485:44
1402 36.1% /usr/software/node-v6.7.0-linux-x64/bin/node 1240 88.4% /usr/software/node-v6.7.0-linux-x64/bin/node 204 16.5% LazyCompile: ~ChildProcess.spawn internal/child_process.js:267:40 204 100.0% LazyCompile: ~exports.spawn child_process.js:373:37 204 100.0% LazyCompile: ~exports.fork child_process.js:19:24 204 100.0% LazyCompile: ~createWorkerProcess cluster.js:297:31 191 15.4% LazyCompile: ~exports.runInThisContext vm.js:75:36 191 100.0% LazyCompile: ~Module._compile module.js:496:37 191 100.0% LazyCompile: ~Module._extensions…js module.js:563:37 191 100.0% LazyCompile: ~Module.load module.js:464:33 160 12.9% LazyCompile: ~runInThisContext bootstrap_node.js:403:28 160 100.0% LazyCompile: NativeModule.compile bootstrap_node.js:485:44 154 96.3% LazyCompile: ~NativeModule.require bootstrap_node.js:419:34 20 13.0% LazyCompile: ~startup bootstrap_node.js:12:19 17 11.0% Function: ~<anonymous> tls.js:1:11 16 10.4% Function: ~<anonymous> http.js:1:11 14 9.1% Function: ~<anonymous> module.js:1:11 12 7.8% LazyCompile: ~Module._load module.js:398:24 11 7.1% Function: ~<anonymous> stream.js:1:11 10 6.5% Function: ~<anonymous> tty.js:1:11 9 5.8% Function: ~<anonymous> util.js:1:11 7 4.5% LazyCompile: ~setupGlobalVariables bootstrap_node.js:202:32 6 3.9% Function: ~<anonymous> _http_client.js:1:11 5 3.2% LazyCompile: ~lookupAndConnect net.js:935:26 4 2.6% LazyCompile: ~setupGlobalTimeouts bootstrap_node.js:230:31 4 2.6% Function: ~<anonymous> internal/child_process.js:1:11 4 2.6% Function: ~<anonymous> child_process.js:1:11 6 3.8% LazyCompile: *Module._load module.js:398:24 6 100.0% LazyCompile: *Module.require module.js:480:36 38 3.1% LazyCompile: ~<anonymous> /root/blog/node_modules/redis-commands/index.js:16:31 38 100.0% LazyCompile: ~InnerArrayForEach native array.js:935:27 38 100.0% LazyCompile: ~forEach native array.js:954:22 38 100.0% Function: ~<anonymous> /root/blog/node_modules/redis-commands/index.js:1:11 33 2.7% LazyCompile: ~parse native json.js:61:19 17 51.5% LazyCompile: readPackage module.js:79:21 13 76.5% LazyCompile: ~tryPackage module.js:101:20 13 100.0% LazyCompile: ~Module._findPath module.js:137:28 4 23.5% LazyCompile: *tryPackage module.js:101:20 4 100.0% LazyCompile: ~Module._findPath module.js:137:28 14 42.4% LazyCompile: Module._extensions…json module.js:570:39 14 100.0% LazyCompile: ~Module.load module.js:464:33 14 100.0% LazyCompile: tryModuleLoad module.js:429:23 2 6.1% LazyCompile: ~channel.onread internal/child_process.js:438:28
超时日志： [2016-10-20 10:40:10.026] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<126>ms,redis timeout<124>ms [2016-10-20 10:40:10.051] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<158>ms,redis timeout<154>ms [2016-10-20 10:40:10.133] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<133>ms,redis timeout<133>ms [2016-10-20 10:40:10.148] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<162>ms,redis timeout<162>ms [2016-10-20 10:40:10.173] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<146>ms,redis timeout<146>ms [2016-10-20 10:40:10.183] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<147>ms,redis timeout<147>ms [2016-10-20 10:40:10.691] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<89>ms,redis timeout<89>ms [2016-10-20 10:40:10.923] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<128>ms,redis timeout<128>ms [2016-10-20 10:40:13.408] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<111>ms,redis timeout<111>ms [2016-10-20 10:40:13.410] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<106>ms,redis timeout<106>ms [2016-10-20 10:40:14.304] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<142>ms,redis timeout<141>ms [2016-10-20 10:40:14.305] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<136>ms,redis timeout<136>ms [2016-10-20 10:40:18.224] [INFO] dateFileLog - visit key:zhaozhi001,total timeout<85>ms,redis timeout<85>ms
