Stormのコマンドが遅い理由とは？ - 夢とガラクタの集積場

こんにちは。

とりあえず気になることができたので、しばらくStormネタです。

1.Stormを使っていて気になる所

皆さんはStormを実際に使ってみたことがあるでしょうか？

私は使って最初のうちは気にならなかったのですが、最近気になってきたことがあります。
それは、Stormのコマンド（storm）の遅さです。

8コア、32GBクラスのマシンの上で動作させていても、
StormのクラスタからTopologyの一覧取得するだけで普通に10秒位使っちゃうんですよね。

ということで、まずは実際にコマンドを実行した結果かかった時間を示してみます。
前提となるマシンスペックは下記です。

■ホストマシン

CPU                 : Core i7 3770
Memory              : 32GB
HDD                 : 2TB

■仮想マシン（stormtest）

CPUコア数           : 2
Memory              : 8GB
HDD                 : 200GB
OS                  : CentOS6.6 64bit(Basic Server)

仮想マシンの性能は低いですが、その場合の値、として見てもらえればＯＫです。
尚、他の仮想マシンは稼働させずに確認しています。

2.Stormコマンド実行にかかる時間

では、実際にコマンドを実行してみます。

Topology起動

所要時間：11秒

[root@stormtest storm]# date;bin/storm jar examples/storm-starter/storm-starter-topologies-0.9.4.jar storm.starter.ExclamationTopology ExclamationTopology;date
2015年  4月  8日 水曜日 23:55:42 JST
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) storm.starter.ExclamationTopology ExclamationTopology
340  [main] INFO  backtype.storm.StormSubmitter - Jar not uploaded to master yet. Submitting jar...
347  [main] INFO  backtype.storm.StormSubmitter - Uploading topology jar examples/storm-starter/storm-starter-topologies-0.9.4.jar to assigned location: /opt/storm/nimbus/inbox/stormjar-1238b151-b1f8-48ad-acc5-80cf4107e688.jar
Start uploading file 'examples/storm-starter/storm-starter-topologies-0.9.4.jar' to '/opt/storm/nimbus/inbox/stormjar-1238b151-b1f8-48ad-acc5-80cf4107e688.jar' (3244061 bytes)
[==================================================] 3244061 / 3244061
File 'examples/storm-starter/storm-starter-topologies-0.9.4.jar' uploaded to '/opt/storm/nimbus/inbox/stormjar-1238b151-b1f8-48ad-acc5-80cf4107e688.jar' (3244061 bytes)
395  [main] INFO  backtype.storm.StormSubmitter - Successfully uploaded topology jar to assigned location: /opt/storm/nimbus/inbox/stormjar-1238b151-b1f8-48ad-acc5-80cf4107e688.jar
395  [main] INFO  backtype.storm.StormSubmitter - Submitting topology ExclamationTopology in distributed mode with conf {"topology.workers":3,"topology.debug":true}
598  [main] INFO  backtype.storm.StormSubmitter - Finished submitting topology: ExclamationTopology
2015年  4月  8日 水曜日 23:55:53 JST

Topology一覧取得

所要時間：16秒

[root@stormtest storm]# date;bin/storm list;date
2015年  4月  8日 水曜日 23:58:49 JST
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.list
1815 [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
Topology_name        Status     Num_tasks  Num_workers  Uptime_secs
-------------------------------------------------------------------
ExclamationTopology  ACTIVE     18         3            192
2015年  4月  8日 水曜日 23:59:05 JST

TopologyActivate

所要時間：15秒

[root@stormtest storm]# date;bin/storm activate ExclamationTopology;date
2015年  4月  9日 木曜日 00:00:43 JST
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.activate ExclamationTopology
1323 [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
1348 [main] INFO  backtype.storm.command.activate - Activated topology: ExclamationTopology
2015年  4月  9日 木曜日 00:00:58 JST

TopologyDeactivate

所要時間：16秒

[root@stormtest storm]# date;bin/storm deactivate ExclamationTopology;date
2015年  4月  8日 水曜日 23:59:51 JST
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.deactivate ExclamationTopology
1776 [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
1813 [main] INFO  backtype.storm.command.deactivate - Deactivated topology: ExclamationTopology
2015年  4月  9日 木曜日 00:00:07 JST

TopologyRebalance

所要時間：16秒

[root@stormtest storm]# date;bin/storm rebalance ExclamationTopology;date
2015年  4月  9日 木曜日 00:02:51 JST
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.rebalance ExclamationTopology
1013 [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
1047 [main] INFO  backtype.storm.command.rebalance - Topology ExclamationTopology is rebalancing
2015年  4月  9日 木曜日 00:03:07 JST

Topology kill

所要時間：16秒

[root@stormtest storm]# date;bin/storm kill ExclamationTopology;date
2015年  4月  9日 木曜日 00:04:25 JST
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.kill_topology ExclamationTopology
711  [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
753  [main] INFO  backtype.storm.command.kill-topology - Killed topology: ExclamationTopology
2015年  4月  9日 木曜日 00:04:41 JST

・・・遅い。
かつ、何故か一番時間がかかりそうなTopology起動よりも
他のコマンド群の方が明らかに時間がかかっているというのはどういうことなんでしょう・・・

ともあれ、とりあえずまとめてみた結果は下記でした。

No	コマンド	機能	所要時間
1	jar	TopologyをStormクラスタにデプロイ	11秒
2	list	StormクラスタのTopology一覧取得	16秒
3	activate	Topologyを有効化	15秒
4	deactivate	Topologyを無効化	16秒
5	rebalance	Topologyを再配置	16秒
6	kill	Topologyを終了	16秒

3.どこに時間がかかっている？

実際に、Stormのコマンドの中身を確認してどこに時間がかかっているかを追ってみます。
今回試した6コマンドは全てStormコマンド内部では「exec_storm_class」という関数を呼び出しています。
ですので、exec_storm_classに下記のように時刻を出力する処理を追記し、再実行してみます。
尚、exec_storm_classの最後で出力を行っていないのは、最後まで実行しないままforkされてしまうからです。

def exec_storm_class(klass, jvmtype="-server", jvmopts=[], extrajars=[], args=[], fork=False):
    import datetime # 追記
    print("Start exec_storm_class " + datetime.datetime.today().strftime("%Y-%m-%d %H:%M:%S")) # 追記
    global CONFFILE
    storm_log_dir = confvalue("storm.log.dir",[CLUSTER_CONF_DIR])
    print("Config get " + datetime.datetime.today().strftime("%Y-%m-%d %H:%M:%S")) # 追記
    if(storm_log_dir == None or storm_log_dir == "nil"):
        storm_log_dir = STORM_DIR+"/logs"
    all_args = [
        JAVA_CMD, jvmtype, get_config_opts(),
        "-Dstorm.home=" + STORM_DIR,
        "-Dstorm.log.dir=" + storm_log_dir,
        "-Djava.library.path=" + confvalue("java.library.path", extrajars),
        "-Dstorm.conf.file=" + CONFFILE,
        "-cp", get_classpath(extrajars),
    ] + jvmopts + [klass] + list(args)
    print("Config get and args construct " + datetime.datetime.today().strftime("%Y-%m-%d %H:%M:%S")) # 追記
    print("Running: " + " ".join(all_args))
    if fork:
        os.spawnvp(os.P_WAIT, JAVA_CMD, all_args)
    else:
        os.execvp(JAVA_CMD, all_args) # replaces the current process and
        # never returnsa

再実行してみた結果は下記になりました。

Topology起動

[root@stormtest storm]# date;bin/storm jar examples/storm-starter/storm-starter-topologies-0.9.4.jar storm.starter.ExclamationTopology ExclamationTopology;date
2015年  4月  9日 木曜日 00:29:24 JST
Start exec_storm_class 2015-04-09 00:29:24
Config get 2015-04-09 00:29:29
Config get and args construct 2015-04-09 00:29:34
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) storm.starter.ExclamationTopology ExclamationTopology
 (省略) 
391  [main] INFO  backtype.storm.StormSubmitter - Finished submitting topology: ExclamationTopology
2015年  4月  9日 木曜日 00:29:34 JST

Topology一覧取得

所要時間：16秒

2015年  4月  9日 木曜日 00:30:53 JST
Start exec_storm_class 2015-04-09 00:30:53
Config get 2015-04-09 00:30:59
Config get and args construct 2015-04-09 00:31:05
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.list
1815 [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
Topology_name        Status     Num_tasks  Num_workers  Uptime_secs
-------------------------------------------------------------------
ExclamationTopology  ACTIVE     18         3            192
2015年  4月  9日 木曜日 00:31:10 JST

TopologyActivate

所要時間：15秒

[root@stormtest storm]# date;bin/storm activate ExclamationTopology;date
2015年  4月  9日 木曜日 00:33:54 JST
Start exec_storm_class 2015-04-09 00:33:54
Config get 2015-04-09 00:33:59
Config get and args construct 2015-04-09 00:34:04
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.activate ExclamationTopology
1628 [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
1641 [main] INFO  backtype.storm.command.activate - Activated topology: ExclamationTopology
2015年  4月  9日 木曜日 00:34:09

TopologyDeactivate

所要時間：16秒

[root@stormtest storm]# date;bin/storm deactivate ExclamationTopology;date
2015年  4月  9日 木曜日 00:33:04 JST
Start exec_storm_class 2015-04-09 00:33:04
Config get 2015-04-09 00:33:09
Config get and args construct 2015-04-09 00:33:14
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.deactivate ExclamationTopology
2085 [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
2098 [main] INFO  backtype.storm.command.deactivate - Deactivated topology: ExclamationTopology
2015年  4月  9日 木曜日 00:33:20 JST

TopologyRebalance

所要時間：16秒

[root@stormtest storm]# date;bin/storm rebalance ExclamationTopology;date
2015年  4月  9日 木曜日 00:36:22 JST
Start exec_storm_class 2015-04-09 00:36:22
Config get 2015-04-09 00:36:27
Config get and args construct 2015-04-09 00:36:32
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.rebalance ExclamationTopology
691  [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
705  [main] INFO  backtype.storm.command.rebalance - Topology ExclamationTopology is rebalancing
2015年  4月  9日 木曜日 00:36:38 JST

Topology kill

所要時間：16秒

[root@stormtest storm]# date;bin/storm kill ExclamationTopology;date
2015年  4月  9日 木曜日 00:37:21 JST
Start exec_storm_class 2015-04-09 00:37:21
Config get 2015-04-09 00:37:26
Config get and args construct 2015-04-09 00:37:32
Running: java -client -Dstorm.options= -Dstorm.home=/opt/storm-0.9.4 (省略) backtype.storm.command.kill_topology ExclamationTopology
583  [main] INFO  backtype.storm.thrift - Connecting to Nimbus at localhost:6627
605  [main] INFO  backtype.storm.command.kill-topology - Killed topology: ExclamationTopology
2015年  4月  9日 木曜日 00:37:37 JST

4.時間がかかっている場所

上記の結果より、下記のことが言えるようです。

設定ファイルから設定値を読み込む（関数「confvalue」実行）に5秒程かかる
Topologyの起動自体は実は1秒程しかかからない
Topology起動以外のlist/activate/deactivate/rebalance/killは5秒程かかる

そのうち「設定ファイルから設定値を読み込むのに5秒程かかる」については、
下記の通りStormのコマンドを見るに、１項目の設定値を読み込むためにJVMを起動しているためのようではあります。

def confvalue(name, extrapaths):
    global CONFFILE
    command = [
        JAVA_CMD, "-client", get_config_opts(), "-Dstorm.conf.file=" + CONFFILE,
        "-cp", get_classpath(extrapaths), "backtype.storm.command.config_value", name
    ]
    p = sub.Popen(command, stdout=sub.PIPE) #Javaプロセスを起動している！
    output, errors = p.communicate()
    # python 3
    if not isinstance(output, str):
        output = output.decode('utf-8')
    lines = output.split("\n")
    for line in lines:
        tokens = line.split(" ")
        if tokens[0] == "VALUE:":
            return " ".join(tokens[1:])
    return ""

ただ、単純にJVMを起動するのに時間がかかる・・
というだけであれば、Topologyを起動するのに1秒ですむ所が、
やること自体は確実に少ないlist/activate/deactivate/rebalance/killは5秒程かかるのは筋が通らないんですよね。

とまぁ、とりあえずどこが遅いかはわかったので、
何故遅いか、については次回に詳細を追ってみることにします。