AWS ECSでよく出てくるawslogsの実装を見てみた

Aug 10, 2024
# docker # aws # ecs

なぜ調査した？

仕事でECS Fargateを用いたアプリケーション開発を行ったていたのですが、その中でログ出力がボトルネックになっているケースが出てきました。処理性能が芳しくなかったので、いろいろ試した結果ログ出力の部分（ログ用の文字列生成ではなく標準出力への出力）を除くことで大幅に性能が改善するケースがありました。

改善したのは良かったのですが、そもそもECS FargateからCloudWatchへのログ連携の仕組みがかっておらず、大幅に改善した理由が釈然としなかったため調査してみました。

awslogsの仕組みはどのようになっている？

今まで知らなかったのですが、awslogsドライバーはaws側でなくdocker側が実装しているもののようです。基本的な機能や設定可能なパラメータ等は下記ページにまとまっているため、通常用途であれば下記を参照すれば問題なく実行することが出来るかと思います。 https://docs.docker.com/config/containers/logging/awslogs/

しかし、実装に関する情報がまとまっているドキュメント等は見つけることが出来ませんでした。代わりにログドライバー達はオープンソースで管理されているらしく、実装を見ることが出来ました。（mobyというのはdockerが主導している(?)コンテナ化を促進するためのオープンソースプロジェクトだそうです。知らんかった） https://github.com/moby/moby/blob/master/daemon/logger/awslogs/cloudwatchlogs.go

自分はgolangに明るくないのですが、コメントが丁寧に書かれているので処理の流れは追うことが出来ました。追っていったところ、下記のようにCloudWatchLogsのPutLogEvents APIを呼んでいるようで、特別な仕組みはなくAWS側のAPIを上手いこと呼ぶことでログの連携を行っていることがわかりました。

// putLogEvents wraps the PutLogEvents API
func (l *logStream) putLogEvents(events []types.InputLogEvent, sequenceToken *string) (*string, error) {
	input := &cloudwatchlogs.PutLogEventsInput{
		LogEvents:     events,
		SequenceToken: sequenceToken,
		LogGroupName:  aws.String(l.logGroupName),
		LogStreamName: aws.String(l.logStreamName),
	}
	resp, err := l.client.PutLogEvents(context.TODO(), input)
	if err != nil {
		var apiErr smithy.APIError
		if errors.As(err, &apiErr) {
			log.G(context.TODO()).WithFields(log.Fields{
				"errorCode":     apiErr.ErrorCode(),
				"message":       apiErr.ErrorMessage(),
				"logGroupName":  l.logGroupName,
				"logStreamName": l.logStreamName,
			}).Error("Failed to put log events")
		}
		return nil, err
	}
	return resp.NextSequenceToken, nil
}

この処理を一定時間ごと（コメントを見るとデフォルトでは5秒になる模様、AWS側で設定があるかは未調査）もしくは、一定の量（レコード数?）を超過した場合に上記の関数の仕組みが呼ばれるようです。上記についてデフォルトbloking設定でもそうなるのかやや怪しいですが、下記のような記事もあるため処理がブロックされるのはawslogsドライバーで処理が行われるところまでであり、cloudwatchのAPIを呼ぶところまで必ずログが出力事に行われないということなのかもしれません。 https://nisshiee.org/blog/2019/001

また、awslogsはいい感じにというか勝手にというか1レコードの制限を超えた場合に分割してくれるのですが、そのあたりの実装は下記で行っているようでした。便利だぜ。

// processEvent processes log events that are ready for submission to CloudWatch
// logs.  Batching is performed on time- and size-bases.  Time-based batching occurs
// at the interval defined by awslogs-force-flush-interval-seconds (defaults to 5 seconds).
// Size-based batching is performed on the maximum number of events per batch
// (defined in maximumLogEventsPerPut) and the maximum number of total bytes in a
// batch (defined in maximumBytesPerPut).  Log messages are split by the maximum
// bytes per event (defined in maximumBytesPerEvent).  There is a fixed per-event
// byte overhead (defined in perEventBytes) which is accounted for in split- and
// batch-calculations.  Because the events are interpreted as UTF-8 encoded
// Unicode, invalid UTF-8 byte sequences are replaced with the Unicode
// replacement character (U+FFFD), which is a 3-byte sequence in UTF-8.  To
// compensate for that and to avoid splitting valid UTF-8 characters into
// invalid byte sequences, we calculate the length of each event assuming that
// this replacement happens.
func (l *logStream) processEvent(batch *eventBatch, bytes []byte, timestamp int64) {
	for len(bytes) > 0 {
		// Split line length so it does not exceed the maximum
		splitOffset, lineBytes := findValidSplit(string(bytes), maximumBytesPerEvent)
		line := bytes[:splitOffset]
		event := wrappedEvent{
			inputLogEvent: types.InputLogEvent{
				Message:   aws.String(string(line)),
				Timestamp: aws.Int64(timestamp),
			},
			insertOrder: batch.count(),
		}

		added := batch.add(event, lineBytes)
		if added {
			bytes = bytes[splitOffset:]
		} else {
			l.publishBatch(batch)
			batch.reset()
		}
	}
}

コンテナ本体からどうようにログドライバに連携されている？

公式ドキュメントにもあるように、標準ではSTDOUTやSTDERRに出力されたものがログドライバによって処理されます。が、ここの連携がどうされているのかは調べられていないので、いつか調べたいです…。

なぜ遅くなった？

ログが膨大に出力される場合は、上述の通り外部API（PutLogEvents API）が呼ばれます。また、PutLogEvents APIでのリクエストサイズの上限もあるため高頻度で外部APIが実行される可能性があります。

外部APIの呼び出しにかかる時間が、通常のアプリケーション実行にも影響を与えて処理のボトルネックになるケースがあるものと考えています。（コンテナのCPUを全然使いきれてないのに性能が出ない時とかは疑っても良いのかなと思います）

awslogsがボトルネックになっている場合の対策は？

上記の仮説が正しい場合は、PutLogEvents APIの呼び出し回数を減らすことが直接的な改善策になります。そのため

ログ出力をしない
ログに出力する内容を精査するというようなことが対策として有効となってきます。

終わりに

ECSからCloudWatchLogsへの連携は魔法のように無条件にスケールしていくような感覚（実態が違うのはわかっていても実践値ではそれに近いような感覚）を持っていました。しかし、蓋を開けてみると意外と普通にAPIを呼たりして急に身近なものに感じられるようになってきたと共に、ボトルネックになりそう部分が見えてくるようになりました。

実装が公開されているものばかりではないですが、見れるものは少しずつ見ていきたいなあと思った日でした。