AWS DeepRacer で社内レースをやるために、ラップタイムを計測してみた

## はじめに

AWS re:Invent 2018 で発表された DeepRacer の社内レースをやってみました。[当社](https://www.dnp.co.jp)（大日本印刷株式会社）および [グループ会社](https://www.dnp-ds.co.jp/)（株式会社DNPデジタルソリューションズ）からメンバーを募ったところ、予想外に多くのメンバーが集まり、盛大な大会となりました。せっかくなので、得られた知見を公開していこうと思います。


## ルール

AWS の [DeepRacerリーグ](https://aws.amazon.com/jp/deepracer/league/) のルールを参考にしようと思いましたが、公開情報がなさそうでしたので、

**ラップタイム最速が優勝！**

という非常にわかりやすいルールとしました。どんなに完走率が低くても奇跡の一周で挽回可能という、ギャンブル要素の非常に強いルールです。


## ラップタイム取得スクリプト

現時点ではDeepRacer本体は未リリースのため、レースはSageMakerとRoboMakerによるシミュレーション上で実施しました。

競うにあたって、ラップタイムがどこかに出ていないか探しました。しかし、どこにもありませんでした。AWS の担当 SA さんにも確認しましたが、現時点ではどこにも出力されていないようで、CloudWatch Logs のログなどから拾うしかないようです。

そこで今回は、CloudWatch Logs からラップタイムを計算し、競うことにして、以下のスクリプトを作成しました。

**注意**

以下の内容は 2019 年 3 月 18 日時点のサンプルノートブックを対象にしています。
その他のバージョンのノートブックでは利用できない可能性があります。

DeepRacerのサンプルノートブックで Evaluation セルの実行後、以下の内容のセルを作成して実行すると、ラップタイムが表示されます。

```python
import re
from datetime import datetime

def get_log_events(client, log_group_name, log_stream_name, region_name=None):
    get_log_events_response = client.get_log_events(
        logGroupName=log_group_name,
        logStreamName=log_stream_name,
        startFromHead=True)
    yield get_log_events_response['events']

    while True:
        token = get_log_events_response['nextForwardToken']
        get_log_events_response = client.get_log_events(
            logGroupName=log_group_name,
            logStreamName=log_stream_name,
            nextToken=token)
        if get_log_events_response['nextForwardToken'] == token:
            break
        yield get_log_events_response['events']

client = boto3.client('logs')
log_group_name = '/aws/robomaker/SimulationJobs'
 
sim_job_name = response["arn"].split('/')[-1]
print('RoboMaker Simuration Job: ' + sim_job_name)
 
log_stream_response = client.describe_log_streams(
    logGroupName=log_group_name,
    logStreamNamePrefix=sim_job_name
)
 
log_streams = log_stream_response["logStreams"]
 
for log_stream in log_streams:
    log_stream_name = log_stream["logStreamName"]
    print('Log Stream: ' + log_stream_name)

    episode = 0
    started = False
    finished = False
    start_time = 0
    finish_time = 0
    finish_step = 0
    results = []   
    
    for events in get_log_events(client, log_group_name, log_stream_name):
        for event in events:
            if 'SIM_TRACE_LOG' in event['message']:
                trace = re.split('[:,]', event['message'])
                episode = int(trace[1])
                step = int(trace[2])
                total_progress = float(trace[10])
                if step == 0:
                    started = True
                    finished = False
                    start_time = event['timestamp']
                    lap_time = None
                    finish_step = None
                elif total_progress >= 100 and not finished:
                    finished = True
                    finish_time = event['timestamp']
                    lap_time = (finish_time - start_time) / 1000
                    finish_step = step
            elif 'Total Reward' in event['message'] and started:
                
                result = [
                    episode,
                    finished,
                    finish_step,
                    datetime.fromtimestamp(start_time / 1000),
                    datetime.fromtimestamp(finish_time / 1000) if finished else None,
                    lap_time
                ]
                results.append(result)

df = pd.DataFrame(results, index=list(range(1,len(results)+1)), columns=['Episode', 'Finished', 'Step', 'Start At', 'Finished At', 'Lap'])
df
```

結果は以下のように表示されます。

![laptime.png](https://qiita-image-store.s3.amazonaws.com/0/390120/22f3fd15-2ed1-d0fb-c365-1fc4084615d3.png)

## コードの内容

Evaluation を実行すると、CloudWatch Logs に以下のようなトレースログが出力されます。

```
SIM_TRACE_LOG:2,1,2.0100,0.6000,0.0108,0.70,0.20,5,0.5050,0.0000,0,False,True,0.0000,0,0,14.95,1552986927.0073557
```

deepracer_env.py を見ると、

```python
# Trace logs to help us debug and visualize the training runs
        stdout_ = 'SIM_TRACE_LOG:%d,%d,%.4f,%.4f,%.4f,%.2f,%.2f,%d,%.4f,%.4f,%d,%s,%s,%.4f,%d,%d,%.2f,%s\n' % (
        self.episodes, self.steps, self.x, self.y,
        self.yaw,
        self.steering_angle,
        self.throttle,
        self.action_taken,
        self.reward,
        self.total_progress,
        0, #self.get_waypoint_action(), #the expert action at the next waypoint
        self.done,
        self.on_track,
        current_progress,
        0, #self.initidxWayPoint, #starting waypoint for an episode
        self.closest_waypoint_index,
        self.track_length,
        time.time())
        print(stdout_)
```

のように記述されており、step のたびに total_progress が出力されているようですので、step=0 の時点から、total_progress が 100 を超えた時点までの経過時間がラップタイムと言えそうです。

上記のコードでは、Evaluation のシミュレーションジョブのログストリームから全てのログイベントを取得し、経過時間を計算しています。


## まとめ

DeepRacer のラップタイムを取得して、社内でレースをしてみました。

ちなみに、奇跡の一周勝負については参加者からの評判が芳しくなかったので、次回は完走率７割以上、などの条件を付与したいと思います。。