Node.jsとasync.jsとcallstack
Node.js の call stack の性質を知る必要がでてきた。ためしてみた結果を記録。
Node.js の stack trace の出し方を知る
Errors | Node.js v7.6.0 Documentation を参考に実行してみる。
var stack = new Error().stack console.log( stack )
実行結果:
$ node app.js Error at Object.<anonymous> (/[directory_path]/app.js:1:75) at Module._compile (module.js:409:26) at Object.Module._extensions..js (module.js:416:10) at Module.load (module.js:343:32) at Function.Module._load (module.js:300:12) at Function.Module.runMain (module.js:441:10) at startup (node.js:139:18) at node.js:968:3
変数 stack には起動から new Error までのcall stack が格納されたようだ。
同じく Console | Node.js v7.6.0 Documentation を参考に実行してみる。
console.trace();
実行結果:
$ node app.js Trace at Object.<anonymous> (/[directory_path]/app.js:1:71) at Module._compile (module.js:409:26) at Object.Module._extensions..js (module.js:416:10) at Module.load (module.js:343:32) at Function.Module._load (module.js:300:12) at Function.Module.runMain (module.js:441:10) at startup (node.js:139:18) at node.js:968:3
console.traceは、
message and stack trace
を印字するそうだ。
基本的な callstack の挙動を見てみる
関数実行後に別途関数を呼び出すのか、関数内で関数を呼び出すのかで call stack が消化されるのか、積まれるのかが変わるはず。
function method() { return true; } method(); console.trace();
実行結果:
$ node app.js Trace at Object.<anonymous> (/[directory_path]/app.js:6:9) at Module._compile (module.js:409:26) at Object.Module._extensions..js (module.js:416:10) at Module.load (module.js:343:32) at Function.Module._load (module.js:300:12) at Function.Module.runMain (module.js:441:10) at startup (node.js:139:18) at node.js:968:3
function method(callback) { callback(true); } method(function(bool){ console.trace(); });
実行結果:
$ node app.js Trace at /[directory_path]/app.js:6:10 at method (/[directory_path]/app.js:2:2) at Object.<anonymous> (/[directory_path]/app.js:5:1) at Module._compile (module.js:409:26) at Object.Module._extensions..js (module.js:416:10) at Module.load (module.js:343:32) at Function.Module._load (module.js:300:12) at Function.Module.runMain (module.js:441:10) at startup (node.js:139:18) at node.js:968:3
両者は method が callstack に残されているかに違いが出る。
call stack overflow を起こす
一度、call stack overflow を経験しておくことにする。真っ先に思いつくのは再帰呼出し。
function method(n) { console.log(n); method(n + 1); } method(0);
実行結果の一部:
17938 17939 17940 util.js:158 function stylizeNoColor(str, styleType) { ^ RangeError: Maximum call stack size exceeded at Object.stylizeNoColor [as stylize] (util.js:158:24) at formatPrimitive (util.js:439:16) at formatValue (util.js:227:19) at inspect (util.js:109:10) at exports.format (util.js:17:20) at Console.log (console.js:39:34) at method (/[directory_path]/app.js:2:10) at method (/[directory_path]/app.js:3:2) at method (/[directory_path]/app.js:3:2) at method (/[directory_path]/app.js:3:2)
なお、Errors | Node.js v7.6.0 Documentation を見ると RangeError は、
a provided argument was not within the set or range of acceptable values for a function
とのことで、今回は後者にあたるはず。
再帰呼び出しを setTimeout でラップする
ためしに event queue に仕事をさせてみる。setTimeout は引数の function をevent queue に登録し、関数自体は即座に結果を返却するはずだ。
function method(n) { setTimeout(function() { console.log(n); method(n + 1); }, 0); } method(0);
こうすると、先程停止した 17940
を過ぎてもMaximum call stack size exceeded
が呼ばれない。ここで、実行中の call stack を比較してみることにする。
function method(n) { if (n === 100) { console.trace(); } else { console.log(n); method(n + 1); } } method(0);
97 98 99 Trace at method (/[directory_path]/app.js:5:17) at method (/[directory_path]/app.js:8:9) at method (/[directory_path]/app.js:8:9) at method (/[directory_path]/app.js:8:9) at method (/[directory_path]/app.js:8:9) at method (/[directory_path]/app.js:8:9) at method (/[directory_path]/app.js:8:9) at method (/[directory_path]/app.js:8:9) at method (/[directory_path]/app.js:8:9) at method (/[directory_path]/app.js:8:9)
function method(n) { if (n === 17940) { console.trace(); } else { setTimeout(function() { console.log(n); method(n + 1); }, 0); } } method(0);
17938 17939 Trace at method (/[directory_path]/app.js:5:17) at null._onTimeout (/[directory_path]/app.js:9:13) at Timer.listOnTimeout (timers.js:92:15)
後者では method が複数積まれていないことがわかる。
async.js 使用時の stack trace をみてみる
async.js では、async.js に定義された関数の処理を通しながら、function list の関数を実行していく。
async.waterfall の場合
async.waterfallは、順次処理を記述する際に便利な関数だ。async.waterfall を例に call stack を見てみる。
var async = require('async'); Error.stackTraceLimit = Infinity; function method(cb){ cb(null); } async.waterfall([method, method, method], function(err, result){ console.trace(); });
実行結果:
Trace at /[directory_path]/app.js:10:10 at /[directory_path]/node_modules/async/dist/async.js:359:16 at nextTask (/[directory_path]/node_modules/async/dist/async.js:5057:29) at /[directory_path]/node_modules/async/dist/async.js:5064:13 at apply (/[directory_path]/node_modules/async/dist/async.js:21:25) at /[directory_path]/node_modules/async/dist/async.js:56:12 at /[directory_path]/node_modules/async/dist/async.js:843:16 at method (/[directory_path]/app.js:6:2) at nextTask (/[directory_path]/node_modules/async/dist/async.js:5070:14) at /[directory_path]/node_modules/async/dist/async.js:5064:13 at apply (/[directory_path]/node_modules/async/dist/async.js:21:25) at /[directory_path]/node_modules/async/dist/async.js:56:12 at /[directory_path]/node_modules/async/dist/async.js:843:16 at method (/[directory_path]/app.js:6:2) at nextTask (/[directory_path]/node_modules/async/dist/async.js:5070:14) at /[directory_path]/node_modules/async/dist/async.js:5064:13 at apply (/[directory_path]/node_modules/async/dist/async.js:21:25) at /[directory_path]/node_modules/async/dist/async.js:56:12 at /[directory_path]/node_modules/async/dist/async.js:843:16 at method (/[directory_path]/app.js:6:2) at nextTask (/[directory_path]/node_modules/async/dist/async.js:5070:14) at Object.waterfall (/[directory_path]/node_modules/async/dist/async.js:5073:5) at Object.<anonymous> (/[directory_path]/app.js:9:7) at Module._compile (module.js:409:26) at Object.Module._extensions..js (module.js:416:10) at Module.load (module.js:343:32) at Function.Module._load (module.js:300:12) at Function.Module.runMain (module.js:441:10) at startup (node.js:139:18) at node.js:968:3
制御のためにいちいちasync.jsの関数を呼び出すので、call stack はやや長くなる。
async.parallel の場合
async.js には、非同期に、並列処理かのように動作する関数が存在する。async.parallelもそのひとつだ。こちらも setTimeoutを使用したときと同様の現象がみられる。
var async = require('async'); Error.stackTraceLimit = Infinity; function method(cb){ cb(null); } async.parallel([method, method, method], function(err, result){ console.trace(); });
Trace at /[directory_path]/app.js:10:10 at /[directory_path]/node_modules/async/dist/async.js:3694:9 at /[directory_path]/node_modules/async/dist/async.js:359:16 at iteratorCallback (/[directory_path]/node_modules/async/dist/async.js:935:13) at /[directory_path]/node_modules/async/dist/async.js:843:16 at /[directory_path]/node_modules/async/dist/async.js:3691:13 at apply (/[directory_path]/node_modules/async/dist/async.js:21:25) at /[directory_path]/node_modules/async/dist/async.js:56:12 at method (/[directory_path]/app.js:6:2) at /[directory_path]/node_modules/async/dist/async.js:3686:9 at eachOfArrayLike (/[directory_path]/node_modules/async/dist/async.js:940:9) at eachOf (/[directory_path]/node_modules/async/dist/async.js:990:5) at _parallel (/[directory_path]/node_modules/async/dist/async.js:3685:5) at Object.parallelLimit [as parallel] (/[directory_path]/node_modules/async/dist/async.js:3765:3) at Object.<anonymous> (/[directory_path]/app.js:9:7) at Module._compile (module.js:409:26) at Object.Module._extensions..js (module.js:416:10) at Module.load (module.js:343:32) at Function.Module._load (module.js:300:12) at Function.Module.runMain (module.js:441:10) at startup (node.js:139:18) at node.js:968:3
stack trace をみると method が一度分しか記載されていないことがわかる。
async.reduce と call stack overflow
async.waterfall 利用時の call stack をみると、call stack overflow を起こし得ると想像がつく。何万もの関数をwaterfallにいれる事例は考えにくいが、引数に値のリストを取るような場合ならどうだろうか。
var async = require('async'); //Error.stackTraceLimit = Infinity; var num = parseInt(process.argv.slice(2), 10); var list = Array.from(Array(num).keys()); function method(memo, num, cb){ cb(null, memo + num); } async.reduce(list, 0, method, function(err, result){ console.log('done'); });
$ node app.js 1940 done
$ node app.js 1950 bootstrap_node.js:432 const script = new ContextifyScript(code, options); ^ RangeError: Maximum call stack size exceeded at runInThisContext (bootstrap_node.js:432:20) at NativeModule.compile (bootstrap_node.js:520:18) at NativeModule.require (bootstrap_node.js:466:18) at tty.js:4:13 at NativeModule.compile (bootstrap_node.js:525:7) at NativeModule.require (bootstrap_node.js:466:18) at createWritableStdioStream (internal/process/stdio.js:142:19) at process.getStdout [as stdout] (internal/process/stdio.js:10:14) at console.js:100:37 at NativeModule.compile (bootstrap_node.js:525:7)
2000件のデータをそのまま async.reduec にいれればこういうことになる。
async.reduceと async.waterfall の組み合わせとcall stack overflow を考える
多数のデータをもつcollection を順次処理にかけるリスクがわかった。より実際の処理で起こり得そうな状況として、async.waterfallとの組み合わせを考える。
var async = require('async'); //Error.stackTraceLimit = Infinity; var num = parseInt(process.argv.slice(2), 10); var list = Array.from(Array(num).keys()); function method(memo, num, cb) { cb(null, memo + num); } function reduce(cb) { async.reduce(list, 0, method, function(err, result){ cb(err); }); } async.waterfall([reduce, reduce, reduce, reduce, reduce], function(err, result){ console.log('done'); })
$ node app.js 400 done
$ node app.js 500 [directory_path]/node_modules/async/dist/async.js:843 callFn.apply(this, arguments); ^ RangeError: Maximum call stack size exceeded at [directory_path]/node_modules/async/dist/async.js:843:16 at [directory_path]/node_modules/async/dist/async.js:2487:13 at method ([directory_path]/app.js:8:2) at [directory_path]/node_modules/async/dist/async.js:2485:9 at replenish ([directory_path]/node_modules/async/dist/async.js:881:17) at iterateeCallback ([directory_path]/node_modules/async/dist/async.js:866:17) at [directory_path]/node_modules/async/dist/async.js:843:16 at [directory_path]/node_modules/async/dist/async.js:2487:13 at method ([directory_path]/app.js:8:2)
async.doWhilstと無限ループを考える
記事冒頭でcall stack overflowの原因に再帰呼び出しを考えたが、無限ループの場合も考えておく。async.doWhilstは繰り返しを実現する関数だ。
var async = require('async'); Error.stackTraceLimit = Infinity; var n = 0; var limit =parseInt(process.argv.slice(2), 10); async.doWhilst( function(cb) { n++; cb(null); }, function() { return (n < limit); }, function(err) { console.trace('done'); } );
$ node app.js 2 Trace: done at [directory_path]/app.js:16:13 at [directory_path]/node_modules/async/dist/async.js:843:16 at [directory_path]/node_modules/async/dist/async.js:2938:18 at apply ([directory_path]/node_modules/async/dist/async.js:21:25) at [directory_path]/node_modules/async/dist/async.js:56:12 at [directory_path]/app.js:10:5 at [directory_path]/node_modules/async/dist/async.js:2937:44 at apply ([directory_path]/node_modules/async/dist/async.js:21:25) at [directory_path]/node_modules/async/dist/async.js:56:12 at [directory_path]/app.js:10:5 at Object.doWhilst ([directory_path]/node_modules/async/dist/async.js:2940:5) at Object.<anonymous> ([directory_path]/app.js:7:7) at Module._compile (module.js:571:32) at Object.Module._extensions..js (module.js:580:10) at Module.load (module.js:488:32) at tryModuleLoad (module.js:447:12) at Function.Module._load (module.js:439:3) at Module.runMain (module.js:605:10) at run (bootstrap_node.js:422:7) at startup (bootstrap_node.js:143:9) at bootstrap_node.js:537:3
少々わかりにくいが、app.js:10:5
が2回呼ばれているのがわかる。ここで、無限ループに陥った場合を考える。
var async = require('async'); var n = 0; var limit =parseInt(process.argv.slice(2), 10); async.doWhilst( function(cb) { n++; cb(null); }, function() { return true; // return (n < limit); }, function(err) { console.log('done'); } );
$ node app.js [directory_path]/node_modules/async/dist/async.js:76 function identity(value) { ^ RangeError: Maximum call stack size exceeded at identity ([directory_path]/node_modules/async/dist/async.js:76:18) at [directory_path]/node_modules/async/dist/async.js:55:24 at [directory_path]/app.js:9:5 at [directory_path]/node_modules/async/dist/async.js:2937:44 at apply ([directory_path]/node_modules/async/dist/async.js:21:25) at [directory_path]/node_modules/async/dist/async.js:56:12 at [directory_path]/app.js:9:5 at [directory_path]/node_modules/async/dist/async.js:2937:44 at apply ([directory_path]/node_modules/async/dist/async.js:21:25) at [directory_path]/node_modules/async/dist/async.js:56:12
この場合もcall stack があふれる。
むすび
call stack の大きさには気をつける。