2022-12-16

Pythonのbytesはsubscriptでコピーが発生する

TL;DR

Pythonのbytesはsubscriptでmemmoveする。

背景

Pythonで簡単なバイナリのパーサーを書いていたとき、そんなに入力が大きくない(1.6MB程度)のに処理に時間がかかることに気づいた。

調査

まず当該プログラムをcProfileを使ってプロファイリングしてみた。しかし、原因の特定につながるような情報は得られなかった。次にInstrumentsを用いてプロファイリングを行った。

bytes_subscript から呼ばれている memmove がボトルネックになっていることがわかった。

考察

思い当たる節はバイナリのパーサーで特定のオフセットから指定したバイト数取り出す際に普段書かない方法で書いていたことだった。

普段は以下のように書く。

b[offset:offset+size]

しかし今回は試作のプログラムで以下のように書いていた。

b[offset:][:size]

両者は基本的に同じ結果を返す。ではなぜ後者の書き方をしていたかと言うと例でもそうだが下のコードのほうが短い。特に今回のプログラムはoffsetの部分に変数同士の計算した式が書いてありコピーするのが億劫だったため後者の書き方をしていた。

そして部分バイト列を取り出す際に内部的にviewのようなものが作られると思い込んでいたため問題ないと判断したが誤りだった。

bytes は subscript でコピーが発生するので前者はsizeバイトのmemmove, 後者はlen(b)-offset+sizeバイトのmemmoveが実行される。この部分バイト列を取り出す処理が頻繁に呼び出されていたため問題になった。

結論

b[offset:offset+size]

の形に書き直したところ10倍ほど速くなった。

Pythonのbytesのsubscriptはmemmoveが発生することを把握しておくと良い。

再現するスクリプトと結果

b = ("b"*1000000).encode()

def before():
  for i in range(len(b)):
    b[i:][:2]

def after():
  for i in range(len(b)):
    b[i:i+2]

if __name__ == "__main__":
  import timeit
  print("before:", timeit.timeit(before, number=1))
  print("after:", timeit.timeit(after, number=1))

出力:

before: 20.346244589949492
after: 0.10111576301278546

2022-10-31

JavaにおけるHeapのClassHistogramを取得する複数の方法とその違い

TL;DR

方法	Full GCの有無	タイミング	条件
JFR の jdk.ObjectCount	あり	定期的	JFRが使える
-XX:+PrintClassHistogram	あり	シグナル受信時	JDK 1.4.2~
jmap -histo:live	あり	実行時	JDK 1.4.2~
jcmd GC.class_histogram	あり	実行時	JDK 7~
jmap -histo	なし	実行時	JDK 1.4.2~
jcmd GC.class_histogram -all	なし	実行時	JDK 7~
-XX:+PrintClassHistogramBeforeFullGC	なし	Full GC 前	JDK 6(?)~8
-XX:+PrintClassHistogramAfterFullGC	なし	Full GC 後	JDK 6(?)~8
-Xlog:classhisto*=trace	なし	Full GC 前後	JDK 9~

はじめに

JavaにおけるHeapのClassHistogramを取得する方法が複数種類あり、それぞれの違いがわからなかったので調べた。

実装の詳細については f3ca0cab75f2faf9ec88f7a380490c9589a27102 時点の openjdk/jdk の情報を元にしている。

github.com

過去のバージョン時点でも同様の挙動であるとは限らない。

OpenJDK から得た情報なので 6 より前の情報は正確でない可能性がある。

-XX:+PrintClassHistogram を使う

Java 1.4.2 からあるオプションで CONTROL + BREAK を外部から送ったタイミングでログに出力される。生存しているオブジェクトのみを出力するために Full GC をトリガーする。

Signal Dispatcher スレッド (signal_thread_entry) -> VMThread::execute(VM_GC_HeapInspection)

VM_GC_HeapInspection が実体。

jmap -histo を使う

Java 1.4.2 からあるツールで VM にアタッチして heapinspect を実行する。

Attach Listener スレッド(attach_listener_thread_entry) -> heap_inspection -> VMThread::execute(VM_GC_HeapInspection) という流れで処理される。

VM_GC_HeapInspection が実体。 live というオプションを付けると Full GC をトリガーする。

jcmd GC.class_histogram を使う

Java 7 からあるツールで VM にアタッチして jcmd を実行する。

Attach Listener スレッド(attach_listener_thread_entry) -> jcmd -> DCmd::parse_and_execute -> ClassHistogramDCmd::execute -> VMThread::execute(VM_GC_HeapInspection) という流れで処理される。

VM_GC_HeapInspection が実体。

-all をつけると Full GC をトリガーしない。

-XX:+PrintClassHistogramBeforeFullGC -XX:+PrintClassHistogramAfterFullGC を使う

Full GC が発生する/したタイミングで出力される。 STW の時間が増加するが自動で出力される。

ClassHistogram は Full GC の前後で見たいことが多いので一番良さそう。

-Xlog:classhisto*=trace

-XX:+PrintClassHistogramBeforeFullGC と -XX:+PrintClassHistogramAfterFullGC は Java 9 からの JEP 271 で削除され -Xlog:classhisto*=trace に変更された。基本的に同じもの。どちらか片方のみを有効にすることができなくなった。

JFR の jdk.ObjectCount を使う

これを JFR で有効にすると VM_GC_SendObjectCountEvent(VM_GC_HeapInspection)　によって毎回 Full GC がトリガーされる。 jfr configure で gc の項目を all にすると jdk.ObjectCount が有効な jfc が生成される。

VM_GC_HeapInspection

VM_GC_HeapInspection は safepoint で評価されるので STW が Full GC の有無に関わらず発生する。

まとめ

方法	Full GCの有無	タイミング	条件
JFR の jdk.ObjectCount	あり	定期的	JFRが使える
-XX:+PrintClassHistogram	あり	シグナル受信時	JDK 1.4.2~
jmap -histo:live	あり	実行時	JDK 1.4.2~
jcmd GC.class_histogram	あり	実行時	JDK 7~
jmap -histo	なし	実行時	JDK 1.4.2~
jcmd GC.class_histogram -all	なし	実行時	JDK 7~
-XX:+PrintClassHistogramBeforeFullGC	なし	Full GC 前	JDK 6(?)~8
-XX:+PrintClassHistogramAfterFullGC	なし	Full GC 後	JDK 6(?)~8
-Xlog:classhisto*=trace	なし	Full GC 前後	JDK 9~

余談1

https://github.com/openjdk/jdk/blob/f3ca0cab75f2faf9ec88f7a380490c9589a27102/src/jdk.jcmd/share/classes/sun/tools/jmap/JMap.java#L198-L199

// inspectHeap is not the same as jcmd GC.class_histogram

というコメントがあるが jmap -histo で実行する inspectheap は jcmd GC.class_histogram と同様の処理をする。 jmap -histo と等価なのは jcmd GC.class_histogram -all だという主張なら理解できる。

余談2

https://docs.oracle.com/en/java/javase/19/docs/specs/man/java.html

-XX:+PrintClassHistogram Setting this option is equivalent to running the jmap -histo command, or the jcmd pid GC.class_histogram command, where pid is the current Java process identifier.

と書いてあるが -XX:+PrintClassHistgoram と厳密に等価なのは jmap -histo:live と jcmd GC.class_histogram だと思われる。

jmap だけデフォルトが Full GC をトリガーしないところため注意が必要だと思われる。

参考リンク

2022-08-24

「CPythonのソースコードを読んでみた」を読んで

背景

inside.estie.co.jp

を読んでExステージについて検証したくなったので

alloc_bytes と alloc_list の速度差について

python 3.11
intel mac

def alloc_bytes(size):
  return b"ABCDEFGH" * size

while True:
  alloc_bytes(1024**2 * 128)

def alloc_list(size):
  return [0, 1] * size

while True:
  alloc_list(1024**2 * 64)

の2つを大体時間実行して Instruments の Time Profiler を用いて観察した。

$ python3 bytes.py

Weight     Self    Weight    Symbol Name
 21.13 s  100.0%        0 s     python3.11 (51417)
 21.13 s  100.0%        0 s      start
 21.13 s  100.0%        0 s       Py_BytesMain
 21.13 s  100.0%        0 s        pymain_main
 21.13 s  100.0%        0 s         Py_RunMain
 21.13 s  100.0%        0 s          _PyRun_AnyFileObject
 21.13 s  100.0%        0 s           _PyRun_SimpleFileObject
 21.13 s  100.0%        0 s            PyEval_EvalCode
 21.13 s  100.0%        0 s             _PyEval_EvalFrameDefault
 21.09 s   99.8%        0 s              bytes_repeat
 21.09 s   99.8%    21.09 s               _platform_memmove$VARIANT$Haswell
38.00 ms    0.1%    1.00 ms              _PyObject_Free

$ python3 list.py

Weight    Self   Weight  Symbol Name
20.93 s  100.0%     0 s     python3.11 (51455)
20.93 s  100.0%     0 s      start
20.93 s  100.0%     0 s       Py_BytesMain
20.93 s  100.0%     0 s        pymain_main
20.93 s  100.0%     0 s         Py_RunMain
20.93 s  100.0%     0 s          _PyRun_AnyFileObject
20.93 s  100.0%     0 s           _PyRun_SimpleFileObject
20.93 s  100.0%     0 s            PyEval_EvalCode
20.93 s  100.0%     0 s             _PyEval_EvalFrameDefault
14.84 s   70.8% 14.84 s              list_repeat
 6.09 s   29.1%  6.06 s              list_dealloc

github.com

bytesobject は methane さんによって tp_dealloc が必要なくなっていて、listobject は tp_dealloc の際に要素をすべて走査して deref している分重いというのが速度差の原因ではないか。

2022-02-13

How to stop running out of ephemeral ports and start to love long-lived connections の副読本

https://blog.cloudflare.com/how-to-stop-running-out-of-ephemeral-ports-and-start-to-love-long-lived-connections/

を読んでいて理解できなかったところをまとめた記事です。

元記事の簡単な概要

エフェメラルポートが枯渇しないようにローカルポートの再利用をしたい。

TCP の普通のユースケースでは自動で再利用されるので困らない。

送信元アドレスを固定する場合はうまく再利用できなかったが 2015 年から IP_BIND_ADDRESS_NO_PORT が追加され問題なく再利用できるようになった。

送信元ポートも固定する場合は SO_REUSEADDR を使うことで再利用ができる。

ところが UDP ではローカルポートの再利用がうまく動かないし、TCP のような簡単な回避策はない。

いかにして UDP でローカルポートの再利用を達成するかの試行錯誤が書かれている。

詳細は元記事を参照。

元記事で理解できなかったところ

理解できなかったのは以下の2点です。

SO_REUSEADDR as a lock でのロックメカニズム
connectx の実装例における _netlink_udp_lookup の挙動

主に UDP についての箇所が理解できなかったのでそれを掘り下げていきます。

前提

この記事は linux 5.16.8 の時点の情報をもとに書かれています。

linux におけるソケットはユーザーランドからは socket という構造体が見えていますが、カーネルランドでは sock という構造体です。

sk という変数名で頻繁に登場します。

sockの説明

この記事で扱うソケットは主に AF_INET というアドレスファミリを持つソケットです。

IPv4 と IPv6 でも挙動が異なりますが、この記事では IPv4 を扱います。

UDP のソケットは udp_table という構造体で管理されています。

udp_tableの説明

udp_table には hash, hash2 という2つのハッシュテーブルがあり2種類の検索を行うことができます。

hash はキーがローカルポートで, hash2 はキーがローカルポートとローカルアドレスになっています。

ハッシュテーブルのキーごとに存在するのがスロットで、スロットは連結リストでエントリを複数保持します。

udp_table におけるエントリは sock 構造体です。

hashのときの構造例

bind の挙動

bind は IP_BIND_ADDRESS_NO_PORT (linux 4.2 以降) が設定されていなければ、その時点でローカルポートを確定します。

ローカルポートの確定方法はプロトコルによって異なります。

プロトコルによって異なる処理は sk_prot で抽象化されています。実態は tcp なら tcp_prot、udp なら udp_prot です。

ローカルポートの確定のための処理は get_port です。

UDP の場合の処理を追っていきます。

udp_prot の get_port は udp_v4_get_port という関数が指定されています。

ローカルポートが指定されていない場合はローカルポートレンジから使用中ではないローカルポートを取得します。

ローカルポートが指定されている場合はそのローカルポートが使用中かどうかを調べます。

使用中か調べるための関数は udp_lib_lport_inuse です。

udp_table の hash を用いることで同一ローカルポートを使っているソケットを列挙することができます。

hash からソケットのリストを走査し、

ローカルポートが等しい
どちらかが SO_REUSEADDR=1 を設定していない
ローカルアドレスが等しい、またはどちらかがワイルドカードである
どちらかが SO_BINDTODEVICE で明示的にバインドするデバイスが指定されている場合、同じデバイスがバインドされている
どちらかが SO_REUSEPORT=1 を設定していない、またはソケットに紐づく uid が異なる

以上の条件をすべて満たすソケットが存在するときにそのローカルポートは使用中とみなします。

簡単に言うとローカルポート、ローカルアドレスが等しい、SO_REUSEADDR=1 も SO_REUSEPORT=1 も設定されていないソケットがある場合、そのローカルポートは使用中とみなされます。

指定したローカルポートが使用中でない、ローカルポートレンジから使用中ではないローカルポートが取得できた場合 bind は成功します。

成功した場合、udp_table の hash と hash2 の対応するスロットの先頭にエントリとしてソケットを追加します。

新しく bind されたソケット

余談: SO_REUSEADDR or SO_REUSEPORT?

UDP における SO_REUSEADDR と SO_REUSEPORT の使い分けは異なるユーザでアドレスとポートを共有するかで異なるということです。

異なるユーザで共有することを想定してない場合は SO_REUSEPORT を使うのが望ましいでしょう。

つまり UDP で接続情報の衝突判定を行わなずに SO_REUSEADDR=1 か SO_REUSEPORT=1 を指定すると接続先が同一かつローカルポートが重複した場合に overshadowing が発生してしまうということです。

クライアントとして UDP を使う場合は SO_REUSEADDR, SO_REUSEPORT を指定するのは慎重になったほうが良いでしょう。(そもそも意味なくオプションを指定することはないと思いますが)

SOCK_DIAG_BY_FAMILY の挙動

https://man7.org/linux/man-pages/man7/sock_diag.7.html

man にはインターフェースは書かれていましたがどういう挙動をするのかわからなかったのでソースコードから調査しました。

netlink インターフェースに対して SOCK_DIAG_BY_FAMILY を要求したとき __sock_diag_cmd で処理が行われます。

アドレスファミリごとに処理をするハンドラが異なり、AF_INET の場合は inet_diag_handler が登録されています。

ハンドラの dump が実行されます、inet_diag_handler では inet_diag_handler_cmd が呼び出されます。

SOCK_DIAG_BY_FAMILY で NLM_F_DUMP が有効でない場合には inet_diag_cmd_exact で処理されます。

プロトコルごとに処理するハンドラが異なり、UDP の場合は udp_diag_handler が登録されています。

ハンドラの dump_one が実行されます、udp_diag_handler では udp_diag_dump_one が呼び出されます。

udp_diag_dump_one は udp_dump_one を呼び出すだけです。

udp_dump_one は AF_INET の場合 __udp4_lib_lookup でソケットの検索を行います。

MEMO:

ソースコードを読む人向けですが udp_dump_one に src and dst are swapped for historical reasons というコメントがあり以降の関数では命名は変わらず用途が逆転します。注意してください。

これによって netlink インターフェースに SOCK_DIAG_BY_FAMILY を要求したときに TCP でも UDP でも src と dst を逆にしないと望んだ結果は得られません。

TCP の場合は inet_diag_find_one_icsk で後続の関数に渡すときに src と dst を入れ替えているので素直にソースコードを読むことができます。

__udp4_lib_lookup では udp4_lib_lookup2 関数を用います。

udp4_lib_lookup2 は udp_table の hash2 のローカルポートとローカルアドレスと紐づくスロットを走査し最もリクエストに一致する有効なソケットを返します。

有効で一致度が等しいソケットが複数存在する場合、走査順が早いソケットが優先されます。

以下の条件を一つでも当てはまるソケットを無効なソケットとして扱います。

リクエストされた送信元ポートとソケットの送信元ポートが一致しない
リクエストされた送信元アドレスとソケットの送信元アドレスが一致しない
ソケットに送信先アドレスが存在し、リクエストされた送信先アドレスと一致しない
ソケットに送信先ポートが存在し、リクエストされた送信先ポートと一致しない
ソケットが特定のデバイスにバウンドされていていて、リクエストされたデバイスと一致しない

リクエストとソケットの一致度を計算する関数が net/ipv4/udp.c に存在する compute_score です。

ソケットのアドレスファミリーが AF_INET である場合 2 点, そうでない場合 1 点
ソケットに送信先アドレスが存在し、リクエストされた送信先アドレスと一致する場合 4 点
ソケットに送信先ポートが存在し、リクエストされた送信先ポートと一致する場合 4 点
ソケットが特定のデバイスにバウンドされている場合 4点
ソケットに対して来たパケットを処理したCPUコアと現在のCPUコアが一致する場合 1 点

すべてを合計した結果が一致度として計算されます。

有効なソケットが存在しなかった場合、リクエストされた送信先アドレスをワイルドカードアドレスにして再度 udp4_lib_lookup2 を呼び出します。得られたソケットの情報、SO_COOKIE の値を返します。

_connectx_udp の挙動

https://github.com/cloudflare/cloudflare-blog/blob/1250f5ea922d543900d82658d7a78939d122fd89/2022-02-connectx/connectx.py#L116-L166

まずソケットを一意に識別できる値 SO_COOKIE を getsocketopt で取得します。

次にローカルアドレスとローカルポートを再利用するために setsocketopt で SO_REUSEADDR=1 にします。

そして bind を実行します、これは失敗する場合がありますが後述します。

他のソケットが同一のローカルアドレス、ローカルポートで bind できないように setsocketopt で SO_REUSEADDR=0 にします。

bind の挙動で説明した通り同一のローカルアドレス、ローカルポートで bind しているソケットに SO_REUSEADDR=0 のソケットが存在する場合、ローカルポートは使用中であるとみなされます。

つまりこれ以降、同一のローカルアドレス、ローカルポートへの bind が失敗するようになります。

通常では同一のローカルアドレス、ローカルポートではすべてのソケットが SO_REUSEADDR=1 か単一のソケットが SO_REUSEADDR=0 にしかなりませんがその前提が壊れます。

カーネル側から想定されていない状態ですが致命的な問題は発生してないので許容しています。

bind が成功して SO_REUSEADDR=0 にする前に複数のソケットが同一ローカルアドレス、ローカルポートで bind に成功している可能性があります。 _netlink_udp_lookup を呼び出して同一接続情報のソケットが存在するか確認します。

_netlink_udp_lookup は完全に一致するソケットがあればそのソケットの SO_COOKIE の値を返します。

完全に一致するソケットがない場合は同一送信元アドレス、同一送信元ポートのソケットで送信先アドレス、送信先ポートが未定のソケットの SO_COOKIE の値を返します。

複数存在する場合は走査順で早いソケットの SO_COOKIE の値を返します。

ソケットは bind が成功するたびにハッシュテーブルのスロットの先頭に追加されるので一番最後に bind が成功したソケットの SO_COOKIE の値になります。

_netlink_udp_lookup で返ってきた SO_COOKIE の値と最初に取得した SO_COOKIE を比較して一致してない場合に失敗とします。

完全に一致するソケットがある場合はすべてのソケットが失敗し、それ以外の場合だと最後に bind に成功したソケット以外は失敗します。

最後に bind に成功したソケットは connect を行います。

試行の成否に関わらずソケットは SO_REUSEADDR=1 に戻し、再度同一ローカルポート、ローカルアドレスの再利用ができる状態にします。

まとめると

一時的に SO_REUSEADDR=0 にすることでローカルアドレス、ローカルポート単位で bind を制限します。

新規に bind ができない区間では _netlink_udp_lookup の結果が一意になります。

ローカルアドレス、ローカルポート単位で同時に一つのソケットしか connect できないようになっています。

これによりローカルアドレスとローカルポートを再利用しつつ、同一接続情報のソケットが作られないようにできます。

SO_REUSEADDR をロックのように使って SOCK_DIAG_BY_FAMILY で衝突判定を行うという手法です。

余談: TCP でローカルポートが積極的に再利用されるのはなぜ？

TCP の場合だとローカルアドレス、ローカルポートの再利用が普通に行われます。

https://elixir.bootlin.com/linux/v5.16.8/source/include/net/inet_hashtables.h#L42

以上のコメントを読んで FTP に言及されており、TCP で最適化が進んだのは FTP があったからなのではと思いました。

個人の感想レベルなのでより正確な情報を知っている方は教えていただけると幸いです。

終わりに

これは会社の勉強会で話すために調査し、話した内容をまとめたものです。

議論を深めるきっかけをくれた勉強会の参加者の皆さんありがとうございました。

2021-12-15

docker pull を速くするために：layer-parallel から chunk-parallel へ

この記事は Recruit Advent Calendar 2021 の15日目の記事です。

TL;DR

従来のレイヤー並列の pull より Range リクエストを用いたチャンク並列の pull によって速度が 2~5倍速くなる可能性がある。

ECR は Public だと region ごとに速度が大きく異るので安定した速度を求める場合は Private にする。 (pull through cache を活用すると良い)

2022/10/9 追記: ECR の Public が適切な Pop から返ってくるようになっていた。その Benchmark も取得し、結果を追記した。 ap-northeast-1 では6倍近く早くなっていて region による差が小さくなっていた。

背景・動機

コンテナイメージは一つ以上のマニフェスト、そこから得られるコンフィグとレイヤーから構成される。

コンテナイメージの pull という操作は以上の情報をコンテナレジストリから取得することである。

具体的にどういう処理をしているかは以下を参照。

https://knqyf263.hatenablog.com/entry/2019/11/29/052818

https://github.com/moby/moby/blob/8955d8da8951695a98eb7e15bead19d402c6eb27/contrib/download-frozen-image-v2.sh

pull はコンテナの実行、ビルドに際して必要になることが多い。

CI/CD の様々なタイミングで pull が必要なので速くすることに意義がある。

dockerd、containerd はデフォルトで3並列でのレイヤー取得を行う。 (layer-parallel)

配布されているイメージは単一レイヤーのものもあり、単一レイヤーの場合はレイヤー並列化のメリットがない。

複数レイヤーの場合でもレイヤーのサイズにばらつきがあることがほとんどである。

コンテナイメージの取得時間はレイヤーの最大サイズに大きく影響をうける。

最もサイズの大きいレイヤーの取得を待っている時間が長いと感じたこともあるのではないだろうか。

chunk-parallel

レイヤーを一定のバイト数に分割したものをチャンクと呼ぶ。

Range リクエスト [RFC7233] を用いたチャンク並列で pull をすることで高速化を図る。

Docker Registry API v2 では Range リクエストを MAY、SHOULD でサポートすると書いてある。

https://docs.docker.com/registry/spec/api/#pulling-a-layer

To allow for incremental downloads, Range requests should be supported, as well.

https://docs.docker.com/registry/spec/api/#fetch-blob-part

This endpoint may also support RFC7233 compliant range requests. Support can be detected by issuing a HEAD request.

OCI Distribution Spec では言及されていない。過去には detail.md で言及されていたが現在では削除されている。

ECR ではサポートしていることがわかっている。裏側が Object Storage になっているレジストリであればサポートしている可能性は高い。

レイヤー並列ではなくチャンク並列の pull にすることで単一レイヤーの場合でも並列に取得することが可能になる。更にレイヤーサイズの偏りの影響を受けづらくなる。

実験

マニフェストの取得、レイヤーの取得までを行うツールを作成し、チャンク並列(チャンク数1、2、4、8)で実験を行った。

https://github.com/orisano/chunpull

今回は pull の制限がない ECR で public.ecr.aws の datadog/agent の amd64 のイメージ(圧縮後248MB)を用いた。

ECR Public/Private は構成が異なるので別々に実験を行った。

ECR Public が返す CloudFront の Pop が期待するものではなかったので ap-northeast-1、us-west-2 での比較実験を行った。

Benchmark は hyperfine を用いて warmup 2回、計測 10回で行った。

ECR Public - ap-northeast-1 (SF, SEA)

Benchmark 1: ./chunpull -i datadog/agent -c 10 -n 1
  Time (mean ± σ):     12.521 s ±  1.063 s    [User: 0.564 s, System: 0.559 s]
  Range (min … max):   11.193 s … 14.220 s    10 runs

Benchmark 2: ./chunpull -i datadog/agent -c 10 -n 2
  Time (mean ± σ):      8.562 s ±  0.301 s    [User: 0.604 s, System: 0.587 s]
  Range (min … max):    7.874 s …  8.982 s    10 runs

Benchmark 3: ./chunpull -i datadog/agent -c 10 -n 4
  Time (mean ± σ):      5.936 s ±  0.086 s    [User: 0.624 s, System: 0.580 s]
  Range (min … max):    5.794 s …  6.047 s    10 runs

Benchmark 4: ./chunpull -i datadog/agent -c 10 -n 8
  Time (mean ± σ):      4.263 s ±  0.037 s    [User: 0.640 s, System: 0.564 s]
  Range (min … max):    4.223 s …  4.344 s    10 runs

Summary
  './chunpull -i datadog/agent -c 10 -n 8' ran
    1.39 ± 0.02 times faster than './chunpull -i datadog/agent -c 10 -n 4'
    2.01 ± 0.07 times faster than './chunpull -i datadog/agent -c 10 -n 2'
    2.94 ± 0.25 times faster than './chunpull -i datadog/agent -c 10 -n 1'

2022/10/09 追記: ECR Public - ap-northeast-1 (NRT57-P3)

Benchmark 1: ./chunpull -i datadog/agent -c 10 -n 1
  Time (mean ± σ):      2.083 s ±  0.060 s    [User: 0.512 s, System: 0.421 s]
  Range (min … max):    1.995 s …  2.188 s    10 runs

Benchmark 2: ./chunpull -i datadog/agent -c 10 -n 2
  Time (mean ± σ):      1.739 s ±  0.101 s    [User: 0.462 s, System: 0.421 s]
  Range (min … max):    1.641 s …  1.944 s    10 runs

Benchmark 3: ./chunpull -i datadog/agent -c 10 -n 4
  Time (mean ± σ):      2.145 s ±  0.610 s    [User: 0.483 s, System: 0.446 s]
  Range (min … max):    1.872 s …  3.871 s    10 runs

Benchmark 4: ./chunpull -i datadog/agent -c 10 -n 8
  Time (mean ± σ):      1.849 s ±  0.037 s    [User: 0.470 s, System: 0.413 s]
  Range (min … max):    1.810 s …  1.926 s    10 runs

Summary
  './chunpull -i datadog/agent -c 10 -n 2' ran
    1.06 ± 0.07 times faster than './chunpull -i datadog/agent -c 10 -n 8'
    1.20 ± 0.08 times faster than './chunpull -i datadog/agent -c 10 -n 1'
    1.23 ± 0.36 times faster than './chunpull -i datadog/agent -c 10 -n 4'

Pop が正常に返るようになって chunk-parallel の効果がなくなったように見える。 2021/12 時点と比較すると6倍近く早くなっていて ECR Public ユーザーだと体感しているかもしれない。

ECR Private - ap-northeast-1

Benchmark 1: ./chunpull -r https://xxx.dkr.ecr.ap-northeast-1.amazonaws.com -i chunpull -c 10 -n 1
  Time (mean ± σ):      2.889 s ±  0.289 s    [User: 0.285 s, System: 0.285 s]
  Range (min … max):    2.761 s …  3.709 s    10 runs

  Warning: The first benchmarking run for this command was significantly slower than the rest (3.709 s). This could be caused by (filesystem) caches that were not filled until after the first run. You should consider using the '--warmup' option to fill those caches before the actual benchmark. Alternatively, use the '--prepare' option to clear the caches before each timing run.

Benchmark 2: ./chunpull -r https://xxx.dkr.ecr.ap-northeast-1.amazonaws.com -i chunpull -c 10 -n 2
  Time (mean ± σ):      1.508 s ±  0.021 s    [User: 0.300 s, System: 0.315 s]
  Range (min … max):    1.484 s …  1.542 s    10 runs

Benchmark 3: ./chunpull -r https://xxx.dkr.ecr.ap-northeast-1.amazonaws.com -i chunpull -c 10 -n 4
  Time (mean ± σ):     862.5 ms ±  13.8 ms    [User: 287.9 ms, System: 311.0 ms]
  Range (min … max):   843.1 ms … 883.8 ms    10 runs

Benchmark 4: ./chunpull -r https://xxx.dkr.ecr.ap-northeast-1.amazonaws.com -i chunpull -c 10 -n 8
  Time (mean ± σ):     574.0 ms ±  40.6 ms    [User: 301.4 ms, System: 343.8 ms]
  Range (min … max):   527.6 ms … 655.9 ms    10 runs

Summary
  './chunpull -r https://xxx.dkr.ecr.ap-northeast-1.amazonaws.com -i chunpull -c 10 -n 8' ran
    1.50 ± 0.11 times faster than './chunpull -r https://xxx.dkr.ecr.ap-northeast-1.amazonaws.com -i chunpull -c 10 -n 4'
    2.63 ± 0.19 times faster than './chunpull -r https://xxx.dkr.ecr.ap-northeast-1.amazonaws.com -i chunpull -c 10 -n 2'
    5.03 ± 0.62 times faster than './chunpull -r https://xxx.dkr.ecr.ap-northeast-1.amazonaws.com -i chunpull -c 10 -n 1'

ECR Public - us-west-2 (HIO)

Benchmark 1: ./chunpull -i datadog/agent -c 10 -n 1
  Time (mean ± σ):      2.359 s ±  0.192 s    [User: 0.452 s, System: 0.355 s]
  Range (min … max):    2.194 s …  2.847 s    10 runs

Benchmark 2: ./chunpull -i datadog/agent -c 10 -n 2
  Time (mean ± σ):      1.725 s ±  0.100 s    [User: 0.428 s, System: 0.374 s]
  Range (min … max):    1.586 s …  1.878 s    10 runs

Benchmark 3: ./chunpull -i datadog/agent -c 10 -n 4
  Time (mean ± σ):      1.490 s ±  0.144 s    [User: 0.419 s, System: 0.368 s]
  Range (min … max):    1.342 s …  1.857 s    10 runs

Benchmark 4: ./chunpull -i datadog/agent -c 10 -n 8
  Time (mean ± σ):      1.451 s ±  0.341 s    [User: 0.431 s, System: 0.361 s]
  Range (min … max):    1.289 s …  2.412 s    10 runs

  Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet PC without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options.

Summary
  './chunpull -i datadog/agent -c 10 -n 8' ran
    1.03 ± 0.26 times faster than './chunpull -i datadog/agent -c 10 -n 4'
    1.19 ± 0.29 times faster than './chunpull -i datadog/agent -c 10 -n 2'
    1.63 ± 0.40 times faster than './chunpull -i datadog/agent -c 10 -n 1'

Benchmark 1: ./chunpull -i datadog/agent -c 10 -n 1
  Time (mean ± σ):      2.431 s ±  0.178 s    [User: 0.449 s, System: 0.367 s]
  Range (min … max):    2.145 s …  2.681 s    10 runs

Benchmark 2: ./chunpull -i datadog/agent -c 10 -n 2
  Time (mean ± σ):      1.730 s ±  0.103 s    [User: 0.422 s, System: 0.386 s]
  Range (min … max):    1.611 s …  1.921 s    10 runs

Benchmark 3: ./chunpull -i datadog/agent -c 10 -n 4
  Time (mean ± σ):      1.675 s ±  0.554 s    [User: 0.442 s, System: 0.366 s]
  Range (min … max):    1.339 s …  3.238 s    10 runs

  Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet PC without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options.

Benchmark 4: ./chunpull -i datadog/agent -c 10 -n 8
  Time (mean ± σ):      1.317 s ±  0.064 s    [User: 0.395 s, System: 0.361 s]
  Range (min … max):    1.246 s …  1.404 s    10 runs

Summary
  './chunpull -i datadog/agent -c 10 -n 8' ran
    1.27 ± 0.42 times faster than './chunpull -i datadog/agent -c 10 -n 4'
    1.31 ± 0.10 times faster than './chunpull -i datadog/agent -c 10 -n 2'
    1.85 ± 0.16 times faster than './chunpull -i datadog/agent -c 10 -n 1'

結果

AWS上の環境ではチャンク並列にすることで速度が改善することがわかった。

ap-northeast-1 だと Public / Private に関わらず並列数に近い速度改善が見られる。

us-west-2 だと Public でも十分に速いが並列化の恩恵は小さい。

ECRの特性?

ap-northeast-1 と us-west-2 では public.ecr.aws からの pull でも5倍近く時間が違う。(平均12秒 => 平均2.4秒)

これは ap-northeast-1 から pull しても Cloud Front の Pop が SEA か SF で返ってきていることが原因だと思われる。

ECR Public と ECR Private を比較した場合 Private には Cloud Front が存在していないが 4倍近く速い。(平均12秒 => 平均2.9秒)

解決していない問題

何故か家の環境からだと chunk parallel にしてもどこかでスロットリングされているのか速度が向上しなかった。

ECR の pull through cache が動かなかった。

ECR Public が ap-northeast-1 と家の環境からアクセスしても SF、SEA の CloudFront から返ってくるのはなぜか。

レイヤー数、レイヤーサイズの分布の調査をする必要がある。

Pull の制限があるレジストリだと早く制限に到達する可能性がある。

使用するメモリ使用量が増加する or ファイルアクセスの回数が増える。

ECR は一定の割合でレイテンシがスパイクすることがあり、チャンク並列でリクエスト数が多くなるとレイテンシが増加する恐れがある。

チャンク数、チャンクサイズ、実行順の決定方法を最適化したいがすぐには実装できなかった。

最後に

この記事はLT駆動開発によって塩漬けにしていたアイデアを実装したものです。

LT の申し込みをしてくれた Sudo さんありがとう。

実験している様子をツイートしていたら連絡をくれた Tori さんありがとう。

pull がやっていることを調べるのが億劫だったので記事にしてくれていた Fukuda さんありがとう。

参考資料

2021-07-22

MySQLのエラー番号はどこに定義されているのか

背景

Go のアプリケーションで MySQL のエラー番号によって処理を分岐させたいことがあり、調査していたらドキュメントには記載されていた。 (例: ER_DUP_ENTRY(1062) をハンドリングしたい)

Go から参照しやすいように定数で提供されているものはないかと調査したが見つけることができなかった。

プログラムから参照しやすい形で存在しているだろうと思い、https://github.com/mysql/mysql-server を検索したが見つからなかった。

調査

ソースコードの中からは定数として参照はされているが定義は見つからない。

どうやら comp_err というコマンドによってビルド時に生成していることがわかった。

comp_err は MySQL 8.0.19 より前は errmsg-utf8.txt、以降は messages_to_error_log.txt と messages_to_clients.txt の情報からエラーを生成していると書かれている。

確かにそれらのファイルはソースコードの中からシンボル名を検索していたときに引っかかっていたがどこにもエラー番号がなかったので無視していた。

つまり comp_err 内部の何らかのロジックによってエラー番号が決められているだろうということでロジックを調査した。

comp_err は設定ファイルから

languages
default-language
start-error-number
ER_、WARN_、(OBSOLETE_ER_、OBSOLETE_WARN_)
(reserved-error-section)

から始まる行とエラーに付随するメッセージを解釈する。括弧がついているものは 8 系から追加された要素である。

languages は言語名の long name と short name の紐付け、文字コードの紐付けを定義する。

default-language は対象の言語のエラーメッセージがなかったときにどの言語のエラーメッセージを使うかを short name で指定する。基本的には eng。

start-error-number によって使用するエラー番号の先頭が決められ、それ以降に現れたエラーのシンボルから順に番号が割り振られていく。 start-error-number は複数回現れることがある。

ER_、WARN_ から始まる行はエラーの定義を行う。SQL State と ODBC State が存在するものに関してはエラーの名前の後に空白区切りで書かれている。

タブや空白から始まる行はエラーに紐づくメッセージの定義を行う。言語名の short name と書式文字列が書かれている。サポートしている言語がエラーによってまちまちで eng しか定義されていないものも多い。

reserved-error-section はエラー番号として予約済みで使ってはいけない範囲を指定する。

github.com

実際に中身を確認するとより理解が深まる。

結論

MySQL のエラー番号は comp_err によって errmsg-utf8.txt、または messages_to_error_log.txt と messages_to_clients.txt で定義されたエラーに対して採番したものが mysqld_error.h に定義されている。

余談1

背景で書いてあるとおりGoから定数として参照したい。すでにリリース済みのMySQLのソースの中の mysqld_error.h から生成すればよいが、せっかく調べたので comp_err の再実装を行い Go のパッケージを生成した。

github.com

GitHub に上がっている errmsg-utf8.txt や messages_to_clients.txt から自動的に生成するようになっている。

余談2

MySQL のエラーのサポート言語を集計してみた。

MySQL 5.7

// english(eng) 1123
// german(ger) 661
// swedish(swe) 331
// japanese(jpn) 292
// portuguese(por) 289
// spanish(spa) 286
// russian(rus) 268
// dutch(nla) 256
// ukrainian(ukr) 243
// italian(ita) 231
// serbian(serbian) 219
// french(fre) 212
// danish(dan) 208
// estonian(est) 206
// czech(cze) 192
// hungarian(hun) 183
// romanian(rum) 174
// korean(kor) 160
// greek(greek) 141
// slovak(slo) 138
// norwegian-ny(norwegian-ny) 128
// norwegian(nor) 126
// polish(pol) 121
// bulgarian(bgn) 3
// (bg) 3

1位は英語で圧倒的、2位がドイツ語なのが個人的には意外に感じた。 3位はスウェーデン語、4位が日本語という結果だった。最下位はブルガリア語で3なのだが明らかにミスのようなものが3つあり、半分しか使えていないのが残念な気持ちになった。

MySQL 8.0

// english(eng) 1672
// german(ger) 661
// swedish(swe) 331
// japanese(jpn) 292
// portuguese(por) 289
// spanish(spa) 286
// russian(rus) 267
// dutch(nla) 256
// ukrainian(ukr) 243
// italian(ita) 231
// serbian(serbian) 219
// french(fre) 212
// danish(dan) 208
// estonian(est) 206
// czech(cze) 192
// hungarian(hun) 183
// romanian(rum) 174
// korean(kor) 160
// greek(greek) 141
// slovak(slo) 138
// polish(pol) 136
// norwegian-ny(norwegian-ny) 128
// norwegian(nor) 126
// bulgarian(bgn) 8

8 系においても順位は変わらないがブルガリア語のミスが修正されており安心した。

2020-08-01

json.Marshalがエラーを返すとき

go 1.14.3 で確認した内容で個人的なメモです.

使っているバージョンによって異なる可能性があるので一次情報を参照してください.

golang.org

github.com

ソースコード上では encodeState の error が呼び出されているところを確認すれば良いと思われます.

エラーを返すパターン

主観ですが遭遇しそうな順で書きます.

floatがInf, NaNだったときの json.UnsupportedValueError
ポインタの循環参照のときに発生する json.UnsupportedValueError
json.Marshaler, encoding.TextMarshaler のMarshal失敗したときの json.MarshalerError
mapのkeyがint, uint, string, ptrではなく, encoding.TextMarshaler が実装されていないときの json.UnsupportedTypeError
mapのkeyが encoding.TextMarshaler を実装していて, marshalに失敗したときの fmt.Errorf("json: encoding error for type: %q")
json.Number で不正な数字列だったときの fmt.Errorf("json: invalid number literal: %q")

ハマりそうなポイント

mapのkeyの encoding.TextMarshaler が失敗したときのエラーは json.MarshalerError ではない.

json.Number をMarshalしたときに文字列が数値として正しくない場合に json パッケージのエラーは返ってこない.

TL;DR

背景

調査

考察

結論

再現するスクリプトと結果

TL;DR

はじめに

-XX:+PrintClassHistogram を使う

jmap -histo を使う

jcmd GC.class_histogram を使う

-XX:+PrintClassHistogramBeforeFullGC -XX:+PrintClassHistogramAfterFullGC を使う

-Xlog:classhisto*=trace

JFR の jdk.ObjectCount を 使う

VM_GC_HeapInspection

まとめ

余談1

余談2

参考リンク

背景

alloc_bytes と alloc_list の速度差について

元記事の簡単な概要

元記事で理解できなかったところ

前提

bind の挙動

余談: SO_REUSEADDR or SO_REUSEPORT?

SOCK_DIAG_BY_FAMILY の挙動

_connectx_udp の挙動

余談: TCP でローカルポートが積極的に再利用されるのはなぜ？

終わりに

TL;DR

背景・動機

関連

chunk-parallel

実験

ECR Public - ap-northeast-1 (SF, SEA)

2022/10/09 追記: ECR Public - ap-northeast-1 (NRT57-P3)

ECR Private - ap-northeast-1

ECR Public - us-west-2 (HIO)

結果

ECRの特性?

解決していない問題

最後に

参考資料

背景

調査

結論

余談1

余談2

MySQL 5.7

MySQL 8.0

エラーを返すパターン

ハマりそうなポイント

JFR の jdk.ObjectCount を使う