Node.jsが非同期で処理してる様子がよく分かるサンプル

概要

HTMLドキュメントを取得するプロキシ
起動したプロキシ(Node.jsプログラム)に対し、jMeter(プロセス数:5)で15回のリクエストを短時間に投げてみた
見所
- 一つのリクエストに対して細切れ(chunk)となったレスポンスが複数返ってきます
- 返ってきたレスポンスを随時処理します。一リクエストが完了するまで他をブロックするということはありません
- 非同期で処理するときは変数を宣言する位置に注意！例：cnt <-> var1、var1の位置でcntを宣言しちゃうと、意図しない値が入ってしまう
クラスタリングもしてみたけど、すべてMasterで処理されている？この程度はWorkerに任せるまでもないということ？
もう一つウィンドウ/タブを開いて、並べて見た方がいいかもね(笑)

サンプルプログラム(index.js)

var
  connect = require('connect'),
  http = require('http'),
  cluster = require('cluster'),
  worker_num = 2,
  var1 = 0; // <<<<< 1

if (cluster.isMaster) {
  for (var i=0; i<worker_num; i++) {
    cluster.fork();
  }
  cluster
  .on('fork', function(worker) {
    console.log('worker %s created.', worker.id);
  })
  .on('exit', function(worker) {
    console.log('worker %s died.', worker.id);
  });
}

connect()
  .use(function(req, res) { // ******
    var1++; // >>>>>> 1
    var cnt = var1;
    console.log('start -> %s', fmt(cnt));
    var var2 = 0; // <<<<<< 2
    if (req.url.length > 1) {
      var target_url = decodeURIComponent(req.url.substring(1));
      console.log('[%s] GET %s', fmt(cnt), target_url);
      var request = http.get(
        target_url,
        function(response) { // ******
          var2++; // >>>>>> 2
          var var3 = 0; // <<<<<< 3
          var buf = [];
          response
            .on('data', function(chunk) { // ******
              var3++; // >>>>>> 3
              var wkid = (cluster.isMaster) ? 'm' : cluster.worker.id;
              console.log('[%s] wk:%s, var:%s/%s/%s receipt data(%d)', fmt(cnt), wkid, fmt(var1,' '), fmt(var2,' '), fmt(var3,' '), chunk.toString().length);
              buf.push(chunk);
            })
            .on('end', function() {
              var content = buf.join('');
              console.log('[%s] receipt end', fmt(cnt));
              res.end(content);
            });
        }
      ).on('error', function(e) {
        console.log('[%s] %s', fmt(cnt), e);
        res.end();
      });
    }
    else {
      console.log('[%s] No target', fmt(cnt));
      res.end();
    }
  })
  .listen(3000);

function fmt(value, ch) {
  if (!ch) ch = '0';
  return (ch.concat(ch).concat(ch).concat(value)).slice(-3);
}

出力されたログ

worker 1 created.
worker 2 created.
start -> 001
[001] GET http://www.google.co.jp/
start -> 002
[002] GET http://www.hatena.ne.jp/
start -> 003
[003] GET http://www.hatena.ne.jp/
start -> 004
[004] GET http://www.yahoo.co.jp/
start -> 005
[005] GET http://www.hatena.ne.jp/
[004] wk:m, var:  5/  1/  1 receipt data(9030)
[003] wk:m, var:  5/  1/  1 receipt data(5201)
[005] wk:m, var:  5/  1/  1 receipt data(5200)
[002] wk:m, var:  5/  1/  1 receipt data(5200)
[003] wk:m, var:  5/  1/  2 receipt data(1310)
[004] wk:m, var:  5/  1/  2 receipt data(9594)
[003] wk:m, var:  5/  1/  3 receipt data(6054)
[005] wk:m, var:  5/  1/  2 receipt data(7364)
[002] wk:m, var:  5/  1/  2 receipt data(2950)
[002] wk:m, var:  5/  1/  3 receipt data(4416)
[004] wk:m, var:  5/  1/  3 receipt data(3694)
[003] wk:m, var:  5/  1/  4 receipt data(6292)
[004] receipt end
start -> 006
[006] GET http://www.google.co.jp/
[005] wk:m, var:  6/  1/  3 receipt data(6290)
[002] wk:m, var:  6/  1/  4 receipt data(6290)
[003] wk:m, var:  6/  1/  5 receipt data(10428)
[005] wk:m, var:  6/  1/  4 receipt data(6410)
[002] wk:m, var:  6/  1/  5 receipt data(8628)
[003] wk:m, var:  6/  1/  6 receipt data(3872)
[003] wk:m, var:  6/  1/  7 receipt data(12644)
[005] wk:m, var:  6/  1/  5 receipt data(5044)
[005] wk:m, var:  6/  1/  6 receipt data(7810)
[002] wk:m, var:  6/  1/  6 receipt data(12388)
[003] wk:m, var:  6/  1/  8 receipt data(22252)
[005] wk:m, var:  6/  1/  7 receipt data(8168)
[005] wk:m, var:  6/  1/  8 receipt data(11598)
[002] wk:m, var:  6/  1/  7 receipt data(1922)
[002] wk:m, var:  6/  1/  8 receipt data(10368)
[002] wk:m, var:  6/  1/  9 receipt data(5782)
[003] wk:m, var:  6/  1/  9 receipt data(14324)
[003] receipt end
[005] wk:m, var:  6/  1/  9 receipt data(2622)
start -> 007
[007] GET http://www.yahoo.co.jp/
[005] wk:m, var:  7/  1/ 10 receipt data(3280)
[005] wk:m, var:  7/  1/ 11 receipt data(19415)
[005] receipt end
start -> 008
[008] GET http://www.yahoo.co.jp/
[002] wk:m, var:  8/  1/ 10 receipt data(25265)
[002] receipt end
[006] wk:m, var:  8/  1/  1 receipt data(4078)
[006] wk:m, var:  8/  1/  2 receipt data(3859)
[006] wk:m, var:  8/  1/  3 receipt data(237)
start -> 009
[009] GET http://www.google.co.jp/
[006] wk:m, var:  9/  1/  4 receipt data(4096)
[006] wk:m, var:  9/  1/  5 receipt data(4096)
[006] wk:m, var:  9/  1/  6 receipt data(4096)
[006] wk:m, var:  9/  1/  7 receipt data(4096)
[006] wk:m, var:  9/  1/  8 receipt data(4085)
[006] wk:m, var:  9/  1/  9 receipt data(3776)
[006] wk:m, var:  9/  1/ 10 receipt data(318)
[006] wk:m, var:  9/  1/ 11 receipt data(4091)
[006] wk:m, var:  9/  1/ 12 receipt data(4092)
[006] wk:m, var:  9/  1/ 13 receipt data(2492)
[006] receipt end
start -> 010
[010] GET http://www.hatena.ne.jp/
[007] wk:m, var: 10/  1/  1 receipt data(5868)
[007] wk:m, var: 10/  1/  2 receipt data(3162)
[009] wk:m, var: 10/  1/  1 receipt data(4078)
[009] wk:m, var: 10/  1/  2 receipt data(3832)
[009] wk:m, var: 10/  1/  3 receipt data(264)
[008] wk:m, var: 10/  1/  1 receipt data(9030)
[007] wk:m, var: 10/  1/  3 receipt data(3164)
[007] wk:m, var: 10/  1/  4 receipt data(6454)
[009] wk:m, var: 10/  1/  4 receipt data(4096)
[009] wk:m, var: 10/  1/  5 receipt data(4096)
[009] wk:m, var: 10/  1/  6 receipt data(4096)
[009] wk:m, var: 10/  1/  7 receipt data(4096)
[009] wk:m, var: 10/  1/  8 receipt data(938)
[009] wk:m, var: 10/  1/  9 receipt data(3147)
[009] wk:m, var: 10/  1/ 10 receipt data(3776)
[008] wk:m, var: 10/  1/  2 receipt data(9498)
[007] wk:m, var: 10/  1/  5 receipt data(3659)
[007] receipt end
start -> 011
[011] GET http://www.google.co.jp/
[009] wk:m, var: 11/  1/ 11 receipt data(318)
[009] wk:m, var: 11/  1/ 12 receipt data(4091)
[009] wk:m, var: 11/  1/ 13 receipt data(4092)
[009] wk:m, var: 11/  1/ 14 receipt data(2492)
[009] receipt end
start -> 012
[012] GET http://www.yahoo.co.jp/
[008] wk:m, var: 12/  1/  3 receipt data(3807)
[008] receipt end
start -> 013
[013] GET http://www.google.co.jp/
[010] wk:m, var: 13/  1/  1 receipt data(5756)
[010] wk:m, var: 13/  1/  2 receipt data(5062)
[011] wk:m, var: 13/  1/  1 receipt data(4078)
[011] wk:m, var: 13/  1/  2 receipt data(3855)
[011] wk:m, var: 13/  1/  3 receipt data(241)
[011] wk:m, var: 13/  1/  4 receipt data(1254)
[010] wk:m, var: 13/  1/  3 receipt data(4104)
[012] wk:m, var: 13/  1/  1 receipt data(5868)
[011] wk:m, var: 13/  1/  5 receipt data(2842)
[011] wk:m, var: 13/  1/  6 receipt data(4096)
[011] wk:m, var: 13/  1/  7 receipt data(4096)
[011] wk:m, var: 13/  1/  8 receipt data(4096)
[011] wk:m, var: 13/  1/  9 receipt data(4085)
[011] wk:m, var: 13/  1/ 10 receipt data(4094)
[011] wk:m, var: 13/  1/ 11 receipt data(570)
[010] wk:m, var: 13/  1/  4 receipt data(2256)
[013] wk:m, var: 13/  1/  1 receipt data(4078)
[013] wk:m, var: 13/  1/  2 receipt data(3884)
[013] wk:m, var: 13/  1/  3 receipt data(212)
[010] wk:m, var: 13/  1/  5 receipt data(4742)
[012] wk:m, var: 13/  1/  2 receipt data(6330)
[011] wk:m, var: 13/  1/ 12 receipt data(3521)
[011] wk:m, var: 13/  1/ 13 receipt data(4092)
[011] wk:m, var: 13/  1/ 14 receipt data(2476)
[011] receipt end
[010] wk:m, var: 13/  1/  6 receipt data(3358)
[013] wk:m, var: 13/  1/  4 receipt data(3466)
[013] wk:m, var: 13/  1/  5 receipt data(630)
[013] wk:m, var: 13/  1/  6 receipt data(2834)
[013] wk:m, var: 13/  1/  7 receipt data(1262)
[013] wk:m, var: 13/  1/  8 receipt data(4096)
[013] wk:m, var: 13/  1/  9 receipt data(4096)
[013] wk:m, var: 13/  1/ 10 receipt data(4085)
[013] wk:m, var: 13/  1/ 11 receipt data(3776)
[012] wk:m, var: 13/  1/  3 receipt data(10124)
[012] receipt end
[010] wk:m, var: 13/  1/  7 receipt data(13082)
[013] wk:m, var: 13/  1/ 12 receipt data(318)
[013] wk:m, var: 13/  1/ 13 receipt data(4091)
[013] wk:m, var: 13/  1/ 14 receipt data(4092)
[013] wk:m, var: 13/  1/ 15 receipt data(2454)
[013] receipt end
[010] wk:m, var: 13/  1/  8 receipt data(15754)
[010] wk:m, var: 13/  1/  9 receipt data(28265)
[010] receipt end
[001] wk:m, var: 13/  1/  1 receipt data(4078)
[001] wk:m, var: 13/  1/  2 receipt data(3800)
[001] wk:m, var: 13/  1/  3 receipt data(296)
[001] wk:m, var: 13/  1/  4 receipt data(4096)
[001] wk:m, var: 13/  1/  5 receipt data(4082)
[001] wk:m, var: 13/  1/  6 receipt data(14)
[001] wk:m, var: 13/  1/  7 receipt data(4096)
[001] wk:m, var: 13/  1/  8 receipt data(4096)
[001] wk:m, var: 13/  1/  9 receipt data(4085)
[001] wk:m, var: 13/  1/ 10 receipt data(4094)
[001] wk:m, var: 13/  1/ 11 receipt data(570)
[001] wk:m, var: 13/  1/ 12 receipt data(3522)
[001] wk:m, var: 13/  1/ 13 receipt data(4091)
[001] wk:m, var: 13/  1/ 14 receipt data(2516)
[001] receipt end
start -> 014
[014] GET http://www.hatena.ne.jp/
[014] wk:m, var: 14/  1/  1 receipt data(5756)
[014] wk:m, var: 14/  1/  2 receipt data(5062)
[014] wk:m, var: 14/  1/  3 receipt data(6358)
[014] wk:m, var: 14/  1/  4 receipt data(10140)
[014] wk:m, var: 14/  1/  5 receipt data(4138)
[014] wk:m, var: 14/  1/  6 receipt data(10926)
[014] wk:m, var: 14/  1/  7 receipt data(15406)
[014] wk:m, var: 14/  1/  8 receipt data(2474)
[014] wk:m, var: 14/  1/  9 receipt data(5690)
[014] wk:m, var: 14/  1/ 10 receipt data(16425)
[014] receipt end
start -> 015
[015] GET http://www.yahoo.co.jp/
[015] wk:m, var: 15/  1/  1 receipt data(5868)
[015] wk:m, var: 15/  1/  2 receipt data(6312)
[015] wk:m, var: 15/  1/  3 receipt data(10100)
[015] receipt end