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が２回呼ばれているのがわかる。ここで、無限ループに陥った場合を考える。

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 の大きさには気をつける。