MySQL(Aurora) への接続を tcpdump でのぞき見してみて判ったことのメモ

MySQL への接続を tcpdump でのぞき見してみて判ったことのメモ

tl;dr

MySQL 等のデータベースに接続してクエリを発行するまでを tcpdump でのぞき見してみたて判ったこと等を雑にメモ。

参考

完全に理解しきれていませんが、とても参考になりました。有難うございますm(__)m

準備

環境

Amazon Linux
RDS（Aurora）→ せっかくなので Aurora を初体験してみた
WireShark（Version 2.0.0）

接続方法

MySQL クライアント（mysql コマンド）

mysql -u dbadmin -h demo-db.cluster-xxxxxxxxxxxxxx.ap-northeast-1.rds.amazonaws.com -pxxxxxxxxxxxxxx --execute="select now()"

ruby-mysql を利用（以下のような雑なスクリプトを用意）

require "logger"
require "mysql"

logger = Logger.new($stdout)
mysql = Mysql::new("demo-db.cluster-xxxxxxxxxxxxxx.ap-northeast-1.rds.amazonaws.com", "xxxxxxxxxxxxxx", "xxxxxxxxxxxxxxx", "mysql")
logger.info mysql.query("select now()")
mysql.close

発行するクエリ

SELECT NOW()

結果

MySQL クライアント

f:id:inokara:20160529152349p:plain

ruby-mysql

f:id:inokara:20160529152421p:plain

判ったこと

MySQL クライアントと ruby-mysql の違い

クエリのリクエストが MySQL クライアントの方が 1 つ多い（後述）
ruby-mysql 経由の方がサーバー接続確立後のオーバーヘッドが大きい（ライブラリ経由の接続が起因しているんだろうなあ）

MySQL クライアントから接続し、MySQL の認証が通過するまでの流れ

（接続開始から約 200 マイクロ秒）冒頭 TCP 3 way ハンドシェイクで Aurora に接続を確立
（ここまでで約 10 〜 14 ミリ秒）接続が確立すると Aurora から以下のような内容の Server Greeting(Initial Handshake Packet) が返ってきている

MySQL Protocol
    Packet Length: 74
    Packet Number: 0
    Server Greeting
        Protocol: 10
        Version: 5.6.10
        Thread ID: 39
        Salt: 1A5'^'Fk
        Server Capabilities: 0xffff
        Server Language: latin1 COLLATE latin1_swedish_ci (8)
        Server Status: 0x0002
        Extended Server Capabilities: 0xc07f
        Authentication Plugin Length: 21
        Unused: 00000000000000000000
        Salt: iJx@p9fxIDXm
        Authentication Plugin: mysql_native_password

（ここまでで約 15 ミリ秒）その後、クライアントから以下のような Login Request を送出（Password は Server Greeting 時にサーバーから受け取った salt 値を利用して計算しているとのこと）

MySQL Protocol
    Packet Length: 67
    Packet Number: 1
    Login Request
        Client Capabilities: 0xa20d
        Extended Client Capabilities: 0x0000
        MAX Packet: 1073741824
        Charset: latin1 COLLATE latin1_swedish_ci (8)
        Username: dbadmin
        Password: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
        Schema: mysql

（ほぼ間髪入れずに）サーバーから以下のような Response OK が返ってきている（Response OK が返ってくる = ユーザー名、パスワードを検証し、正しいユーザーとして判断された）

MySQL Protocol
    Packet Length: 7
    Packet Number: 2
    Affected Rows: 0
    Server Status: 0x0002
        .... .... .... ...0 = In transaction: Not set
        .... .... .... ..1. = AUTO_COMMIT: Set
        .... .... .... .0.. = More results: Not set
        .... .... .... 0... = Multi query - more resultsets: Not set
        .... .... ...0 .... = Bad index used: Not set
        .... .... ..0. .... = No index used: Not set
        .... .... .0.. .... = Cursor exists: Not set
        .... .... 0... .... = Last row sent: Not set
        .... ...0 .... .... = database dropped: Not set
        .... ..0. .... .... = No backslash escapes: Not set
        .... .0.. .... .... = Session state changed: Not set
        .... 0... .... .... = Query was slow: Not set
        ...0 .... .... .... = PS Out Params: Not set
    Warnings: 0

時間にすると 1 ミリ秒以下（環境やクライアント数によって差異はあると思うが）という、tcpdump しなければ、絶対に見ることが出来ないスピードでクエリ発行が可能な状態となる。

MySQL クライアントでのクエリ発行

MySQL クライアント（mysql コマンド）で接続した際には以下のようなクエリ（Request Query）が最初に飛んでいる

MySQL Protocol
    Packet Length: 33
    Packet Number: 0
    Request Command Query
        Command: Query (3)
        Statement: select @@version_comment limit 1

上記のクエリに対するレスポンス（Response）は以下の通り

Frame 10: 167 bytes on wire (1336 bits), 167 bytes captured (1336 bits)
Linux cooked capture
Internet Protocol Version 4, Src: 172.31.38.50, Dst: 172.31.5.129
Transmission Control Protocol, Src Port: 3306 (3306), Dst Port: 46934 (46934), Seq: 90, Ack: 228, Len: 99
MySQL Protocol
    Packet Length: 1
    Packet Number: 1
    Number of fields: 1
MySQL Protocol
    Packet Length: 39
    Packet Number: 2
    Catalog: def
    Database: 
    Table: 
    Original table: 
    Name: @@version_comment
    Original name: 
    Charset number: utf8 COLLATE utf8_general_ci (33)
    Length: 84
    Type: FIELD_TYPE_VAR_STRING (253)
    Flags: 0x0000
        .... .... .... ...0 = Not null: Not set
        .... .... .... ..0. = Primary key: Not set
        .... .... .... .0.. = Unique key: Not set
        .... .... .... 0... = Multiple key: Not set
        .... .... ...0 .... = Blob: Not set
        .... .... ..0. .... = Unsigned: Not set
        .... .... .0.. .... = Zero fill: Not set
        .... .... 0... .... = Binary: Not set
        .... ...0 .... .... = Enum: Not set
        .... ..0. .... .... = Auto increment: Not set
        .... .0.. .... .... = Timestamp: Not set
        .... 0... .... .... = Set: Not set
    Decimals: 31
MySQL Protocol
    Packet Length: 5
    Packet Number: 3
    EOF marker: 254
    Warnings: 0
    Server Status: 0x0002
        .... .... .... ...0 = In transaction: Not set
        .... .... .... ..1. = AUTO_COMMIT: Set
        .... .... .... .0.. = More results: Not set
        .... .... .... 0... = Multi query - more resultsets: Not set
        .... .... ...0 .... = Bad index used: Not set
        .... .... ..0. .... = No index used: Not set
        .... .... .0.. .... = Cursor exists: Not set
        .... .... 0... .... = Last row sent: Not set
        .... ...0 .... .... = database dropped: Not set
        .... ..0. .... .... = No backslash escapes: Not set
        .... .0.. .... .... = Session state changed: Not set
        .... 0... .... .... = Query was slow: Not set
        ...0 .... .... .... = PS Out Params: Not set
MySQL Protocol
    Packet Length: 29
    Packet Number: 4
    text: MySQL Community Server (GPL)
MySQL Protocol
    Packet Length: 5
    Packet Number: 5
    EOF marker: 254
    Warnings: 0
    Server Status: 0x0002
        .... .... .... ...0 = In transaction: Not set
        .... .... .... ..1. = AUTO_COMMIT: Set
        .... .... .... .0.. = More results: Not set
        .... .... .... 0... = Multi query - more resultsets: Not set
        .... .... ...0 .... = Bad index used: Not set
        .... .... ..0. .... = No index used: Not set
        .... .... .0.. .... = Cursor exists: Not set
        .... .... 0... .... = Last row sent: Not set
        .... ...0 .... .... = database dropped: Not set
        .... ..0. .... .... = No backslash escapes: Not set
        .... .0.. .... .... = Session state changed: Not set
        .... 0... .... .... = Query was slow: Not set
        ...0 .... .... .... = PS Out Params: Not set

ログイン時に表示されるアレはクエリだったんだなという気付き。

以上

tcpdump してみるべきだなーと思った
あんまり Aurora 関係無かった（MySQL でも同じような流れになると思う）

今回ののぞき見のような場合にはクライアント数はたかが知れているけど、高負荷な Web アプリケーションだと最初の 3 Way ハンドシェイクだったり、Server Greeting からの Response OK までのオーバーヘッドだったり、最適化されていないようなクエリがジワジワ効いてくるんだろうなあと思いを馳せつつ、ここでコネクションプーリングのような接続のキャッシュ機構を挟むとどこのステップが簡略化されるのかなど興味が尽きないが、それ以前に色々な知識が足りていないことに辛くなった。

精進しなければ...。

ようへいの日々精進XP

よかろうもん