Cloud

Cloud Machine Learning 1

[takanashi, GClue]

Docker版のGoogle Datalabを使ってTensorflowのMNISTサンプルをGoogle Cloud PlatformのCloud Machine Learning Engineで実行してみた結果

Dockerイメージ:gcr.io/cloud-datalab/datalab:local
ステップ数:2000 -> 200000に変更
完了 (1 時間 52 分)

Cloud Machine Learning Engineの1ステップの平均計算速度:0.01262331 sec

INFO    2017-03-22 04:55:12 +0000    master-replica-0        Step 199000: loss = 0.00 (0.010 sec)
INFO    2017-03-22 04:55:12 +0000    master-replica-0        Step 199100: loss = 0.00 (0.113 sec)
INFO    2017-03-22 04:55:12 +0000    master-replica-0        Step 199200: loss = 0.00 (0.002 sec)
INFO    2017-03-22 04:55:35 +0000    master-replica-0        Step 199300: loss = 0.00 (0.002 sec)
INFO    2017-03-22 04:55:35 +0000    master-replica-0        Step 199400: loss = 0.00 (0.002 sec)
INFO    2017-03-22 04:55:35 +0000    master-replica-0        Step 199500: loss = 0.00 (0.002 sec)
INFO    2017-03-22 04:55:35 +0000    master-replica-0        Step 199600: loss = 0.00 (0.003 sec)
INFO    2017-03-22 04:55:35 +0000    master-replica-0        Step 199700: loss = 0.00 (0.002 sec)
INFO    2017-03-22 04:55:35 +0000    master-replica-0        Step 199800: loss = 0.00 (0.002 sec)
INFO    2017-03-22 04:55:35 +0000    master-replica-0        Step 199900: loss = 0.00 (0.002 sec)
echo "scale=8; `cat sample-mnist200000-ml.log | grep " sec)" | sed -e 's/^.*(\(.*\)sec).*$/\1/' | awk '{sum+=$1}END{print sum}'`/` cat sample-mnist200000-ml.log | grep " sec)" | wc -l` " | bc
.01262331

ノートPC VM 4コアCPUの1ステップの平均計算速度:0.01048800 sec

Step 199000: loss = 0.00 (0.003 sec)
Step 199100: loss = 0.00 (0.052 sec)
Step 199200: loss = 0.00 (0.002 sec)
Step 199300: loss = 0.00 (0.003 sec)
Step 199400: loss = 0.00 (0.002 sec)
Step 199500: loss = 0.00 (0.002 sec)
Step 199600: loss = 0.00 (0.002 sec)
Step 199700: loss = 0.00 (0.002 sec)
Step 199800: loss = 0.00 (0.002 sec)
Step 199900: loss = 0.00 (0.002 sec)
echo "scale=8; `cat sample-mnist200000-pc.log | grep " sec)" | sed -e 's/^.*(\(.*\)sec).*$/\1/' | awk '{sum+=$1}END{print sum}'`/` cat sample-mnist200000-pc.log | grep " sec)" | wc -l` " | bc
.0104880

ノートPC VM 4コアCPUでの20万ステップのtime実行結果。

real    13m8.613s
user    11m54.476s
sys    16m33.616s

time実行結果のsysの値を見てわかるように分散処理で動作しているため、20万ステップの実行に 0.01048800 * 200000 / 60 = 35 分かかるわけではなく、13分9秒で終わっている。

Cloud Machine Learning Engineを使った場合は、20万ステップの実行に42分かかる計算になるが、完了するまでに1時間52分かかっている。

ログを先頭から見ていくと、タスクを開始するまでに4分かかっている。

Job [sample_mnist200000] submitted successfully.
INFO    2017-03-22 03:03:25 +0000    unknown_task        Validating job requirements...
INFO    2017-03-22 03:03:26 +0000    unknown_task        Job creation request has been successfully validated.
INFO    2017-03-22 03:03:26 +0000    unknown_task        Job sample_mnist200000 is queued.
INFO    2017-03-22 03:03:33 +0000    unknown_task        Waiting for job to be provisioned.
INFO    2017-03-22 03:03:39 +0000    unknown_task        Waiting for TensorFlow to start.
INFO    2017-03-22 03:03:42 +0000    unknown_task        Waiting for TensorFlow to start.
INFO    2017-03-22 03:07:24 +0000    master-replica-0        Running task with arguments: --cluster={"master": ["master-17bf13a583-0:2222"]} --task={"type": "master", "index": 0} --job={

その後プロジェクトの準備が4秒程入ってから学習用pythonが実行される。

INFO    2017-03-22 03:07:28 +0000    master-replica-0        Successfully built trainer
INFO    2017-03-22 03:07:28 +0000    master-replica-0        Installing collected packages: trainer
INFO    2017-03-22 03:07:28 +0000    master-replica-0        Successfully installed trainer-0.0.0
INFO    2017-03-22 03:07:28 +0000    master-replica-0        Running command: python -m trainer.task --train_dir=gs://deepfishing-157205-ml/sample_mnist200000/train
WARNING    2017-03-22 03:07:36 +0000    master-replica-0        From /root/.local/lib/python2.7/site-packages/trainer/task.py:165: merge_all_summaries (from tensorflow.python.ops.logging_ops) is deprecated and will be removed after 2016-11-30.
WARNING    2017-03-22 03:07:36 +0000    master-replica-0        Instructions for updating:
WARNING    2017-03-22 03:07:36 +0000    master-replica-0        Please switch to tf.summary.merge_all.
WARNING    2017-03-22 03:07:36 +0000    master-replica-0        From /usr/local/lib/python2.7/dist-packages/tensorflow/python/ops/logging_ops.py:285: merge_summary (from tensorflow.python.ops.logging_ops) is deprecated and will be removed after 2016-11-30.
WARNING    2017-03-22 03:07:36 +0000    master-replica-0        Instructions for updating:
WARNING    2017-03-22 03:07:36 +0000    master-replica-0        Please switch to tf.summary.merge.
WARNING    2017-03-22 03:07:36 +0000    master-replica-0        The TensorFlow library wasn't compiled to use AVX2 instructions, but these are available on your machine and could speed up CPU computations.
WARNING    2017-03-22 03:07:36 +0000    master-replica-0        The TensorFlow library wasn't compiled to use FMA instructions, but these are available on your machine and could speed up CPU computations.
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Successfully downloaded train-images-idx3-ubyte.gz 9912422 bytes.
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Extracting /tmp/tmpbjWhgY/train-images-idx3-ubyte.gz
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Successfully downloaded train-labels-idx1-ubyte.gz 28881 bytes.
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Extracting /tmp/tmpbjWhgY/train-labels-idx1-ubyte.gz
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Successfully downloaded t10k-images-idx3-ubyte.gz 1648877 bytes.
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Extracting /tmp/tmpbjWhgY/t10k-images-idx3-ubyte.gz
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Successfully downloaded t10k-labels-idx1-ubyte.gz 4542 bytes.
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Extracting /tmp/tmpbjWhgY/t10k-labels-idx1-ubyte.gz
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Step 0: loss = 2.29 (0.076 sec)
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Step 100: loss = 2.15 (0.002 sec)
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Step 200: loss = 1.90 (0.002 sec)

学習開始までに9分程かかるものの、このまま順調にいけば遅くても50分足らずで終わりそうであり、1時間52分かかった理由につながらない。

もう少し見ていくと、6000ステップと6100ステップの間で4分停滞したかのようなログになっている。

INFO    2017-03-22 03:12:49 +0000    master-replica-0        Step 0: loss = 2.29 (0.076 sec)
...
INFO    2017-03-22 03:12:49 +0000    master-replica-0        Step 6000: loss = 0.25 (0.008 sec)
INFO    2017-03-22 03:16:49 +0000    master-replica-0        Step 6100: loss = 0.36 (0.002 sec)

ここではターミナルに出力されたログの時間を見ているので同一秒で6000ステップが実行されたように見えるが、Google Cloud Platformのロギングで見てみると、マイクロ秒単位で時間がかかっているように見える。

12:12:49.404 Step 0: loss = 2.29 (0.076 sec)
...
12:12:49.419 Step 6000: loss = 0.25 (0.008 sec)
12:16:49.642 Step 6100: loss = 0.36 (0.002 sec)

おおよそ、6500ステップまでは一気に分散処理が出来て、次の処理まで3分30秒の停滞がある。

12:12:49.404 Step 0: loss = 2.29 (0.076 sec)
12:12:49.419 Step 6000: loss = 0.25 (0.008 sec)
 6000件, 4分
12:16:49.642 Step 6100: loss = 0.36 (0.002 sec)
12:16:49.661 Step 12900: loss = 0.09 (0.002 sec)
 7000件, 3分
12:19:55.175 Step 13000: loss = 0.16 (0.008 sec)
12:19:55.190 Step 19800: loss = 0.08 (0.109 sec)
 7000件, 3分30秒
12:23:20.978 Step 19900: loss = 0.12 (0.002 sec)
12:23:20.995 Step 26300: loss = 0.09 (0.002 sec)
 6500件, 3分30秒
12:26:55.204 Step 26400: loss = 0.09 (0.112 sec)
12:26:55.219 Step 32900: loss = 0.05 (0.002 sec)
 6500件, 3分30秒
12:30:32.056 Step 33000: loss = 0.13 (0.109 sec)

これでかかる時間を計算してみると、

20万ステップ ÷ 6500ステップ = 30.7回の停滞回数

30.7回 × 3.5分 = 107分 = 1時間47分 (20万ステップの実行時間)

処理終了までに1時間52分(ログ上は1時間54分)かかっているので、そのうち20万ステップの実行に大雑把に1時間47分かかる。(実際はStep0 – 199900に1時間45分)

残りは前後処理で、前処理に9分、後処理に1分30秒。

13:55:35.959 Step 199900: loss = 0.00 (0.002 sec)
13:55:35.960 Training Data Eval:
13:55:35.960 Num examples: 55000 Num correct: 55000 Precision @ 1: 1.0000
13:55:35.960 Validation Data Eval:
13:55:35.960 Num examples: 5000 Num correct: 4890 Precision @ 1: 0.9780
13:55:35.960 Test Data Eval:
13:55:35.960 Num examples: 10000 Num correct: 9776 Precision @ 1: 0.9776
13:55:36.048 Module completed; cleaning up.
13:55:36.048 Clean up finished.
13:55:36.049 Task completed successfully.
13:56:09.123 Tearing down TensorFlow.
13:57:02.387 Finished tearing down TensorFlow.
13:57:09.035 Job completed successfully.

今回はノートPC VM 4コアCPU が13分9秒で終わり、Cloud Machine Learning Engineは1時間52分かかるという結果でしたが、Cloud Machine Learning Engineはトレーニングユニット数を変更できるようですので、ユニット数を増やして試してみたいところです。

気になるGoogle Cloud Platformの今月の請求額

Google Cloud Machine Learning Engine Training time in seconds multiplied by scale. 1.97 hour $0.97
*見込み課金額(税抜き)、毎日更新 合計: $0.97

次回はユニット数を増やすことで、ステップの実行時間を改善できるのか?

というところを見てみたいと思います。

 

Related post

  1. TensorFlow

    スマートフォンに訪れるTensorFlowの波

    今日もTF三昧の佐々木です。CES 2017で、Qualcom…

  2. TensorFlow

    DatalabのTensorFlowを1.0.0aにUpdate

    最近、TF三昧の佐々木です。TensorFlowを学習する際に…

  3. TensorFlow

    TFUG Aizu オープニングイベント&ハンズオン

    1/7,1/8と、お隣会津大学のLictiaで開催された、TFUG A…

  4. TensorFlow

    TFUG Aizu 第二回ハンズオン(2/4開催)

    佐々木です。佐々木が代表を務めるTFUG Aizuのハンズオン…

  5. Cloud

    Lamdba Uploaderの設定

    佐々木です。Lamdbaでは、作ったソースをZIPにかためてA…

  6. TensorFlow

    TFUG Aizu第二回ハンズオンを開催

    佐々木です。TFUG Aizuの第二回ハンズオンを2/4に会津…

Comment

  1. No comments yet.

  1. No trackbacks yet.

最近の記事

  1. GClue

    改良モーターシールド
  2. GClue

    RaspberryPi3でデータを取得して機械学習をしてみる
  3. Cloud

    Cloud Machine Learning 1
  4. Android

    Daydream
  5. TensorFlow

    TFUG Aizu オープニングイベント&ハンズオン
PAGE TOP