2016年08月24日

BLE デバイス間の通信内容をパケットレベルで読み解いてみる

はてなブックマークに登録

前回の記事:
パケットスニファを使って実際に BLE 機器間の応酬を追ってみました。備忘をかねて以下に情報を控えます。題材には低価格で出回っているありふれた Anti-Lost 系 BLE デバイス A を選びました。この小さなデバイスには LED・ブザーと押しボタンスイッチが実装されており、対向スマホアプリとの間で双方向のやりとりが可能なつくりになっています。


デバイス A の UI

操作内容

デバイス A と Android 端末を使って以下の操作を行いスニファで BLE パケットのログを採取しました。

  1. デバイス A の電源を入れる
  2. Android 端末上の対向アプリからデバイスを探索しデバイス A との接続を確立
  3. アプリからデバイス A の LED+ブザーを ON にする
  4. デバイス A のボタンを押しアプリへ通知を送る
  5. アプリ上でデバイス A との接続を切断

応酬の全体像

スニファの Wireshark ログより

上の操作時に収集したパケットログの全体図です。   (クリックで大きく表示)

    

要約

パケットログの内容の要約を以下に示します。   (クリックで大きく表示)

  1. デバイス A の電源を入れる
    • デバイス A がアドバタイジングを開始 (ADV_IND)
  2. スマホ上の対向アプリからデバイスを探索しデバイス A との接続を確立
    • デバイスのスキャン (SCAN_REQ / SCAN_RSP) を経て接続要求 (CONNECT_REQ) 〜接続が確立するとデバイス A はアドバタイジングを停止
    • 機能情報を交換 (LL_FEATURE_REQ / LL_FEATURE_RSP)
    • デバイス A の提供する GATT プライマリサービス一覧を取得
    • 各サービス配下のエントリ(Included Service, キャラクタリスティック)一覧を取得
    • 各キャラクタリスティック配下のデスクリプタを取得
    • デバイス A のボタンが押された時に通知されるよう所定の Client Characteristic Configuration descriptor へアプリから Notification Bit 0x0001 を書き込む
  3. アプリからデバイス A の LED+ブザーを ON にする
    • アプリ上の所定のボタンが押されたタイミングでアプリはデバイス A の Immediate Alert サービス配下の Alert Level キャラクタリスティックへ値 2 (High Alert)を書き込む。これにより一定時間 A の LED とブザーが ON になる
  4. デバイス A のボタンを押しアプリへ通知を送る
    • デバイス A のボタンが押されたタイミングでデバイス A は時機のユーザ定義サービス 1 (UID=0xFFE0) 配下のユーザ定義キャラクタリスティック (UID=0xFFE1) へ値 1 を書き込む。当該キャラクタリスティック配下の Client Characteristic Configuration descriptor にはアプリ側から予め Notification Bit がセットされているためアプリへ通知される
  5. アプリ上でデバイス A との接続を切断
    • アプリからデバイス A へ LL_TERMINATE_IND を送る

応酬の詳細

全体の流れを見渡したところで次に個々のパケットデータを読み進めていきます。

  • 以下の記事には Wireshark のスクリーンショットをログとして添えています  (それぞれクリックで大きく表示)
  • ログには BLE パケットデータ本体に加え nRF Sniffer が解析の便宜のためにログへ出力する「Nordic BLE sniffer meta」ヘッダが含まれています
    • nRF Sniffer User Guide v1.1 (PDF) - www.nordicsemi.com Page 8 より
      4   Using Wireshark
      
      All BLE packets detected by the Sniffer are passed to Wireshark and are
      wrapped in a header which contains useful meta-information not present
      in the BLE packet itself. Wireshark dissects the packets and separates
      the actual packet from the meta-information.
                   :
      
  • 記事には下記資料からの抜粋へのリンクを参照用に適宜挿入しています
  • 随所に「https://developer.bluetooth.org/gatt/」下のサービス・キャラクタリスティックの記事へのリンクを張っていますが、2016年7月頃までは参照可能だった各記事が現在はリンク切れになっており(再構成中?)、さらに現時点では代替ページが見当たらないためリンク先はやむなく http://web.archive.org/ 上のキャッシュとしています。ただし web.archive.org 上にも保存履歴のない記事については一階層上のページへのリンクを張っています
    例:「Link Loss」サービスの単独ページのキャッシュは web.archive.org にも見当たらないため、上位のサービス一覧ページのキャッシュをターゲットに

局面

Scene 1: デバイス A のアドバタイジングと SCAN_REQ / SCAN_RSP

Frame 124 - 126 はデバイス A 発のアドバタイジングパケット

  • 全 40 チャネルのうちアドバタイジングパケット用の 37, 38, 39 の 3 チャネルが順次使用されていることが見てとれる
  • 「0x8e89bed6」の Access Address はアドバタイジングチャネルパケットで使用される固定値
  • デバイス A のアドバタイジングのタイプは Connectable Undirected(詳細: 1, 2, 3, 4) であることを示す一般的な「ADV_IND」である
  • 「Advertising Data: 020106020a000702031802180418」に含まれる不完全 16ビットサービスクラス UUID は次の内容
    • 16 bit uuid: 0x1803 --> 既定の「Link Loss」サービス
    • 16 bit uuid: 0x1802 --> 既定の「Immediate Alert」サービス
    • 16 bit uuid: 0x1804 --> 既定の「Tx Power」サービス
Frame 124

    

Frame 125

    

Frame 126

    

Frame 127

接続に際し対向アプリがデバイス A に対して SCAN_REQ を発行

    

Frame 128

デバイス A が対向アプリからの SCAN_REQ に対し SCAN_RSP を返信。ここでは ScanRspData としてデバイスのローカルネームが渡されている

    

Scene 2: 接続の確立と情報交換

Frame 217

対向アプリがデバイス A に対して CONNECT_REQ(詳細:1a, 2a, 1b, 2b)を発行して接続を試みる

  • 「Connection Request」中の「Connection Access Address」には、接続確立後のデータ通信において Access Address として双方が一意に使用する任意のアドレスが含まれる。ここでは「0xa6a188c8」
  • 「Connection Request」中の「Channel map」には接続確立後のデータ通信で使用するチャネル番号のリストが提示される。ここでは 0 - 36 の全データチャネルが指定されている
  • その他のパラメータについては上のリンクの資料を参照のこと
  • CONNECT_REQ に対する直接のレスポンスは発生しない。接続が確立するとデータ通信アイドル時にスレーブ - マスタ間で空パケット(Empty PDU)の応酬が始まるためこれが接続成否の判定に用いられる

    

Frame 218, 224 は接続確立後の最初の応酬。接続が確立すると対向アプリはマスタ、デバイス A はスレーブの位置づけとなる。ここでは リンク層制御 PDU の LL_FEATURE_REQ および LL_FEATURE_RSP によりマスタ - スレーブ間で Feature Exchange を行っている。ここでは双方とも「Supported feature: LE Encryption (0)」のみを提示(ただしここでは以降の通信において暗号化は行われていない)
Frame 218

    

Frame 224

    

Frame 222 ではアプリ側が「Device Name」を要求し Frame 226 でデバイス A 側がそれに応えている。
「Device Name」は、既定の Generic Access(GAP)サービス配下の既定のキャラクタリスティック(UUID = 0x2A00)であり、GATT サーバは必ず GAP サービスを含んでいる(詳細:1, 2
Frame 222

  Opcode: Read By Type Request (0x08)
  Starting Handle: 0x0001
  Ending Handle: 0xffff
  UUID: Device Name (0x2a00)

    

Frame 226

  Opcode: Read By Type Response (0x09)
  Length: 6
  Attribute Data, Handle: 0x0003
      Handle: 0x0003
      Value: ********

    

(GAP サービスおよび Device Name キャラクタリスティックは後続の Frame 231, Frame 266 であらためて表に現れる)

Scene 3: デバイス A の GATT サービス群の取得

(Scene 3, Scene 4 共通の基礎知識)
BLUETOOTH SPECIFICATION Version 4.2(PDF) [Vol 3, Part G] より
    2.6 GATT PROFILE HIERARCHY
       2.6.1 Overview, 2.6.2 Service, 2.6.3 Included Services, 2.6.4 Characteristic
  3 SERVICE INTEROPERABILITY REQUIREMENTS
     3.1 SERVICE DEFINITION, 3.2 INCLUDE DEFINITION, 3.3 CHARACTERISTIC DEFINITION
       3.3.1 Characteristic Declaration
         3.3.1.1 Characteristic Properties, 3.3.1.2 Characteristic Value Attribute Handle, 3.3.1.3 Characteristic UUID
       3.3.2 Characteristic Value Declaration

初期処理として、マスタはスレーブの提供するサービス一覧を取得する (詳細:1, 2, 3

  • アプリ側が、デバイス A の GATT サーバの提供する公開サービス(プライマリサービス)の問合せを開始。 以降、GATT サーバ上の所定のサービスへアクセスするためのハンドルのアドレスと当該サービスの種類を識別する UUID を順次取得する
  • ハンドルのアドレス空間は 0x0000 - 0xFFFF であり GATT サーバ側の応答に応じて照会範囲を絞っていく


      (図は 「BLUETOOTH SPECIFICATION Version 4.2」 より引用)

Frame 229

まずハンドル 0x0001 - 0xffff 全範囲についてプライマリサービスを照会

    Opcode: Read By Group Type Request (0x10)
    Starting Handle: 0x0001
    Ending Handle: 0xffff
    UUID: GATT Primary Service Declaration (0x2800)

    

Frame 231

以下のみっつのサービスの情報が得られた

  • ハンドルグループ 0x0001 - 0x000b:既定の「Generic Access」サービス(UUID = 0x1800)が使用
  • ハンドルグループ 0x000c - 0x000f:既定の「Generic Attribute」サービス(UUID = 0x1801)が使用
  • ハンドルグループ 0x0010 - 0x0022:既定の「Device Information」サービス(UUID = 0x180A)が使用

    Opcode: Read By Group Type Response (0x11)
    Length: 6
    Attribute Data, Handle: 0x0001, Group End Handle: 0x000b
        Handle: 0x0001
        Group End Handle: 0x000b
        Value: 0018
    Attribute Data, Handle: 0x000c, Group End Handle: 0x000f
        Handle: 0x000c
        Group End Handle: 0x000f
        Value: 0118
    Attribute Data, Handle: 0x0010, Group End Handle: 0x0022
        Handle: 0x0010
        Group End Handle: 0x0022
        Value: 0a18

    

Frame 235

続けてハンドル 0x0023 - 0xffff 範囲のプライマリサービスを照会

    

Frame 238

以下のみっつのサービスの情報が得られた

  • ハンドルグループ 0x0023 - 0x0025:既定の「Immediate Alert」サービス(UUID = 0x1802)が使用
  • ハンドルグループ 0x0026 - 0x002a:既定の「Tx Power」サービス(UUID = 0x1804)が使用
  • ハンドルグループ 0x002b - 0x002d:既定の「Link Loss」サービス(UUID = 0x1803)が使用

    

Frame 242

続けてハンドル 0x002e - 0xffff 範囲のプライマリサービスを照会

    

Frame 247

以下のみっつのサービスの情報が得られた

  • ハンドルグループ 0x002e - 0x0032:既定の「Battery Service」サービス(UUID = 0x180F)が使用
  • ハンドルグループ 0x0033 - 0x0037:ユーザ定義のサービス 1(UUID = 0xFFE0)が使用
  • ハンドルグループ 0x0038 - 0x003a:ユーザ定義のサービス 2(UUID = 0xFFF0)が使用

    

Frame 250

続けてハンドル 0x003b - 0xffff 範囲のプライマリサービスを照会

    

Frame 253

「Attribute Not Found (0x0a)」のエラーが返る。これ以上プライマリサービスが存在しないことを意味する。サービスの照会はここまで

    Opcode: Error Response (0x01)
    Request Opcode in Error: Read By Group Type Request (0x10)
    Handle in Error: 0x003b
    Error Code: Attribute Not Found (0x0a)

    

Scene 4: デバイス A 各サービス配下のキャラクタリスティック - デスクリプタの取得

(Scene 3, Scene 4 共通の基礎知識)
BLUETOOTH SPECIFICATION Version 4.2(PDF) [Vol 3, Part G] より
    2.6 GATT PROFILE HIERARCHY
       2.6.1 Overview, 2.6.2 Service, 2.6.3 Included Services, 2.6.4 Characteristic
  3 SERVICE INTEROPERABILITY REQUIREMENTS
     3.1 SERVICE DEFINITION, 3.2 INCLUDE DEFINITION, 3.3 CHARACTERISTIC DEFINITION
       3.3.1 Characteristic Declaration
         3.3.1.1 Characteristic Properties, 3.3.1.2 Characteristic Value Attribute Handle, 3.3.1.3 Characteristic UUID
       3.3.2 Characteristic Value Declaration

次に、収集ずみの各プライマリサービスのハンドルグループごとに以下を行う (詳細:1, 2, 3, 4, 5, 6

  • 所定のサービスに含まれる Included Service の照会


      (図は 「BLUETOOTH SPECIFICATION Version 4.2」 より引用)

  • 所定のサービスに含まれるキャラクタリスティックの照会


      (図は 「BLUETOOTH SPECIFICATION Version 4.2」 より引用)

    • 所定のキャラクタリスティックに含まれるデスクリプタの照会


        (図は 「BLUETOOTH SPECIFICATION Version 4.2」 より引用)

Frame 255

前掲の Frame 231 の示すハンドルグループ 0x0001 - 0x000b の「Generic Access」サービス内の Included Service を照会

    Opcode: Read By Type Request (0x08)
    Starting Handle: 0x0001
    Ending Handle: 0x000b
    UUID: GATT Include Declaration (0x2802)

    

Frame 259

当該サービス内に Included Service は存在しない(注:図のログではスニファがパケットデータを取りこぼしている)

    

Frame 262

ハンドルグループ 0x0001 - 0x000b の「Generic Access」サービス内のキャラクタリスティックを照会

    Opcode: Read By Type Request (0x08)
    Starting Handle: 0x0001
    Ending Handle: 0x000b
    UUID: GATT Characteristic Declaration (0x2803)

    

Frame 266

以下のみっつのキャラクタリスティックの情報が得られた

(※キャラクタリスティック の Value フィールドの構成は前掲の「BLUETOOTH SPECIFICATION Version 4.2] - [Vol 3, Part G] p.532 「3.3.1 Characteristic Declaration」 に、プロパティ値の意味は同じく p.533 「3.3.1.1 Characteristic Properties」 に説明あり)

  • ハンドル:0x0002
    「value: 080300002a」より、プロパティ = 0x08 (Write), Characteristic Value Handle = 0x0003
    UUID = 0x2A00 = 既定の「Device Name
  • ハンドル:0x0004
    「value: 020500012a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0005
    UUID = 0x2A01 = 既定の「Appearance
  • ハンドル:0x0006
    「value: 020700042a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0007
    UUID = 0x2A04 = 既定の「Peripheral Preferred Connection Parameters

    Opcode: Read By Type Response (0x09)
    Length: 7
    Attribute Data, Handle: 0x0002
      Handle: 0x0002
      Value: 080300002a
    Attribute Data, Handle: 0x0004
      Handle: 0x0004
      Value: 020500012a
    Attribute Data, Handle: 0x0006
      Handle: 0x0006
      Value: 020700042a

    

Frame 270

続けてハンドル 0x0007 - 0x000b 範囲のキャラクタリスティックを照会

    

Frame 275

以下のふたつのキャラクタリスティックの情報が得られた

  • ハンドル:0x0008
    「value: 020900022a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0009
    UUID = 0x2A02 = 既定の「Peripheral Privacy Flag
  • ハンドル:0x000a
    「value: 020b00032a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x000b
    UUID = 0x2A03 = 既定の「Reconnection Address

    

Frame 279

前掲の Frame 231 の示すハンドルグループ 0x000c - 0x000f の「Generic Attribute」サービス内の Included Service を照会

    

Frame 284

当該サービス内に Included Service は存在しない

    

Frame 287

ハンドルグループ 0x000c - 0x000f の「Generic Attribute」サービス内のキャラクタリスティックを照会

    

Frame 289

以下のキャラクタリスティックの情報が得られた

  • ハンドル:0x000d
    「value: 200e00052a」より、プロパティ = 0x20 (Indicate), Characteristic Value Handle = 0x000e
    UUID = 0x2A52 = 既定の「Service Changed

    

Frame 293

続けてハンドル 0x000e - 0x000f 範囲のキャラクタリスティックを照会

    

Frame 298

当該サービス内にはこれ以上キャラクタリスティックは存在しない

    

Frame 302

Frame 289 の示す通り 0x0000e は Service Changed キャラクタリスティックの Value Handle であり、残る0x000f に関する情報を GATT に問い合わせてみる (詳細:1, 2

    Opcode: Find Information Request (0x04)
    Starting Handle: 0x000f
    Ending Handle: 0x000f

    

Frame 305

0x000f は Service Changed キャラクタリスティックの Client Characteristic Configuration Descriptor (UID = 0x2902) (詳細:1, 2) である旨の情報が得られた

    Opcode: Find Information Response (0x05)
    UUID Format: 16-bit UUIDs (0x01)
    Handle: 0x000f
    UUID: Client Characteristic Configuration (0x2902)

    

Frame 308

前掲の Frame 231 の示すハンドルグループ 0x0010 - 0x0022 の「Device Information」サービス内の Included Service を照会

    

Frame 312

当該サービス内に Included Service は存在しない

    

Frame 315

ハンドルグループ 0x0010 - 0x0022 の「Device Information」サービス内のキャラクタリスティックを照会

    

Frame 319

以下のみっつのキャラクタリスティックの情報が得られた

  • ハンドル:0x00011
    「value: 021200292a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0012
    UUID = 0x2A29 = 既定の「Manufacturer Name String
  • ハンドル:0x00013
    「value: 021400242a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0014
    UUID = 0x2A24 = 既定の「Model Number String
  • ハンドル:0x00015
    「value: 021600252a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0014
    UUID = 0x2A25 = 既定の「Serial Number String

    

Frame 323

続けてハンドル 0x0016 - 0x0022 範囲のキャラクタリスティックを照会

    

Frame 326

以下のみっつのキャラクタリスティックの情報が得られた

  • ハンドル:0x00017
    「value: 021800262a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0018
    UUID = 0x2A26 = 既定の「Firmware Revision String
  • ハンドル:0x00019
    「value: 021a00272a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x001a
    UUID = 0x2A27 = 既定の「Hardware Revision String
  • ハンドル:0x0001b
    「value: 021c00282a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x001c
    UUID = 0x2A28 = 既定の「Software Revision String

    

Frame 330

続けてハンドル 0x001c - 0x0022 範囲のキャラクタリスティックを照会

    

Frame 333

以下のみっつのキャラクタリスティックの情報が得られた

  • ハンドル:0x0001d
    「value: 021e00232a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x001e
    UUID = 0x2A23 = 既定の「System ID
  • ハンドル:0x0001f
    「value: 0220002a2a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0020
    UUID = 0x2A2A = 既定の「IEEE 11073-20601 Regulatory Certification Data List
  • ハンドル:0x00021
    「value: 022200502a」より、プロパティ = 0x02 (Read), Characteristic Value Handle = 0x0022
    UUID = 0x2A50 = 既定の「PnP ID

    

Frame 337

前掲の Frame 238 の示すハンドルグループ 0x0023 - 0x0025 の「Immediate Alert」サービス内の Included Service を照会
(注:このリクエストに対する正しいレスポンスは「Attribute Not Found (0x0a)」だが、スニファ取りこぼしのためログが欠落している)

    

Frame 341

ハンドルグループ 0x0023 - 0x0025 の「Immediate Alert」サービス内のキャラクタリスティックを照会

    

Frame 345

以下のキャラクタリスティックの情報が得られた

  • ハンドル:0x0024
    「value: 042500062a」より、
    プロパティ = 0x04 (Write without Response),
    Characteristic Value Handle = 0x0025
    UUID = 0x2A06 = 既定の「Alert Level

    

Frame 349

前掲の Frame 238 の示すハンドルグループ 0x0026 - 0x002a の「Tx Power」サービス内の Included Service を照会
(注:このリクエストに対する正しいレスポンスは「Attribute Not Found (0x0a)」だが、スニファ取りこぼしのためログが欠落している)

    

Frame 355

ハンドルグループ 0x0026 - 0x002a の「Tx Power」サービス内のキャラクタリスティックを照会

    

Frame 359

以下のキャラクタリスティックの情報が得られた

  • ハンドル:0x0027
    「value: 122800072a」より、プロパティ = 0x12 (Read | Notify), Characteristic Value Handle = 0x0028
    UUID = 0x2A07 = 既定の「Tx Power Level

    

Frame 362

続けてハンドル 0x0028 - 0x002a 範囲のキャラクタリスティックを照会

    

Frame 366

当該サービス内にはこれ以上キャラクタリスティックは存在しない

    

Frame 369

Frame 359 の示す通り 0x00028 は Tx Power Level キャラクタリスティックの Value Handle であり後続の 0x0029 - 0x002a に関する情報を GATT に問い合わせてみる (詳細:1, 2

    

Frame 373

0x0029 は Tx Power Level キャラクタリスティックの Client Characteristic Configuration Descriptor (UID = 0x2902) (詳細:1, 2) である旨の情報が得られた

    

Frame 376

残る0x002a に関する情報を GATT に問い合わせてみる (詳細:1, 2

    

Frame 380

0x002a は Tx Power Level キャラクタリスティックの Characteristic Presentation Format Descriptor (UID = 0x2904) (詳細:1, 2, 3, 4) である旨の情報が得られた

    Opcode: Find Information Response (0x05)
    UUID Format: 16-bit UUIDs (0x01)
    Handle: 0x002a
    UUID: Characteristic Presentation Format (0x2904)

    

Frame 384

前掲の Frame 238 の示すハンドルグループ 0x002b - 0x002d の「Link Loss」サービス内の Included Service を照会
(注:このリクエストに対する正しいレスポンスは「Attribute Not Found (0x0a)」だが、スニファ取りこぼしのためログが欠落している)

    

Frame 390

ハンドルグループ 0x002b - 0x002d の「Link Loss」サービス内のキャラクタリスティックを照会

    

Frame 392

以下のキャラクタリスティックの情報が得られた

  • ハンドル:0x002c
    「value: 0a2d00062a」より、プロパティ = 0x0a (Read | Write), Characteristic Value Handle = 0x002d
    UUID = 0x2A06 = 既定の「Alert Level

    

Frame 395

前掲の Frame 247 の示すハンドルグループ 0x002e - 0x0032 の「Battery Service」サービス内の Included Service を照会

    

Frame 397

当該サービス内に Included Service は存在しない

    

Frame 401

ハンドルグループ 0x002e - 0x0032 の「Battery Service」サービス内のキャラクタリスティックを照会

    

Frame 404

以下のキャラクタリスティックの情報が得られた

  • ハンドル:0x002f
    「value: 123000192a」より、プロパティ = 0x12 (Read | Notify), Characteristic Value Handle = 0x0030
    UUID = 0x2A19 = 既定の「Battery Level

    

Frame 407

続けてハンドル 0x0030 - 0x0032 範囲のキャラクタリスティックを照会

    

Frame 411

当該サービス内にこれ以上キャラクタリスティックは存在しない

    

Frame 415

Frame 404 の示す通り 0x00030 は Battery Level キャラクタリスティックの Value Handle であり後続の 0x0031 - 0x0032 に関する情報を GATT に問い合わせてみる (詳細:1, 2

    

Frame 420

0x0031 は Battery Level キャラクタリスティックの Client Characteristic Configuration Descriptor (UID = 0x2902) (詳細:1, 2) である旨の情報が得られた

    

Frame 423

残る0x0032 に関する情報を GATT に問い合わせてみる (詳細:1, 2

    

Frame 427

0x0032 は Battery Level キャラクタリスティックの Characteristic Presentation Format Descriptor (UID = 0x2904) (詳細:1, 2, 3, 4) である旨の情報が得られた

    

Frame 431

前掲の Frame 247 の示すハンドルグループ 0x0033 - 0x0037 のユーザ定義サービス 1(UUID = 0xFFE0)内の Included Service を照会

    

Frame 434

当該サービス内に Included Service は存在しない

    

Frame 437

ハンドルグループ 0x0033 - 0x0037 のユーザ定義サービス 1 内のキャラクタリスティックを照会

    

Frame 439

以下のキャラクタリスティックの情報が得られた

  • ハンドル:0x0034
    「value: 103500e1ff」より、
    プロパティ = 0x10 (Notify),
    Characteristic Value Handle = 0x0035
    UUID = 0xFFE1 : ユーザ定義のキャラクタリスティック

    

Frame 442

続けてハンドル 0x0035 - 0x0037 範囲のキャラクタリスティックを照会

    

Frame 446

当該サービス内にこれ以上キャラクタリスティックは存在しない

    

Frame 450

Frame 439 の示す通り 0x00035 はユーザ定義キャラクタリスティック(UUID = 0xFFE1)の Value Handle であり後続の 0x0036 - 0x0037 に関する情報を GATT に問い合わせてみる (詳細:1, 2

    

Frame 453

0x0036 はユーザ定義キャラクタリスティック(UUID = 0xFFE1)の Client Characteristic Configuration Descriptor (UID = 0x2902) (詳細:1, 2) である旨の情報が得られた

    

Frame 456

残る0x0037 に関する情報を GATT に問い合わせてみる (詳細:1, 2

    

Frame 458

0x0037 はユーザ定義キャラクタリスティック(UUID = 0xFFE1)の Characteristic User Description Descriptor (UID = 0x2901)である旨の情報が得られた

    

Frame 462

前掲の Frame 247 の示すハンドルグループ 0x0038- 0x003a のユーザ定義サービス 2(UUID = 0xFFF0)内の Included Service を照会

    

Frame 465

当該サービス内に Included Service は存在しない

    

Frame 468

ハンドルグループ 0x0038 - 0x003a のユーザ定義サービス 2 内のキャラクタリスティックを照会

    

Frame 470

以下のキャラクタリスティックの情報が得られた

  • ハンドル:0x0039
    「value: 043a00f1ff」より、プロパティ = 0x04 (Write without Response), Characteristic Value Handle = 0x003a
    UUID = 0xFFF1 : ユーザ定義のキャラクタリスティック

    

Scene 5: デバイス A ボタン押下時のアプリへの通知を設定

Frame 491

Frame 453Frame 439Frame 453 の示す通り、ハンドル 0x0036 は、 "ユーザ定義サービス 1(UUID = 0xFFE0)配下のユーザ定義キャラクタリスティック(UUID = 0xFFE1)配下の Client Characteristic Configuration Descriptor (CCCD)" である

当該ユーザ定義キャラクタリスティック(UUID = 0xFFE1)のプロパティには Notify が設定されており、クライアントである対向アプリから CCCD 0x0036 に Notification bit (0x0001) を書き込んでおくことで、このキャラクタリスティックの値が更新された時に Value Handle である 0x0035 経由でアプリ側へ通知(Notification)が行われるようになる
(詳細: 1a, 2a, 1b, 2b

    Opcode: Write Request (0x12)
    Handle: 0x0026
    Value: 0100

    

Frame 495

    Opcode: Write Response (0x13)

    

Scene 6: アプリからデバイス A の LED・ブザーを操作

Frame 616

対向アプリ上の所定のボタンを押下すると、Frame 345, Frame 238 の示す、 "「Immediate Alert」サービス配下の「Alert Level」キャラクタリスティック" の Value Handle 0x0025 に値「2(High Alert)」が書き込まれる

デバイス A の LED・ブザーはファームウェアレベルでこの Alert Level キャラクタリスティックに紐づけられている模様。High Alert 値が書き込まれるとそれに反応して短時間 LED とブザーが ON になる

なお、Frame 345 の示すように Alert Level キャラクタリスティックのプロパティには「Write without Response」(0x04) が設定されているため、アプリから値を書き込んでもデバイス A からのレスポンスは発生しない

    Opcode: Write Command (0x52)
    Handle: 0x0025
    Value: 02

    

Scene 7: デバイス A のボタンを押すとアプリへ通知

Frame 711

デバイス A の物理ボタンはファームウェアレベルで Frame 439 の示す "ユーザ定義サービス 1(UUID = 0xFFE0)配下のユーザ定義キャラクタリスティック(UUID = 0xFFE1)" に紐づけられている模様。このボタンを押すと当該キャラクタリスティックの値がデバイス内部で更新され Frame 491 での仕込みに基づきアプリ側へ通知が行われる

    Opcode: Handle Value Notification (0x1b)
    Handle: 0x0035
    Value: 01

    

Scene 8: アプリ側からデバイス A との接続を切断

対向アプリ上の所定のボタンを押下するとリンク層制御 PDU の LL_TERMINATE_IND (0x02) がデバイス A 側に送出され両者間の接続が終了する(詳細:1, 2

Frame 779

    


(tanabe)

klab_gijutsu2 at 19:02
この記事のURLComments(0)TrackBack(0)Bluetooth | IoT
2016年08月23日

pixiv private isucon 2016 Python 版実装を用意しました

はてなブックマークに登録

今年の ISUCON でも Python 実装が提供されることが 発表されました。

Python での練習は過去の予選問題でも可能ですが、今年の出題チームが準備した問題で 練習できるように Python 版の実装を用意しました。とりあえずベンチマーカーが完走する ところまでは確認してあります。

リポジトリ

用意したのはアプリの実装だけなので、これを使って練習する際は pixiv さんが公開されている AMIwebapp ディレクトリ配下に python という名前で git clone し、 systemd などの設定は練習の一環として自前で行ってください。

また時間があるときに自分でチューニングしてみて、ミドルウェアの選定や ツール・テクニックなどを公開したいと思います。


@methane
songofacandy at 20:55
この記事のURLComments(0)TrackBack(0)ISUCON | Python
2016年08月18日

技適マークつき BLE パケットスニファを入手する

はてなブックマークに登録

Bluetooth Low Energy (BLE) の勉強のために BLE パケットを覗いてみたいと思いました。BLE の通信プロトコルは複雑ですが、パケットの内容を適宜精査すれば座学的な情報の向こう側にある実像を捉えることが可能となるでしょう。

国内では次のような BLE プロトコルアナライザが販売されています。もっともこういった数百万円オーダーの専用機にはなかなか手を出せません。

もっと手軽な方法として、BLE チップ・モジュールベンダの提供するパケットスニファを利用する選択があります。代表的な製品をピックアップしてみます。 2016年8月時点では日本国内で正規に流通している BLE パケットスニファ製品は見当たりません。もちろん国外から調達することは可能ですが、電波法に基づく技術基準適合(技適)証明とのかねあいが気になるところです。

パケットスニファと技適

たとえば、前掲の Nordic Semiconductor 社製「nRF51 Dongle」は技適証明を受けていないためディストリビュータが次のように注意を促しています。

  • nRF51 USB dongle for emulator,firmware - jp.rs-online.com
    警告
    
    本開発キットは技術基準適合証明を受けておりません。本製品のご使用に際しては、
    電波法遵守のため、以下のいずれかの措置を取っていただく必要がありますので
    ご注意ください。
    
     - 電波法施行規則第 6 条第 1 項第 1 号に基づく平成 18 年 3 月 28 日総務省告示
       第 173 号で定められた電波暗室等の試験設備内で使用する。
     - 実験局の免許を取得したのち使用する。
     - 技術基準適合証明を取得したのち使用する。
    
ただ、電波法は受信のみを目的とするものを規制対象外としています。
  • 電波法 (最終改正:平成二七年五月二二日法律第二六号) - law.e-gov.go.jp
       第一章 総則
              :
    第二条 この法律及びこの法律に基づく命令の規定の解釈に関しては、次の定義に
           従うものとする。 
              :
      五  「無線局」とは、無線設備及び無線設備の操作を行う者の総体をいう。
           但し、受信のみを目的とするものを含まない。 
              :
    
機能の性質上、パケットスニファの通信上の役割は受信に特化しています。ではこのデバイスを規制対象外と判断し安心して国内で使うことは適切でしょうか? 実はさらに考慮すべき話題があります。

上の記事のように、nRF51 Dongle は mbed 対応のプログラマブルな無線通信デバイスです。つまり、この「無線設備」は元来「受信のみを目的とするもの」ではなくむしろ「操作を行う者」によってプログラムを書き換え可能であることを特長のひとつに掲げている製品です。上に挙げたスニファデバイスはいずれも同様の側面を持っています。

以下の例のように、技適マークつきの製品においてさえ「ファームウェアの書き換え」との整合性を一意に判断できない事情を考え合わせると、技適マークなしのこれらのスニファ製品の日本国内での使用の是非はやはり微妙かもしれません。

  • ESP-WROOM-02のファームウェアを書き換えた場合、技適はどうなるのか - スイッチサイエンス
    ユーザーによるファームウェアの書き換えが、ESP-WROOM-02の工事設計認証を
    無効にする可能性について、メーカーのEspressif Systemsに確認をしました。
    同社は登録認証機関に確認した上で、Arduino core for ESP8266 WiFi chip
    または同社製SDKを使っている限りにおいては、認証には影響を与えないという
    回答を下さいました。他の開発環境など、ファームウェアを書き換える部分に
    よっては、認証に影響を及ぼし得るとのことですので、ご注意ください。
    
  • モノワイヤレス製品情報 - MONO-WIRELESS.COM - mono-wireless.com
    電波法規(技適)について
             :
    更にファームウエアを書き換えると認証の範囲を外れてしまう無線モジュール
    も存在しています。弊社製品は全て技適認証に適合した無線モジュールですので
    コンプライアンスに背くことなく安心してご使用していただけます。併せて
    「電波法についての考慮事項」を参照ください。
    
  • DD-WRT - wikipedia
    電波法による規制
    
    日本においては無線機器に対してメーカー側が想定していない非公式ファーム
    ウェアへの書き換えを行った時点で技適マークが無効となり、無線LANを利用する
    場合は電波法に違反する[要出典]。
             :
    

Adafruit 社製「Bluefruit LE Sniffer」

そんなわけで前掲のスニファの導入は一旦保留していましたが、情報を探しているうちにふとある製品のスペックに目がとまりました。

MDBT40 は、Nordic Semiconductor 社製のメジャーな nRF51822 チップを搭載した 中国 Raytac 社の BLE モジュールです。前に BLE まわりの製品調査を行っていた折にこの MDBT40 が日本の技適証明を取得ずみであることを知り名前が印象に残っていました。

MDBT40 を載せた製品は下記の例のように国内で流通しています。

  • Adafruit Feather 32u4 Bluefruit LE - スイッチサイエンス
    BLE(Bluetooth Low Energy)機能付きの小型Arduino互換ボードです。
    Adafruit Bluefruit LE Microの後継品です。
                    :
    Arduino Leonardoなどに搭載されているATmega 32u4を搭載。
    BLEモジュールであるMDBT40は、総務省の工事設計認証(いわゆる技適)を
    取得済みなので、日本国内で使用することができます。
                    :
    
Adafruit 社製のこの「Bluefruit LE Sniffer」の製品写真をよく見ると、技適マークつきの MDBT40 が載っていることを確認できます。 (クリックで原寸画像を表示)

cdn-shop.adafruit.com

このスニファであれば技適関連のジレンマなしに利用できそうです。本体価格は直販で $29.95。以下、Adafruit 社公式サイトより。

Bluefruit LE Sniffer のポイントをざっくりまとめてみます。

さっそく Adafruit 社サイトでオーダーしました。 配送方法には最も安価な United States Postal Service の「First-Class Package International Service™ incl. $1.60 insurance : $16.40」を指定、計 $46.35 を PayPal で決済し一週間ほどで到着しました。

発送連絡後に USPS サイトで配送状況を確認すると経由地に「JAMAICA」の表記あり。さては Japan -> Jamaica のミスか? と疑いましたがこれはカリブ海域にある国の名前ではなく JFK 空港そばの「JAMAICA, NY 11430」でした。物流の要衝のようですが恥ずかしながらニューヨークにジャマイカという地名があることを初めて知りました。Adafruit さん疑ってごめんなさい(^^;

使ってみる

Windows PC で Bluefruit LE Sniffer を使用する最短の手順を示します。詳細は nRF Sniffer アーカイブ内の「nRF Sniffer User Guide」に記載されています。

  1. FTDI 社の仮想 COM ポートドライバを未導入ならインストール
  2. 最新の nRF Sniffer の zip アーカイブをダウンロードし適当なフォルダ A へ展開
  3. Wireshark(v1.10.1 以降)を未導入ならインストール
  4. Bluefruit LE Sniffer を USB ポートへ接続し Sniffing の対象とするデバイスを近接させておく
    図は「nRF Sniffer User Guide v1.2」より
  5. フォルダ A 直下の「ble-sniffer_win_<version>_Sniffer.exe」を実行
  6. コンソールが開きアドバタイジング中の BLE デバイスが一覧表示される
  7. カーソルキー+ENTER または「#」番号で対象とするデバイスを選択
  8. デバイスを選択した状態で「w」キーを押下すると Wireshark が起動。あとはデバイス側で必要な操作を行えばよい

付記:デュアルユース品と輸出規制

ご存知の方も多いと思いますが、MouserRSDigi-key といった一般のディストリビュータから所定の電子部品を購入しようとすると、その製品の内容と在庫元・出荷元の国や地域によっては軍事転用の可能な「デュアルユース品目」として輸出規制に引っかかり、所定の書類一式の提出を求められ審査のために数週間程度待たされる場合があります。

今回、某ディストリビュータへ所定の商品が輸出規制の対象が否かを事前に判別する方法の有無を尋ねたところ「注文を受け実際に輸出手続きを開始しなければわからない」との回答でした。 輸出規制に関する注意書きの有無はまちまちですが、以下に一例を引用します。

  • nRF51-Dongle Nordic Semiconductor | Mouser - www.mouser.jp
    This product may require additional documentation to export
    from the United States.
    この製品をアメリカから配送するには、追加の書類が必要になる
    ことがあります。
    
一方、直販も行っている Adafruit は自社製品の輸出管理を主体的に実施している旨を公式サイト上で宣言しています。こういう場合には直販を利用するほうが面倒が少ないようです。


(tanabe)
klab_gijutsu2 at 11:35
この記事のURLComments(0)TrackBack(0)Bluetooth | IoT
2016年08月03日

Tomoru と Pochiru と Linking

はてなブックマークに登録

Tomoru

Tomoru は、昨年(2015年)11月より国内のクラウドファンディングサービス Makuake で支援募集の行われた Bluetooth Low Energy(BLE)デバイスです。「Project Linking」の立ち上げとともに当時話題になったためご存知の方も多いことでしょう。2016年8月現在は製造元である株式会社 Braveridge公式ストアAmazon から入手することができます。以前このブログで「blink(1)」という製品をピックアップしたことがありますが、個人的に「光りもの」は好物で、この Tomoru も支援募集への応募によって届いた個体を持っています。

Tomoru

www.products.braveridge.com

現時点では対応アプリが全体的にやや大人しめで Linking 自体も本格的な普及はこれからのようですが、手元では BLE の勉強がてらにこの可愛いデバイスを楽しんでいます。

Pochiru

Braveridge 社はその後も活発に Linking 対応製品をリリースしています。最近目にとまった「Pochiru」というデバイスを買ってみました。Pochiru には LED に加えネーミングどおり押しボタンが実装されています。そのため通信先の機器との双方向のやりとりが可能です。

Pochiru

linkingiot.com
ボタンものの BLE デバイスはいろいろ販売されていますが、リモートシャッターやメディアプレイヤーの操作といった所定の目的に閉じたものが多く、廉価でありながら自作のアプリケーションと汎用的に連携可能であることが Pochiru の魅力です。この価格でこのサイズの BLE ボタンデバイスを自作することの難度を考えるとコストパフォーマンスの高い製品と言えるでしょう。

プログラムを書く

Tomoru や Pochiru のような Linking 対応デバイス用のアプリは Project Linking が無償で公開している SDK を利用して作成します。BLE まわりのハンドリングはすべて Linking 本体が仲介するため、抽象化された Linking API を呼び出すだけでデバイスとの連携が可能です。

Project Linking の開発者向けページの中ほどの「API guide」項の利用規約を確認の上 SDK をダウンロードし、「API 仕様書」の「ポーティング」ページの説明に添って開発環境をセットアップします。後は「API 仕様書」と SDK アーカイブに含まれる「LinkingIFDemo」のコードを読み合わせれば要領を理解しやすいでしょう。

手元では Android 版 SDK を利用しています。上記のサンプルを元に作成した簡単なアプリのコードを以下に示します。アプリの「LED」ボタンを押すと連携ずみデバイスの LED が点灯し、連携ずみデバイス側のボタン押下等のイベントによってアプリが通知を受けるとその旨を画面に表示する内容です。

試作:Linking01

MainActivity.java
/**
 *
 * Linking01
 *
 * - 連携ずみ Linking デバイスの LED を点灯させる
 * - Linking デバイスからの通知を受け取る
 *
 */

package jp.klab.Linking01;

import android.content.Context;
import android.content.SharedPreferences;
import android.media.AudioManager;
import android.media.ToneGenerator;
import android.os.Bundle;
import android.support.v7.app.AppCompatActivity;
import android.support.v7.widget.Toolbar;
import android.view.View;
import android.widget.Button;
import android.widget.Toast;

import com.nttdocomo.android.sdaiflib.Define;
import com.nttdocomo.android.sdaiflib.NotifyNotification;
import com.nttdocomo.android.sdaiflib.SendOther;

public class MainActivity extends AppCompatActivity
        implements View.OnClickListener {

    private Context mCtx;
    private Button mButtonLED;

    private static final byte LINKING_IF_PATTERN_ID = 0x20; //LEDパターンの設定項目ID(固定値)
    private static final byte LINKING_IF_COLOR_ID = 0x30;   //LED色の設定項目ID(固定値)
    private static final byte COLOR_ID_RED = 0x01;  // 点灯色
    private static final byte BLINK_PATTERN = 0x22; // 点灯パターン

    private NotifyNotification mNotifyNotification;
    private MyNotificationInterface mMyNotificationInterface;

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        mCtx = this;
        setContentView(R.layout.activity_main);
        Toolbar toolbar = (Toolbar) findViewById(R.id.toolbar);
        setSupportActionBar(toolbar);
        mButtonLED = (Button)findViewById(R.id.buttonLED);
        mButtonLED.setOnClickListener(this);
        // Linking デバイスからの通知受信用
        mMyNotificationInterface = new MyNotificationInterface();
        mNotifyNotification = new NotifyNotification(this, mMyNotificationInterface);
    }

    @Override
    public void onClick(View v) {
        // LED ボタン押下で連携ずみデバイスあてに LED 点灯指示を送る
        if (v == (View)mButtonLED) {
            SendOther sendOther = new SendOther(this);
            sendOther.setIllumination(
                    new byte[] {
                            LINKING_IF_PATTERN_ID,
                            BLINK_PATTERN,
                            LINKING_IF_COLOR_ID,
                            COLOR_ID_RED
                    });
            sendOther.send();
        }
    }

    @Override
    protected void onDestroy() {
        super.onDestroy();
        mNotifyNotification.release();
    }

    private class MyNotificationInterface implements NotifyNotification.NotificationInterface {
        @Override
        public void onNotify() { // 通知を受信した
            // Linking デバイスからの通知内容は SharedPreferences に記録される
            SharedPreferences preference =
                    getSharedPreferences(Define.NotificationInfo, Context.MODE_PRIVATE);
            int DEVICE_ID = preference.getInt("DEVICE_ID", -1);
            int DEVICE_BUTTON_ID = preference.getInt("DEVICE_BUTTON_ID", -1);
            // Toast 表示
            Toast.makeText(mCtx, "onNotify: DEVICE_ID=" + DEVICE_ID +
                    " DEVICE_BUTTON_ID=" + DEVICE_BUTTON_ID, Toast.LENGTH_SHORT).show();
            // 音も鳴らす
            ToneGenerator toneGenerator
                           = new ToneGenerator(AudioManager.STREAM_SYSTEM, ToneGenerator.MAX_VOLUME);
            toneGenerator.startTone(ToneGenerator.TONE_CDMA_CALL_SIGNAL_ISDN_PING_RING);
        }
    }
}

試作の動作の様子

(動画:36秒 音なし)

Linking でのデバイス・アプリの設定手順

Linking 対応デバイスと Linking アプリを連携させるためには事前に設定が必要です。手順は以下の要領です。

  1. 端末に「Linking」をインストールする(未インストールの場合のみ)

             Linking(Android 版)- play.google.com

  2. 連携させるアプリ(ここでは自作の「Linking01」)のインストールを行い Linking を実行する
      
  3. 「デバイスの検索」を行い連携対象のデバイスを Linking に接続する(当該デバイスを未登録の場合のみ)
            
         
  4. デバイスの登録・接続が完了したら「デバイス詳細画面」へ移動し当該デバイスと連携させるアプリケーション(複数可。ここでは「Linking01」)を設定する
            
  5. Linking を抜け上の手順で設定したアプリを起動してデバイスとの連携を確認する
         

備考: デバイスの Linking への再接続について

手元の Android 5.1 端末の環境では以下の現象が見られます。Linking のバージョンは 2016年8月現在最新の「03.10.00000」です。

  • Linking に接続ずみのデバイスを Linking 上で「切断」すると再接続できなくなる
               
手元ではこの状況に以下の手順で対処しています。
  • Android の Bluetooth 設定において当該デバイスとのペアを解除してから Linking 上で再接続を行う
               
         
関連記事
(tanabe)
klab_gijutsu2 at 19:54
この記事のURLComments(0)TrackBack(0)IoT | Bluetooth
2016年07月27日

MySQL プロトコル上のテキストの闇

はてなブックマークに登録

MySQL 5.7 で JSON 型が追加されたのに関連して、私がメンテナをしている MySQL ドライバーで罠にハマったので、 MySQL のテキストプロトコルの闇を書き残しておくことにします。

Text Resultset

MySQL にクエリを投げるコマンドが COM_QUERY で、そのレスポンスとして返されるのが Text Resultset と呼ばれる一連のパケットです。その中身は次のようになっています。

  • column count (整数1つだけのパケット)
  • column definition * column count (各カラムの定義)
  • EOF
  • row * N (結果行数分)
  • EOF

この記事で注目するのは column definition パケット (定義) の中にある、 column_typecharacter set です。

Python の MySQL ドライバーは、この2つの値を元に、 row に含まれる各バイト列を Python の適切な型の値に変換しています。

なお、以降に書く MySQL の振る舞いは、 MySQL 5.7.13 に基いています。

Character Set の闇

Q. connection encoding が latin1 のコネクションで、UTF-8 の VARCHAR 型のカラムに保存された「こんにちは」を SELECT したとき、 column definition の charset と row に含まれるバイト列はどうなるでしょう?

  1. charset=utf8, row には UTF-8 のバイト列
  2. charset=latin1, row には latin1で "?????"

A. 2

どうやら、 Column Definition にある character set は Column Character Set と無関係に connection encoding になるようです。 カラム毎に変わらないなら、なんで Column Definition に character set 書いてるんでしょうね?

あと、カラムの値は、カラムのエンコーディングからコネクションのエンコーディングにサーバーサイドで変換されるようです。 テキストの関数を使う必要が無いのなら、 VARCHAR や TEXT より VARBINARY や BLOB 使ったほうがエンコーディングに関わる問題を踏みにくそうです。

TEXT 型の闇

column type の一覧 を見てみると、 VARCHAR, VAR_STRING, STRING, TINY_BLOB, MEDIUM_BLOB, LONG_BLOB, BLOB といった型があるのですが、 TEXT 型がありません。

Q. TEXT 型のカラムを SELECT したとき、 column definition の column_type は何になるでしょうか?

  1. VARCHAR
  2. STRING
  3. BLOB

A. 3

どうやら、 column_type は特にテキストとバイナリの区別を付けていないようですね。 区別付けないのはいいとして、型の名前として VARBINARY じゃなくて VARCHAR を使っているのに、 TEXT じゃなくて BLOB を使ってるのはどうなんでしょうか?テキストかバイナリのどちらかに寄せておいたほうが混乱が少ないと思うのですが。

さて、 Python ではテキストとバイナリを明確に区別したいです。 Java や C# もきっと同じだと思います。 その場合、 character set を見てテキストとバイナリを区別することができます。 character set が connection encoding と同じならテキストで、 binary ならバイナリです。

なお、 INT 型などは charset は binary が設定されます。 例えば 42 は ASCII の "42" として返ってくるので、文字列を10進整数としてパースしたい場合はいったん ASCII でデコードしてからパースすることになると思います。 これを擬似コードで書くとこうなります。

if column_type in [VARCHAR, VAR_STRING, ... 全ての文字列/バイナリ型]:
    if charset == CHARSET_BINARY:
        # バイト列
        return data
    else:
        return data.decode(connection_encoding)
else: # 文字列以外
    data = data.decode('ascii')  # ascii でデコードしておいて、
    return converters[column_type](data)  # column_type ごとに用意した変換関数で変換する

JSON 型の闇

column_type には JSON が追加されました。そして MySQL 内部では JSON は常に UTF-8 (utf8mb4) で扱っているはずです。

さて、 column definition の character set はどうなっているでしょうか?

Q. connection encoding が utf8 のコネクションで、JSON 型のカラムを SELECT したとき、 character set は?

  1. binary
  2. utf8
  3. utf8mb4

A. 1

きっとテキスト型とちがって、カラムに character set を保存して無いので、文字列/バイナリ型以外の整数型などと同じように binary を返してしまうんでしょうね。

Q. connection encoding が utf8 のコネクションで、 SELECT CAST('{"hello": "world"}' AS JSON) AS anon_1 したとき、 character set は?

  1. binary
  2. utf8
  3. utf8mb4

A. 2

カラムと違ってコネクションには character set があるので、 それを返しているんでしょうね。でも、整数型とかは SELECT 42 しても binary なんですよね…

さて、上に書いた擬似コードを見て、JSON型のカラムをテキストとして返すにはどうすればいいか考えてみましょう。

結論: プロトコルを考えるときは、受け取る側がシステマチックに 解釈できるように(個別のif文が少なくなるように)設計しましょうね!!

@methane


songofacandy at 21:40
この記事のURLComments(0)TrackBack(0)mysql 
2016年06月29日

vmprof-flamegraph を作りました

はてなブックマークに登録

vmprof-flamegraph を作ったのでその紹介をしておきます。

まず、サンプルとして Sphinx を使って Python のドキュメントをビルドしたときの vmprof 結果を flamegraph にしてみたので、どんなものかはこちらを見てみてください。

http://dsas.blog.klab.org/img_up/sphinx-prof.svg

flamegraph について

flamegraph の一般的な紹介については省略して、リンクだけ置いておきます。

公式サイト: http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html

日本語の紹介記事: http://d.hatena.ne.jp/yohei-a/20150706/1436208007

他にプロファイル結果をビジュアライズするツールとしては cachegrind 系 (kcachegrind, wincachegrind など) がありますが、 flamegraph の方がスタックトレースで 遅い部分が分かりやすいので最近のお気に入りです。

たとえばWebアプリで、ORMのクエリオブジェクトから実際のクエリを生成してそれを実行して結果をインスタンス化する処理が重い事がわかったとします。 その場合、 cachegrind 系でもどこから呼び出されているのが重いのかまではだいたい分かります。しかし flamegraph を使った場合は、 ここから呼び出された場合はインスタンス生成が重い(大量にオブジェクトを取得しているなど)、こっちから呼び出された場合はクエリビルドが重い (単純にクエリの実行回数が多いなど)、までひと目で把握することができます。

他のメリットとして、GUIアプリが不要でブラウザで見ることができるとか、 flamegraph.pl に食わせるデータファイルのテキスト形式が grep などのツールと親和性が高い (興味がある関数で grep してから食わせることができる) などのメリットがあり、使いやすいです。

このテキストファイルのフォーマットはシンプルで、各行が次のようになっています。

トップレベルの関数名;1段深い関数名;一番深い関数名  サンプル数

関数名としているところは実際にはなんでも良く、サンプル数も整数であれば何でも良いです。なのでCPU時間以外にもメモリ使用量とかいろんな目的で利用することができます。

vmprof について

PyPy プロジェクトで開発されている、 PyPy と CPython 用のサンプリングプロファイラです。

サンプリングプロファイラなので、サンプル間隔を長めにすればオーバーヘッドを小さくすることができ、本番環境で動かすことも可能です。

まだまだ開発中のプロジェクトですが、サンプリングプロファイラ好きなので積極的に使っています。

vmprof はビジュアライザとして独自の Web アプリを開発していて、実際に http://vmprof.com/ で動いています。 特に PyPy のプロファイル結果を見る場合、 JIT のウォームアップなども見ることができます。

この Web アプリは https://github.com/vmprof/vmprof-server を見れば(ある程度のPythonの知識があれば)簡単に動かすことができます。

vmprof-flamegraph について

簡単に動かせると言っても、プロファイル結果を見るためだけに社内でWebアプリを運用するのも面倒です。 CPython で動かしているアプリのプロファイルを見るだけなら flamegraph を使うほうがお手軽です。

ということで、 vmprof が生成するバイナリ形式のプロファイル結果を、 flamegraph.pl の入力フォーマットのテキストファイルに変換するのが vmprof-flamegraph になります。

インストール方法は、 flamegraph.pl を PATH が通ったディレクトリに置いておき、 vmprof をインストールした Python の環境で pip install vmprof-flamegraph するだけです。

その Python 環境の bin ディレクトリに vmprof-flamegraph.py がインストールされます。

使い方は次のような感じになります。

$ python3 -m vmprof -o profile.data <Pythonスクリプト>
$ vmprof-flamegraph.py profile.data | flamegraph.pl > profile.svg
$ open profile.svg  # Mac の場合

詳細は vmprof-flamegraph や flamegraph.pl のヘルプを見てください。


@methane


songofacandy at 17:27
この記事のURLComments(0)TrackBack(0)Python 
2016年06月24日

Python に現在実装中の Compact dict の紹介

はてなブックマークに登録

背景

2015年1月に、 PyPy の開発者Blogにこんな記事がポストされました。

Faster, more memory efficient and more ordered dictionaries on PyPy

その後リリースされた PyPy 2.5.1 から dict は挿入順を維持するようになり、メモリ使用量も削減されました。

一方 CPython では、 PEP 468 で、キーワード引数を **kwargs という形式の仮引数で受け取るときに、引数の順序を保存しようという提案がされました。

例えば、 SQLAlchemy のクエリーで .filter_by(name="methane", age=32) と書いたときに生成されるクエリーが WHERE name = "methane" AND age = 32 になるか WHERE age = 32 AND name="methane" になるか不定だったのが、ちゃんと順序を維持するようになるといったメリットがあります。

(filter_by は等式専用のショートカット関数であって、キーワード引数を使わない filter というメソッドを使えば順序も維持されます。)

この提案者は pure Python だった OrderedDict クラスをCで再実装して、 Python 3.5 から OrderedDict がより高速かつ省メモリになりました。 (dict の方の修正を避けたのは、それだけ dict が Python インタプリタのために複雑に最適化されているからです。)

しかし、Cで再実装されたとは言え、双方向リンクリストで順序を管理された OrderedDict はそれなりにオーバーヘッドがあります。特にメモリ使用量については、倍近い差があります。

Python 3.5.1 (default, Dec  7 2015, 17:23:22)
[GCC 4.2.1 Compatible Apple LLVM 7.0.0 (clang-700.1.76)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import sys
>>> d = {i:i for i in range(100)}
>>> from collections import OrderedDict
>>> od = OrderedDict((i,i) for i in range(100))
>>> sys.getsizeof(d), sys.getsizeof(od)
(6240, 11816)

そのせいもあり、まだ PEP 468 は止まったままになっています。

私も、一部のユースケースで便利だからといって、全てのキーワード引数の性能を落とす可能性がある変更には抵抗があり、また PyPy の実装した dict に興味があったので、 Python 3.6 にギリギリ間に合う今のうちに挑戦することにしました。

(予定では9月前半に beta リリースされ機能追加できなくなるので、それまでに実装、評価検証、MLでの議論などを経てマージされる必要があります)

データ構造

変更した構造体は PyDictKeysObject だけです。ただし、以前よりメモリレイアウトがより動的になります。

struct _dictkeysobject {
    Py_ssize_t dk_refcnt;
    Py_ssize_t dk_size;
    dict_lookup_func dk_lookup;
    Py_ssize_t dk_usable;
    Py_ssize_t dk_nentries;  /* How many entries is used. */
    char dk_indices[8];      /* dynamically sized. 8 is minimum. */
};

#define DK_SIZE(dk) ((dk)->dk_size)
#define DK_IXSIZE(dk) (DK_SIZE(dk) <= 0xff ? 1 : DK_SIZE(dk) <= 0xffff ? 2 : \
                       DK_SIZE(dk) <= 0xffffffff ? 4 : sizeof(Py_ssize_t))
#define DK_ENTRIES(dk) ((PyDictKeyEntry*)(&(dk)->dk_indices[DK_SIZE(dk) * \
                        DK_IXSIZE(dk)]))

dk_get_index(PyDictKeysObject *keys, Py_ssize_t i)
{
    Py_ssize_t s = DK_SIZE(keys);
    if (s <= 0xff) {
        return ((char*) &keys->dk_indices[0])[i];
    }
    else if (s <= 0xffff) {
        return ((PY_INT16_T*)&keys->dk_indices[0])[i];
    }
    else if (s <= 0xffffffff) {
        return ((PY_INT32_T*)&keys->dk_indices[0])[i];
    }
    else {
        return ((Py_ssize_t*)&keys->dk_indices[0])[i];
    }
}

dk_set_index(PyDictKeysObject *keys, Py_ssize_t i)
{
...

以前のハッシュテーブルは 3word (hash, key, value) の PyDictKeyEntry 構造体の配列でしたが、こちらの方式ではハッシュテーブルの要素をただの整数型にしています。 構造体の宣言では char dk_index[8] になっていますが、これは最小の dk_size が8の時の大きさで、実際にはアロケート時により大きいサイズを確保します。さらに、この整数型自体も dk_size が 128 までは char ですが 256 からは int16_t になります。このようにしてギリギリまでハッシュテーブルのサイズを小さくします。

さらに、 dk_indices のサイズが動的なので構造体に直接宣言できませんが、この構造体の後ろに PyDictKeyEntry 構造体の配列を置いています。この配列のサイズは dk_size ではなくその 2/3 (前回の記事で紹介した、このハッシュテーブルに挿入可能な最大要素数) にしています。新しい要素を挿入するときは、この配列に追記していき、そのインデックスを dk_indices に保存します。 dk_nentries は配列中の要素数になります。

挿入時の操作を、同じキーがまだ存在しないと仮定した擬似コードで示すとこうなります。

// dk_indices 内の挿入位置を検索
pos = lookup(keys, key, hash);

// エントリ配列にエントリを追記する
DK_ENTRIES(mp)[keys->dk_nentries].me_hash = hash;
DK_ENTRIES(mp)[keys->dk_nentries].me_key = key;
DK_ENTRIES(mp)[keys->dk_nentries].me_value = value;

// dk_indices にそのエントリのインデックスを保存
dk_set_index(keys, pos, keys->dk_nentries);

// 最後に使用済みエントリ数をインクリメント
mp->dk_nentries++;

削除

この dict からアイテムを削除するには、 dk_indices の該当位置にダミー要素を代入しておきます。 (各インデックスが1バイトで扱えるエントリー数が256までではなく128までなのは、マイナスの値をダミーと空を表すために利用しているからです。)

エントリーからの削除については2つの方式があります。

最初に compact dict のアイデアが Python の開発者MLに投稿されたときは、最後の要素を削除された要素があった位置に移動することで、エントリー配列を密に保っていました。この方式では最後の要素が前に来るので、「挿入順を保存する」という特性が要素を削除したときに失われます。

一方、 PyPy や今回僕が採用したのは、単に空いた場所に NULL を入れておくというものです。

// dk_indices 内の削除する要素のインデックスがある位置を検索
pos = lookup(keys, key, hash);
// 削除する要素のエントリー配列内の位置を取得する
index = dk_get_index(keys, pos);

// 要素を削除する
DK_ENTRIES(mp)[index].me_key = NULL;
DK_ENTRIES(mp)[index].me_value = NULL;

// dk_indices にダミーを登録
dk_set_index(keys, pos, DUMMY);

こちらの方式は、挿入と削除を繰り返したときにエントリー配列がダミーでいっぱいになってコンパクションを実行する必要があるというデメリットがあります。 しかし、実は最初に提案された方式でも、挿入と削除を繰り返すうちにハッシュテーブルがダミーで埋まってしまい検索ができなくなってしまう可能性があるので、どちらにしろコンパクションは必要になります。そのため、挿入順を維持する方が良いと判断しました。

ちなみに、 .popitem() は、エントリー配列のうち最後の要素を削除し、 dk_nentries をデクリメントすることで、平均計算量を O(1) に保っています。 この場合も dk_usable という「残り挿入可能数」をインクリメントしないので、削除と挿入を繰り返すとコンパクションを実行してハッシュテーブルを再構成します。

Shared-Key dict

さて、問題の shared key dict です。

最初は、 compact dict を実装する前と同じように、ハッシュテーブルにダミー要素を挿入せず、エントリー配列側が NULL になっていたらダミーと判断すれば良いと思っていました。

しかし、これでは shared key に最初に要素を追加した dict の挿入順しか保存することができません。

>>> class A:
...     pass
...
>>> a = A()
>>> b = A()
>>> a.a = 1
>>> a.b = 2
>>> b.b = 1
>>> b.a = 2
>>> a.__dict__.items()
dict_items([('a', 1), ('b', 2)])
>>> b.__dict__.items()  # 挿入順は b, a なのに、、、
dict_items([('a', 2), ('b', 1)])

この問題について、次の3つの方針を考えていますが、MLで議論した上でGuidoかGuidoが委任したコア開発者が最終決定するまでどれになるか分かりません。

(1) ありのままを受け入れる

今の Python の言語仕様では、 dict の順序は不定です。なので、「インスタンスの属性を管理する dict を除いて挿入順を保存する」という今の動作も、言語仕様的には問題ないことになります。

compact dict になると shared key dict も ma_values 配列のサイズが dk_keys からその 2/3 になってよりコンパクトになるので、その恩恵を完全に受ける事ができます。

一方、デメリットとしては、殆どのケースで挿入順を保存するように振る舞うので、言語仕様を確認しない人はそれが仕様だと誤解してしまうことがあります。 この問題は「誤解するほうが悪い」とするのは不親切です。 たとえば Go はこのデメリットを避けるために、 map をイテレートするときの順序を意図的に (高速な擬似乱数を使って) 不定にしています。

(2) 挿入順が違ったら shared key をやめる

shared key が持っている順序と違う順序で挿入されようとしたらすぐに shared key をやめるという方法があります。

一番無難な方法に見えますが、どれくらい shared key を維持できるのかわかりにくくてリソース消費が予測しにくくなるとか、稀に通るパスで挿入順が通常と違い、 shared key が解除されてしまうと、同じサイズの dict を同じくらい利用し続けてるのにメモリ使用量がじわじわ増えてくる、といった問題があります。

実行時間が長い Web アプリケーションなどのプログラムで、メモリ消費量が予測しづらく、じわじわ増えるのは、あまりうれしくありません。 なので私はこの方式に乗り気では無いです。

(3) Shared Key Dict をやめる

shared key dict は、ハマったときはとても効率がいいものの、 compact ordered dict の方が安定して効率がいいです。 しかも shared key dict をサポートするために、 dict の実装がだいぶ複雑になってしまっています。

実際に shared key dict を実装から削ってみた所、4100行中500行くらいを削除することができました。簡単に削除しただけなので、さらにリファクタリングして削れると思います。

一方効率は、 Python のドキュメントを Sphinx でビルドするときの maxrss を /usr/bin/time で計測した所、

  • shared: 176312k
  • compact + shared: 158104k
  • compact only: 166888k

という感じで、 shared key をやめても compact dict の効果によるメモリ削減の方が大きいという結果がでました。

(もちろんこれは1つのアプリケーションにおける結果でしか無いので、他に計測に適した、クラスやインスタンスをそこそこ使って実行時間とメモリ使用量が安定している現実のアプリケーションがあれば教えてください。)

また、 shared key を削除して実装を削れた分、別の効率のいい特殊化 dict を実装して、 compact + shared よりも高い効率を狙うこともできます。 今はあるアイデアのPOCを実装中なので、採用されたらまた紹介します。

OrderedDict

OrderedDict を compact dict を使って高速化する方法についても補足しておきます。

Python 3 には、 Python 2.7 には無かった move_to_end(key, last=True) というメソッドがあります。このキーワード引数がクセモノで、 move_to_end(key, last=False) とすると先頭に移動することができます。(機能はともかくメソッドの命名についてはとてもセンスが悪いと思います。 move_to_front(key) でええやん。)

この機能を実装するために、 dk_entries 配列をキャパシティ固定の動的配列ではなく、キャパシチィ固定の deque として扱うというアイデアを持っています。 つまり、今は dk_entries[0] から dk_entries[dk_nentries-1] までを使っているのですが、それに加えて先頭に要素を追加するときは dk_entries の後ろから先頭に向かって挿入していきます。

これを実現するには dk_nentries の反対版を作って、ハッシューテーブルの走査やリサイズがその部分を扱うように改造すれば良いです。 OrderedDict 1つあたり 1word (8byte) を追加するだけで、消費メモリを半減させることが可能なはずです。

ですが、Shared-Key 問題で手一杯なうえ、 dict が挿入順を保存するようになったら OrderedDict の利用機会も減ってしまうので、このアイデアを実装するモチベーションがありません。少なくとも Python 3.6 には(誰かが僕の代わりに実装してくれない限り)間に合わないでしょう。


@methane


songofacandy at 16:02
この記事のURLComments(0)TrackBack(0)Python 
2016年06月22日

Python の dict の実装詳解

はてなブックマークに登録

@methane です。

最近 Python の dict をハックしているので、その紹介をしたいと思います。 ですが、まずこの記事では現在 (Python 3.6a2) の dict の実装を詳解します。

データ構造

基本となる構造体は3つです。(Python 3.6a2 のソースより引用)

typedef struct _dictkeysobject PyDictKeysObject;

typedef struct {
    PyObject_HEAD
    Py_ssize_t ma_used;
    PyDictKeysObject *ma_keys;
    PyObject **ma_values;
} PyDictObject;

typedef struct {
    /* Cached hash code of me_key. */
    Py_hash_t me_hash;
    PyObject *me_key;
    PyObject *me_value; /* This field is only meaningful for combined tables */
} PyDictKeyEntry;

typedef PyDictKeyEntry *(*dict_lookup_func)
(PyDictObject *mp, PyObject *key, Py_hash_t hash, PyObject ***value_addr);

struct _dictkeysobject {
    Py_ssize_t dk_refcnt;
    Py_ssize_t dk_size;
    dict_lookup_func dk_lookup;
    Py_ssize_t dk_usable;
    PyDictKeyEntry dk_entries[1];
};

PyDictObject が dict のインスタンスを表すオブジェクトです。 PyObject_HEAD は Python のオブジェクトすべてが持っている共通の管理用データ(参照カウント等)を定義するマクロで、通常ビルドでは3ワード(64bit環境では24バイト)になります。

ma_used がその dict に入っている要素数、 ma_keys が動的に確保されるハッシュテーブルです。 ma_values については後述します。

PyDictKeyEntry はハッシュテーブルの各エントリとなる構造体です。 me_key, me_value が名前のままキーと対応する値となる Python オブジェクトへのポインタで、 me_hash は me_key のハッシュ値です。探索やハッシュテーブルの再構築のときに必要になるので毎回計算するのではなくてエントリーに持ってしまっています。

PyDictKeysObject がハッシュテーブルです。 dk_size がハッシュテーブルのサイズ、 dk_usable があと何要素ハッシュテーブルに入れられるかを示すカウンタです。 dk_usable が 0 のときに挿入しようとするとハッシュテーブルが再構築され、必要に応じて拡張されます。 dk_refcnt については ma_values とともに後で解説します。

dk_lookup は探索関数への関数ポインタです。 dict は例えば関数呼び出しのときに名前から関数を探索したりと、主に文字列をキーとして Python の言語の基本を支えているので、 key の型が文字列の dict に特殊化して高速にした関数を最初に入れておき、文字列以外のキーを挿入した段階で汎用の関数へのポインタに差し替えるなどを行っています。

dk_entries はハッシュテーブルの実態です。構造体の宣言では1要素の配列になっていますが、実際には次のように PyDictKeysEntry をアロケートすることで dk_size の長さを持つ配列になります。

    dk = PyObject_MALLOC(sizeof(PyDictKeysObject) +
                      sizeof(PyDictKeyEntry) * (size-1));

オープンアドレス法

ハッシュテーブルのサイズ (dk_size) は 2^n になっています。また、そのハッシュテーブルに格納できる要素数 (dk_usable の初期値) は (2*dk_size+1)/3 になっています。

dk_size が 2^n なので、ハッシュテーブルに要素を挿入したり、探索する場合は、ハッシュ値 & (dk_size-1) で場所を決めます。 (dk_size が 8 なら2進数で表すと 0b1000 で、 dk_size-1 が 7 = 0b0111 になり、ハッシュ値の下位3bitを利用することになる)

dk_usable が 0 になりハッシュテーブルを再構築する際、(削除操作がなく純粋に追加してきた場合は)dk_sizeが2倍になり、ハッシュテーブルの「密度」は 2/3 から 1/3 になります。なのでハッシュテーブルの密度は下限がだいたい 1/3 、上限が 2/3 になります。

さて、ハッシュ値が綺麗に分散しているとしたら、挿入時に利用されるハッシュ値の下位ビットの衝突率は 1/3 と 2/3 の平均で 1/2 程度になるでしょう。 実際にはハッシュ値は綺麗に分散しているとは限らないので、これより悪くなるはずです。

ハッシュ法で衝突に対処する方法としては、要素をハッシュテーブル外のリストなどに置いてハッシュテーブルにはそこへの参照を格納する方法(オープンハッシュ法)と、ハッシュテーブル内の別の場所に格納する方法(クローズドハッシュ法、またはオープンアドレス法。「オープン」が全く逆のオープンハッシュ法と被るので紛らわしいです)がありますが、 Python はクローズドハッシュ法を採用しています。

クローズドハッシュ法では、「衝突したら次はどこを使うか」というアルゴリズムを決めておいて、挿入も探索も同じ方法を使わなければなりません。 メモリアクセスの効率を考えると衝突した場所の隣の場所を使うのが良いのですが、ハッシュ値が良くなくて衝突が頻発したときや、ハッシュテーブル内に偏りが発生した場合に、次も、その次も、その次も、という感じに衝突する可能性が高くなります。

ハッシュテーブル内を飛び飛びに巡回し、最終的にはテーブル内の全要素を1回ずつ走査する関数が欲しいのですが、その関数として Python は (5*i+1) mod dk_size を採用しています。 例えば dk_size が 8 で ハッシュ値の下位3bitが 3 なら、ハッシュテーブルを 3, 0, 1, 6, 7, 4, 5, 2, 3 という形で、 0~7 を1度ずつ通って最初の 3 に戻ってきます。

しかし、この方法ではハッシュテーブル内の密度の偏りの影響を避けられるものの、ハッシュ値の下位ビットが衝突する key は同じ順番に巡回するので線形探索になってしまい効率が悪いという欠点があります。そこで、先程の関数を改造して、次のようにしています。

    for (perturb = hash; ; perturb >>= PERTURB_SHIFT) {
        i = i * 5 + perturb + 1;

これで、最初のうちはハッシュ値の上位ビットを使って次の位置を決定していき、ハッシュ値を右シフト仕切ったら先ほどのアルゴリズムで確実に巡回する、というハイブリッド型の巡回アルゴリズムになります。

(ちなみに、このforループには最初の衝突のあとにくるので、 perturb の初期値が hash のままだと、hash 値の下位ビットが衝突する key と1つ目だけでなく2つ目も衝突してしまいますね…)

(なお、 dict よりも最近に改良された set 型では、最初はキャッシュ効率を重視して近くの要素を探すといった改良がされています。)

削除

オープンアドレス法での要素の削除には注意が必要です。というのは、探索や挿入のときの巡回は、同じキーか空きを発見したときに停止するからです。

あるキーAを挿入するときに別のキーBと衝突して別の場所に挿入したのに、その別のキーBが削除されて空きになってしまうと、キーAをまた探索するときに、キーBがあった場所に空きを見つけて、キーAはハッシュテーブルに存在しないと判断してしまいます。

これを避けるために、削除するときはハッシュテーブルを空きに戻すのではなく、ダミー要素に入れ替えます。

また、 popitem() という dict の中の任意の (key, value) を取得しつつ削除するメソッドの実装にも注意が必要です。 ハッシュテーブルを線形探索して、最初に見つけた要素を返し、その場所をダミーに置き換えるのですが、これを繰り返すとハッシュテーブルがダミー要素だらけになっていって、次のようなアルゴリズムの実行時間が O(n**2) になってしまいます。

while d:
    k, v = d.popitem()
    do_something(k, v)

popitem() の平均計算量を O(1) にするために、ハッシュテーブルの先頭に要素があればそれを返し、無かった場合は線形探索した後に、次に線形探索を開始する場所を(空、あるいはダミーkeyが入っている)先頭要素の me_value に格納しておきます。

PEP 412: Key-Sharing Dictionary

次のインタラクティブセッションでは、2つの空の dict のメモリ使用量を表示しています。

>>> d = {}
>>> class A: pass
...
>>> a = A()
>>> ad = a.__dict__  # a の属性を格納している dict のインスタンス
>>> d
{}
>>> ad
{}
>>> type(d), type(ad)
(<class 'dict' at 0x109c735b0>, <class 'dict' at 0x109c735b0>)
>>> import sys
>>> sys.getsizeof(d)
288
>>> sys.getsizeof(ad)
96

両方共確かに dict の空のインスタンスなのですが、サイズは 288 バイトと 96 バイトと、3倍近くの差があります。なぜでしょうか?

ここで、説明を省略していた PyDictKeysObject の dk_refcnt と PyDictObject の ma_values が登場します。

dk_refcnt は参照カウントになっていて、A のインスタンス a を作った際、 a の属性を管理する dict インスタンスを作った後、その PyDictKeysObject の dk_refcnt をインクリメントして、クラス A にポインタをもたせます。

その後、クラスAのインスタンスを作る際は、そのインスタンス用の dict を作るときに PyDictKeysObject を作るのではなく、クラスAが持っているオブジェクトを参照し、参照カウントをインクリメントします。このように、同じクラスの複数のインスタンス間で、 PyDictKeysObject は共有されます。

ハッシュテーブルを共有しているので、 me_value に各 dict が持つはずの値を格納することができません。 PyDictObject の ma_values に、 dk_size と同じ大きさの PyObject* の配列を持たせて、 dk_entries[i].me_value の代わりに ma_values[i] に値を格納します。

dk_entries は各要素がポインタ3つ分の大きさを持っている一方で、 ma_values はポインタ1つ分で済むので、これでかなりのサイズを削減できます。

また、 dk_usable の初期値が (dk_size*2)/3 ではなく (dk_size*2+1)/3 になっていたのにも秘密があります。

通常の dict では dk_size の最小値が 8 なのですが、 key sharing dict では dk_size が 4 になっているのです。 (4*2)/3 は 2 なのに対して、 (4*2+1)/3 は3になるので、この最小の key sharing dict は3つの要素を格納することができるのです。

この結果、属性が3つ以下のインスタンスは 64bit 環境では 96 バイトの dict で属性を管理することができるのです。

この key sharing dict は、 Python 3.4 で導入されました。 (ちなみに 3.4 ではバグでサブクラスで有効にならなかったのが、 3.4.1 で解消されました)

この素敵な新機能が、 dict をハックしていた僕を、単純に実装を複雑にしたり考えないといけないケースを増やすというだけでなく、かなり重い意味で苦しめることになります。

その話は次回の記事で解説します。


@methane


songofacandy at 17:01
この記事のURLComments(0)TrackBack(0)Python 
2016年06月03日

pixiv private isucon 2016 攻略 (5/5)

はてなブックマークに登録

攻略記事一覧:

ボトルネック探し

前回は一番重かったトップページにページキャッシュを導入して劇的に高速化したものの、CPU以外がボトルネックになって大した高速化はできませんでした。 こういう場合は dstat が役に立つことが多いです。

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  2   0  98   0   0   0| 596k  271k|   0     0 |   0     0 | 606   755
  1   0 100   0   0   0|   0     0 | 192B 1190B|   0     0 | 119   177
  0   0 100   0   0   0|   0     0 |  66B  350B|   0     0 | 103   158
  1   0  98   1   0   0| 512k    0 | 537B  783B|   0     0 | 962  1035
 48   7  38   3   0   5|  16M  728k|4590k   60M|   0     0 |  24k   20k
 44   7  36   5   0   8|  11M  376k|6568k   71M|   0     0 |  34k   26k
 44  11  35   4   0   7|  18M  312k|6190k   71M|   0     0 |  33k   27k
 48   8  33   3   0   8|  14M  272k|7784k   71M|   0     0 |  31k   24k
 41   7  42   4   0   6|  17M  352k|8097k   72M|   0     0 |  31k   23k
 44   9  38   4   1   5|  14M  256k|8019k   71M|   0     0 |  33k   25k
 44  10  35   3   0   8|  10M  448k|7705k   71M|   0     0 |  32k   25k
 36   9  46   3   0   6|  14M  224k|7196k   71M|   0     0 |  32k   22k
 38  10  39   6   0   7|  16M   18M|7812k   71M|   0     0 |  31k   22k
 47   9  28  11   0   4|  20M   47M|6683k   72M|   0     0 |  29k   19k
 45   7  39   3   0   6|  10M  696k|6113k   71M|   0     0 |  33k   24k
 42   7  39   4   0   8|  12M  672k|3825k   71M|   0     0 |  33k   24k
 51   8  31   3   0   6|  13M  512k|6750k   71M|   0     0 |  31k   22k
 44   9  39   2   0   5|5496k  648k|8045k   71M|   0     0 |  32k   24k
 53   9  28   3   0   6|  20M  544k|5832k   71M|   0     0 |  29k   20k
 41   7  42   3   0   7|  14M  616k|7459k   71M|   0     0 |  35k   24k
 48   9  31   4   0   8|  17M  608k|5869k   71M|   0     0 |  30k   23k
 38  11  40   3   0   8|  14M  752k|8956k   71M|   0     0 |  32k   24k
 44  11  36   4   0   5|  13M  576k|7181k   71M|   0     0 |  33k   25k
 47   7  35   7   0   5|  14M   62M|5753k   65M|   0     0 |  30k   22k
...

net の send が 71M で張り付いてるのが目につきますね。アプリサーバーは c4.large なのでこんなもんでしょう。

ですが、 pixiv さんの Blog 記事 のスクリーンショットを見ると、多くのチームが 40k 点を超えていて、トップチームは180k点に到達しています。こっちは40k点の手前で帯域の壁にぶつかってるのに、変だぞ? (Twitter で pixiv の @catatsuy さんに、ポータルのスコアとコマンドラインによるベンチマーカーのスコアが同一であることを確認しました。)

さて、2つ目の記事で、次のように言っていましたね。

帯域は /image/ が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。

試しにクライアントのキャッシュ実装に影響を与えそうなヘッダーを追加してみましょう。 "nginx 静的ファイル キャッシュ" でググってそれっぽいのを探します

  upstream app {
    server 127.0.0.1:8080;
    keepalive 64;
  }

server {
  listen 80;

  client_max_body_size 10m;
  root /home/isucon/private_isu/webapp/public/;

  location / {
    try_files $uri @app;
  }
  location ~* \.(?:ico|css|js|gif|jpe?g|png)$ {
    try_files $uri @app;
    expires max;
    add_header Pragma public;
    add_header Cache-Control "public, must-revalidate, proxy-revalidate";
    etag off;
  }
  location @app {
    proxy_set_header Host $host;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_pass http://app;
  }
}

計測してみます。

スコア:

{"pass":true,"score":182435,"success":174747,"fail":0,"messages":[]}

pixiv 社内 isucon のトップと同じくらいのスコアがでました。(これはプロファイルを取ったりいろいろしながらのスコアなので、仕上げしたらもう少し伸びるはずです)

top, dstat:

Tasks:  81 total,   3 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 80.7 us, 11.5 sy,  0.0 ni,  3.0 id,  0.5 wa,  0.0 hi,  4.2 si,  0.0 st
KiB Mem:   1022972 total,   954144 used,    68828 free,    25432 buffers
KiB Swap:        0 total,        0 used,        0 free.   557948 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1397 isucon    20   0  377096  97572   8880 S 100.5  9.5   0:27.35 app.dc4a3eaa
  731 mysql     20   0 1059292 183956  10552 S  65.9 18.0   2:26.08 mysqld
 1396 www-data  20   0   92088   5304   3144 R  18.6  0.5   0:04.99 nginx
 1069 isucon    20   0   33140  10476   2636 S   5.7  1.0   0:12.10 tmux
  308 memcache  20   0  334624   9744   2228 S   0.7  1.0   0:01.38 memcached
  110 root      20   0       0      0      0 S   0.3  0.0   0:00.08 jbd2/xvda2-8
 1034 root      20   0       0      0      0 S   0.3  0.0   0:02.89 kworker/1:0
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  0   0 100   0   0   0|   0     0 |   0     0 |   0     0 |  45    76 
 21   5  71   2   0   1|  11M    0 |1987k   12M|   0     0 |8731  9184 
 73  15   5   2   0   5|  17M  904k|4574k   25M|   0     0 |  19k   20k
 78  13   3   1   0   6|  20M  272k|3815k   18M|   0     0 |  15k   17k
 80   9   6   2   0   4|  25M  272k|7221k   20M|   0     0 |  16k   17k
 81  11   4   1   0   4|  18M  272k|5953k   20M|   0     0 |  15k   16k
 81  10   4   0   0   5|  24M  256k|5363k   24M|   0     0 |  15k   17k
 76  13   6   2   0   4|  20M  272k|8293k   18M|   0     0 |  16k   17k
 82  11   2   1   0   5|  15M  552k|2665k   18M|   0     0 |  16k   16k
 80  14   3   1   0   4|  14M  408k|2870k   15M|   0     0 |  15k   16k
 79  12   5   1   0   4|  16M  360k|5475k   19M|   0     0 |  17k   18k
 79  11   5   2   0   3|  16M   65M|5456k   21M|   0     0 |  15k   16k
 77  12   6   1   0   4|  19M  760k|6763k   23M|   0     0 |  19k   20k
 79  12   4   2   0   4|  23M  592k|6824k   19M|   0     0 |  16k   17k
 79  12   5   2   0   3|  11M  632k|5994k   20M|   0     0 |  16k   18k
 82  11   3   1   0   4|  11M  680k|3447k   16M|   0     0 |  15k   17k
 83  11   2   0   0   4|  13M  792k|5076k   18M|   0     0 |  16k   18k
...

CPUを使い切るようになったのが判ります。

access.log 集計:

Request by count
117444 GET /image/*
7987 GET /
6394 GET /js/jquery-2.2.0.js
6394 GET /css/style.css
6394 GET /js/jquery.timeago.ja.js
6394 GET /favicon.ico
6394 GET /js/jquery.timeago.js
6394 GET /js/main.js
4028 POST /login
1459 GET /login
1176 GET /posts/*
959 POST /register
958 GET /admin/banned
873 GET /@user
731 GET /logout
609 POST /
330 GET /posts?max_created_at=
268 POST /comment
1 GET /initialize

Request by total time
98.996 0.299987878788 GET /posts?max_created_at=
84.66 0.0105997245524 GET /
84.077 0.0963081328751 GET /@user
52.172 0.0129523336643 POST /login
39.666 0.0337295918367 GET /posts/*
33.621 0.0552068965517 POST /
19.801 0.0738843283582 POST /comment
17.144 0.0117505140507 GET /login
...

Request by out bytes
894159053 7613 GET /image/*
185613643 23239 GET /
16456443 18850 GET /@user
11202870 33948 GET /posts?max_created_at=
4098331 3484 GET /posts/*
...

image の転送量が大幅に減ったことが確認できます。また、集計せずに access.log を見ると、狙い通り 304 を返せていることが判ります。

(余談) 壁の超え方

2つ目の記事で 304 Not Modified を返せることを予想していたのは、エスパーでもなんでもありません。一昨年 (2014年) の決勝であったんです。その時はこの壁を超えられず悔しい思いをしました。

その時、壁を超えたチームが2チームありました。準優勝チームは静的ファイルを返すための nginx の設定のテンプレ(いわゆる「秘伝のタレ」)を使ったらいきなりスコアが上がったけど何が起こったのか設定した本人にも分からなかった、そして優勝チームは順優勝チームのスコアを見て「必ず壁を超える方法があるはずだ」と試行錯誤した結果壁を超えたと記憶しています。(興味がある方は当時の blog 記事を探してみてください)

「秘伝のタレ」が偶然ハマる、という壁の超え方は準備の賜物です。 個人的にはチューニングするときはパラメーターを1つ1ついじって効果確認したいところですが、それだと時間がもったいないし、ベンチマーカーの挙動についての予想が当てられないと壁が超えられないので、やはり「秘伝のタレ」は強力な武器になります。

一方、ベンチマーカーの動作を予想し試行錯誤するやり方は、問題作成側の心理を読む ISUCON 力、可能性のある試行錯誤をするための引き出し(今回でいえば HTTP ヘッダーとキャッシュに関する知識)、精神力などが求められます。 過去に決勝で優勝したチームはどれもこの能力が特に優れていたチームだと思います。難しいですが優勝を目指して勉強と鍛錬をしましょう。

雑巾絞り

CPUネックになったことですし、CPUプロファイルを見てみましょう。

(pprof) top30 -cum
7.63s of 29.87s total (25.54%)
Dropped 601 nodes (cum <= 0.15s)
Showing top 30 nodes out of 296 (cum >= 4.36s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     28.68s 96.02%  runtime.goexit
         0     0%     0%     24.58s 82.29%  net/http.(*conn).serve
         0     0%     0%     23.35s 78.17%  net/http.(*ServeMux).ServeHTTP
         0     0%     0%     23.35s 78.17%  net/http.serverHandler.ServeHTTP
         0     0%     0%     23.32s 78.07%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0%     0%     23.30s 78.00%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0%     0%     23.30s 78.00%  github.com/zenazn/goji/web/middleware.RequestID.func1
         0     0%     0%     23.30s 78.00%  net/http.HandlerFunc.ServeHTTP
         0     0%     0%     23.25s 77.84%  github.com/zenazn/goji/web/middleware.Logger.func1
         0     0%     0%     22.71s 76.03%  github.com/zenazn/goji/web.(*mStack).newStack.func1
     0.01s 0.033% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web.(*router).route
         0     0% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
         0     0% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web/middleware.Recoverer.func1
     0.01s 0.033% 0.067%     18.11s 60.63%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0% 0.067%     12.85s 43.02%  main.getPosts
         0     0% 0.067%     12.46s 41.71%  github.com/jmoiron/sqlx.(*DB).Select
         0     0% 0.067%     12.46s 41.71%  github.com/jmoiron/sqlx.Select
     0.07s  0.23%   0.3%     11.69s 39.14%  github.com/jmoiron/sqlx.scanAll
     1.72s  5.76%  6.06%      9.78s 32.74%  runtime.mallocgc
     0.16s  0.54%  6.60%      8.62s 28.86%  runtime.systemstack
     5.02s 16.81% 23.40%      7.29s 24.41%  runtime.scanobject
     0.15s   0.5% 23.90%      5.91s 19.79%  runtime.newobject
         0     0% 23.90%      5.33s 17.84%  runtime.gcAssistAlloc
         0     0% 23.90%      5.33s 17.84%  runtime.gcAssistAlloc.func1
     0.04s  0.13% 24.04%      5.33s 17.84%  runtime.gcDrainN
     0.04s  0.13% 24.17%      5.22s 17.48%  database/sql.(*Rows).Next
     0.03s   0.1% 24.27%      5.04s 16.87%  github.com/go-sql-driver/mysql.(*textRows).Next
     0.34s  1.14% 25.41%      5.01s 16.77%  github.com/go-sql-driver/mysql.(*textRows).readRow
         0     0% 25.41%      4.55s 15.23%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.04s  0.13% 25.54%      4.36s 14.60%  main.makePosts


(pprof) list getPosts
Total: 29.87s
ROUTINE ======================== main.getPosts in /home/isucon/private_isu/webapp/golang/app.go
         0     12.85s (flat, cum) 43.02% of Total
         .          .    593:           fmt.Println(terr)
         .          .    594:           return
         .          .    595:   }
         .          .    596:
         .          .    597:   results := []Post{}
         .     11.19s    598:   rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT
))
         .          .    599:   if rerr != nil {
         .          .    600:           fmt.Println(rerr)
         .          .    601:           return
         .          .    602:   }
         .          .    603:
         .      1.03s    604:   posts, merr := makePosts(results, getCSRFToken(r), false)
         .          .    605:   if merr != nil {
         .          .    606:           fmt.Println(merr)
         .          .    607:           return
         .          .    608:   }
         .          .    609:
         .          .    610:   if len(posts) == 0 {
         .          .    611:           w.WriteHeader(http.StatusNotFound)
         .          .    612:           return
         .          .    613:   }
         .          .    614:
         .          .    615:   fmap := template.FuncMap{
         .          .    616:           "imageURL": imageURL,
         .          .    617:   }
         .          .    618:
         .          .    619:   template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
         .       10ms    620:           getTemplPath("posts.html"),
         .          .    621:           getTemplPath("post.html"),
         .      620ms    622:   )).Execute(w, posts)
         .          .    623:}
         .          .    624:
         .          .    625:func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
         .          .    626:   pid, err := strconv.Atoi(c.URLParams["id"])
         .          .    627:   if err != nil {

(pprof) list makePosts
Total: 29.87s
ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
      40ms      4.36s (flat, cum) 14.60% of Total
         .          .    188:}
         .          .    189:
         .          .    190:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
         .          .    191:   var posts []Post
         .          .    192:
         .       20ms    193:   for _, p := range results {
         .      720ms    194:           err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
         .          .    195:           if err != nil {
         .          .    196:                   return nil, err
         .          .    197:           }
         .          .    198:
         .          .    199:           query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
         .          .    200:           if !allComments {
         .          .    201:                   query += " LIMIT 3"
         .          .    202:           }
         .          .    203:           var comments []Comment
         .      920ms    204:           cerr := db.Select(&comments, query, p.ID)
         .          .    205:           if cerr != nil {
         .          .    206:                   return nil, cerr
         .          .    207:           }
         .          .    208:
         .          .    209:           for i := 0; i < len(comments); i++ {
      20ms      1.89s    210:                   uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
         .          .    211:                   if uerr != nil {
         .          .    212:                           return nil, uerr
         .          .    213:                   }
         .          .    214:           }
         .          .    215:
         .          .    216:           // reverse
         .          .    217:           for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
         .          .    218:                   comments[i], comments[j] = comments[j], comments[i]
         .          .    219:           }
         .          .    220:
         .          .    221:           p.Comments = comments
         .          .    222:
      20ms      780ms    223:           perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
         .          .    224:           if perr != nil {
         .          .    225:                   return nil, perr
         .          .    226:           }
         .          .    227:
         .          .    228:           p.CSRFToken = CSRFToken
         .          .    229:
         .          .    230:           if p.User.DelFlg == 0 {
         .       30ms    231:                   posts = append(posts, p)
         .          .    232:           }
         .          .    233:           if len(posts) >= postsPerPage {
         .          .    234:                   break
         .          .    235:           }
         .          .    236:   }

getPosts が重いのは、前に getIndex が重いのを直した時と同じく、 LIMIT すれば良さそうですね。

makePosts もクエリを投げすぎているので、 Post の取得とその User の取得は INNER JOIN で一気にする、コメント一覧はメモリ上にキャッシュしてしまうことにします。 あとテンプレートのコンパイルも事前にするようにしていきます。 Go アプリ側で出力しているログも tmux や ssh の CPU を食ってるのでそろそろ止めてしまいましょう。 (nginx のログを止めるのは一番最後です)

diff --git a/app.go b/app.go
index f246ad6..eca8413 100644
--- a/app.go
+++ b/app.go
@@ -187,54 +184,78 @@ func getFlash(w http.ResponseWriter, r *http.Request, key string) string {
 	}
 }
 
-func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
-	var posts []Post
+var (
+	commentM     sync.Mutex
+	commentStore map[int][]Comment = make(map[int][]Comment)
+)
 
-	for _, p := range results {
-		err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
+func getCommentsLocked(postID int) []Comment {
+	if cs, ok := commentStore[postID]; ok {
+		return cs
+	}
+
+	var cs []Comment
+	query := ("SELECT comments.id, comments.comment, comments.created_at, users.id, users.account_name " +
+		" FROM `comments` INNER JOIN users ON comments.user_id = users.id " +
+		" WHERE `post_id` = ? ORDER BY comments.`created_at`")
+
+	rows, err := db.Query(query, postID)
+	if err != nil {
+		log.Println(err)
+		return cs
+	}
+	for rows.Next() {
+		var c Comment
+		err := rows.Scan(&c.ID, &c.Comment, &c.CreatedAt, &c.User.ID, &c.User.AccountName)
 		if err != nil {
-			return nil, err
+			log.Println(err)
+			continue
 		}
+		cs = append(cs, c)
+	}
+	rows.Close()
 
-		query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
-		if !allComments {
-			query += " LIMIT 3"
-		}
-		var comments []Comment
-		cerr := db.Select(&comments, query, p.ID)
-		if cerr != nil {
-			return nil, cerr
-		}
+	commentStore[postID] = cs
+	return cs
+}
 
-		for i := 0; i < len(comments); i++ {
-			uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
-			if uerr != nil {
-				return nil, uerr
-			}
-		}
+func getComments(postID int) []Comment {
+	commentM.Lock()
+	defer commentM.Unlock()
+	return getCommentsLocked(postID)
+}
 
-		// reverse
-		for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
-			comments[i], comments[j] = comments[j], comments[i]
-		}
+func appendComent(c Comment) {
+	commentM.Lock()
+	cs := getCommentsLocked(c.PostID)
+	commentStore[c.PostID] = append(cs, c)
+	commentM.Unlock()
+}
+
+func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
+	var posts []Post
 
+	for _, p := range results {
+		comments := getComments(p.ID)
+		if !allComments && len(comments) > 3 {
+			comments = comments[len(comments)-3:]
+		}
 		p.Comments = comments
+		p.CSRFToken = CSRFToken
 
 		perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
 		if perr != nil {
 			return nil, perr
 		}
 
-		p.CSRFToken = CSRFToken
-
-		if p.User.DelFlg == 0 {
-			posts = append(posts, p)
+		if p.User.DelFlg != 0 {
+			continue
 		}
+		posts = append(posts, p)
 		if len(posts) >= postsPerPage {
 			break
 		}
 	}
-
 	return posts, nil
 }
 
@@ -411,8 +432,9 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
 }
 
 var (
-	indexTemplate *template.Template
-	postsTemplate *template.Template
+	indexTemplate       *template.Template
+	postsTemplate       *template.Template
+	accountNameTempalte *template.Template
 
 	indexPostsM         sync.Mutex
 	indexPostsT         time.Time
@@ -434,6 +456,13 @@ func init() {
 		getTemplPath("posts.html"),
 		getTemplPath("post.html"),
 	))
+
+	accountNameTempalte = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+		getTemplPath("layout.html"),
+		getTemplPath("user.html"),
+		getTemplPath("posts.html"),
+		getTemplPath("post.html"),
+	))
 }
 
 func renderIndexPosts() {
@@ -506,7 +535,6 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 	}
 
 	results := []Post{}
-
 	rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = ? ORDER BY `created_at` DESC", user.ID)
 	if rerr != nil {
 		fmt.Println(rerr)
@@ -527,12 +555,10 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 	}
 
 	postIDs := []int{}
-	perr := db.Select(&postIDs, "SELECT `id` FROM `posts` WHERE `user_id` = ?", user.ID)
-	if perr != nil {
-		fmt.Println(perr)
-		return
+	for _, r := range results {
+		postIDs = append(postIDs, r.ID)
 	}
-	postCount := len(postIDs)
+	postCount := len(results)
 
 	commentedCount := 0
 	if postCount > 0 {
@@ -557,16 +583,7 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 
 	me := getSessionUser(r)
 
-	fmap := template.FuncMap{
-		"imageURL": imageURL,
-	}
-
-	template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
-		getTemplPath("layout.html"),
-		getTemplPath("user.html"),
-		getTemplPath("posts.html"),
-		getTemplPath("post.html"),
-	)).Execute(w, struct {
+	accountNameTempalte.Execute(w, struct {
 		Posts          []Post
 		User           User
 		PostCount      int
@@ -595,7 +612,7 @@ func getPosts(w http.ResponseWriter, r *http.Request) {
 	}
 
 	results := []Post{}
-	rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT))
+	rerr := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 AND posts.`created_at` <= ? ORDER BY `created_at` DESC LIMIT 20", t.Format(ISO8601_FORMAT))
 	if rerr != nil {
 		fmt.Println(rerr)
 		return
@@ -806,9 +823,24 @@ func postComment(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
-	db.Exec(query, postID, me.ID, r.FormValue("comment"))
-
+	now := time.Now()
+	commentStr := r.FormValue("comment")
+	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`, `created_at`) VALUES (?,?,?,?)"
+	res, err := db.Exec(query, postID, me.ID, commentStr, now)
+	if err != nil {
+		log.Println(err)
+		return
+	}
+	lid, _ := res.LastInsertId()
+	c := Comment{
+		ID:        int(lid),
+		PostID:    postID,
+		UserID:    me.ID,
+		Comment:   commentStr,
+		CreatedAt: now,
+		User:      me,
+	}
+	appendComent(c)
 	renderIndexPosts()
 	http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
 }
@@ -921,6 +953,7 @@ func main() {
 
 	go http.ListenAndServe(":3000", nil)
 
+	goji.DefaultMux = web.New()
 	goji.Get("/initialize", getInitialize)
 	goji.Get("/login", getLogin)
 	goji.Post("/login", postLogin)

計測

スコア:

{"pass":true,"score":271542,"success":256436,"fail":0,"messages":[]}

pixiv 社内 isucon の優勝チームのスコアを超えることができたと思います。

top:

ks:  82 total,   4 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 57.1 us, 13.8 sy,  0.0 ni, 16.5 id,  5.1 wa,  0.0 hi,  7.3 si,  0.2 st
KiB Mem:   1022972 total,   926504 used,    96468 free,    27152 buffers
KiB Swap:        0 total,        0 used,        0 free.   432620 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                 1494 isucon    20   0  544796 191292   8940 S  81.5 18.7   0:29.06 app.7f063c1
  731 mysql     20   0 1125024 182444  10552 S  44.9 17.8   3:04.05 mysqld
 1524 www-data  20   0   92056   5276   3140 R  27.6  0.5   0:09.65 nginx
  308 memcache  20   0  336672  11756   2228 S   1.7  1.1   0:02.25 memcached
   31 root      20   0       0      0      0 S   0.7  0.0   0:00.40 kswapd0
   89 root       0 -20       0      0      0 S   0.3  0.0   0:00.73 kworker/0:1H
    1 root      20   0   28636   4736   3100 S   0.0  0.5   0:01.31 systemd

ちょっと idle が出てきたかな。

dstat:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  0   0 100   0   0   0|   0     0 |   0     0 |   0     0 |  82   283 
 11   3  82   2   0   2|  12M    0 |1684k   15M|   0     0 |7607  5952 
 55  13  17   9   0   7|  49M  864k|  11M   44M|   0     0 |  27k   20k
 58  15  14   8   0   6|  48M  416k|  13M   43M|   0     0 |  28k   20k
 48  14  21  12   0   5|  43M   63M|  12M   40M|   0     0 |  25k   19k
 55  17  14   7   0   7|  48M  528k|  14M   42M|   0     0 |  25k   18k
 55  12  19   8   0   6|  45M  488k|  12M   42M|   0     0 |  27k   20k
 52  17  16   6   0   8|  35M  592k|  14M   38M|   0     0 |  27k   19k
 50  12  19  14   0   6|  34M   59M|  11M   38M|   0     0 |  25k   17k
 56  12  18   6   0   7|  42M  720k|  11M   45M|   0     0 |  28k   20k
 51  15  18   9   0   8|  45M  704k|  14M   39M|   0     0 |  26k   19k
 52  17  17   7   0   7|  39M 3936k|  14M   45M|   0     0 |  27k   19k
 47  17  18  13   0   5|  41M   56M|  12M   39M|   0     0 |  24k   17k
 53  13  19   9   0   6|  45M  848k|  13M   41M|   0     0 |  27k   20k
 57  15  16   6   0   6|  38M  776k|  13M   42M|   0     0 |  27k   19k
 53  14  20   9   0   4|  28M   58M|  11M   29M|   0     0 |  24k   16k
 53  13  19   6   0   8|  44M  672k|  13M   38M|   0     0 |  26k   18k
 57  13  16   9   0   6|  46M  872k|  10M   38M|   0     0 |  25k   18k
 53  12  22   7   0   6|  44M  776k|  12M   41M|   0     0 |  28k   20k
 54  16  16   8   0   6|  33M   57M|9049k   33M|   0     0 |  24k   18k
 51  16  21   5   0   7|  32M  888k|  12M   38M|   0     0 |  27k   19k
 54  13  19   7   0   7|  49M 2264k|  11M   46M|   0     0 |  26k   18k
 54  14  19   6   0   7|  36M  680k|  12M   42M|   0     0 |  28k   19k
 48  16  19  10   0   7|  33M   52M|  14M   31M|   0     0 |  23k   16k
 55  15  15   7   0   7|  42M  720k|  12M   34M|   0     0 |  26k   20k
 59  14  17   5   0   6|  33M  744k|  12M   35M|   0     0 |  25k   18k
 47  15  25   7   0   6|  34M  736k|9604k   43M|   0     0 |  28k   19k
 47  11  27   8   0   6|  31M   51M|  12M   39M|   0     0 |  25k   17k
 54  18  17   5   0   7|  34M  816k|  12M   33M|   0     0 |  27k   20k
 55  16  16   6   0   6|  35M  888k|  14M   34M|   0     0 |  27k   19k
 57  13  18   6   0   6|  34M  720k|  11M   37M|   0     0 |  27k   19k
 52  12  18  12   0   6|  36M   53M|  11M   34M|   0     0 |  23k   17k
 62  12  15   4   0   7|  26M  720k|9309k   29M|   0     0 |  25k   19k
 46  20  19   5   0   9|  30M  560k|  16M   35M|   0     0 |  28k   20k
 59  12  20   5   0   5|  23M  544k|  10M   36M|   0     0 |  25k   17k
 53  13  21   8   0   5|  25M   47M|  11M   31M|   0     0 |  23k   16k
 54  14  18   6   0   9|  38M  584k|  14M   35M|   0     0 |  27k   21k
...

帯域は半分強使っていますね。大きい js があるので、 `nginx の gzip_static モジュールを使うなどでもう少し帯域を開けられると思います。

pprof:

(pprof) top30 -cum
6.95s of 22.25s total (31.24%)
Dropped 621 nodes (cum <= 0.11s)
Showing top 30 nodes out of 321 (cum >= 2.44s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     20.30s 91.24%  runtime.goexit
     0.02s  0.09%  0.09%     17.03s 76.54%  net/http.(*conn).serve
         0     0%  0.09%     14.60s 65.62%  net/http.(*ServeMux).ServeHTTP
         0     0%  0.09%     14.60s 65.62%  net/http.serverHandler.ServeHTTP
         0     0%  0.09%     14.58s 65.53%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*mStack).newStack.func1
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*router).route
         0     0%  0.09%     14.57s 65.48%  net/http.HandlerFunc.ServeHTTP
         0     0%  0.09%     10.03s 45.08%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
     0.01s 0.045%  0.13%      6.12s 27.51%  html/template.(*Template).Execute
         0     0%  0.13%      5.58s 25.08%  text/template.(*Template).Execute
     0.12s  0.54%  0.67%      5.57s 25.03%  text/template.(*state).walk
     0.01s 0.045%  0.72%      5.20s 23.37%  text/template.(*state).walkTemplate
     0.04s  0.18%   0.9%      4.68s 21.03%  text/template.(*state).walkRange
     0.01s 0.045%  0.94%      4.65s 20.90%  text/template.(*state).walkRange.func1
     0.97s  4.36%  5.30%      4.60s 20.67%  runtime.mallocgc
         0     0%  5.30%      4.46s 20.04%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.23s  1.03%  6.34%      4.38s 19.69%  runtime.systemstack
     0.04s  0.18%  6.52%      4.07s 18.29%  text/template.(*state).evalPipeline
     0.08s  0.36%  6.88%      4.03s 18.11%  text/template.(*state).evalCommand
     2.54s 11.42% 18.29%      3.71s 16.67%  runtime.scanobject
     0.10s  0.45% 18.74%      3.09s 13.89%  text/template.(*state).evalCall
     0.03s  0.13% 18.88%      3.07s 13.80%  text/template.(*state).evalFunction
         0     0% 18.88%      2.99s 13.44%  main.getAccountName
     2.48s 11.15% 30.02%      2.70s 12.13%  syscall.Syscall
         0     0% 30.02%      2.62s 11.78%  main.getPosts
     0.01s 0.045% 30.07%      2.56s 11.51%  reflect.Value.Call
     0.26s  1.17% 31.24%      2.52s 11.33%  reflect.Value.call
         0     0% 31.24%      2.44s 10.97%  github.com/jmoiron/sqlx.(*DB).Get

テンプレートの実行とが重いのと、あとGCが重いですね。

テンプレートが重いのは、ページキャッシュだとトップページ以外はどれくらいキャッシュヒット率が見込めるかわかりません。 valyala/quicktemplate などの、リフレクションを多用しない高速なテンプレートエンジンに乗り換えるほうが早いかもしれません。

GCの方は、クエリ実行回数をさらに削っていけば、一時オブジェクトがを削減するのが有効そう。どこでアロケートが多発しているのかを確認したい場合は pprof -alloc_objects を使ってみてください。

まとめ

スコア: 4745 (初期状態) -> 39743 (前回) -> 182435 (Not Modified) -> 271542 (最終版)

壁を超えた効果で、いままで伸び悩んでいたスコアが一気にジャンプしました。

攻略記はここまでにしますが、できればさらにチューニングを続けてみてください。練習で実際に手を動かしていないことは、本番ではほぼ確実にできません。 私の場合は、次のようなチューニングで500k点を超えましたが、これでもまだ帯域を使い切っていないし nginx よりも app と MySQL が使用するCPUの方が大きいのでさらに上を狙えるはずです。

  • gzip_static を使う (スコアは上がりませんでしたが、帯域に余裕を作りました)
  • テンプレートが重い posts の部分で valyala/quicktemplate を使ってみる
  • ユーザーをオンメモリキャッシュし、強引なJOINをやめる
  • セッションストアを memcached からオンメモリに切り替える
  • nginx と app の間を unix domain socket に切り替える
  • nginx が重くなってきていたので worker_processes を 2 にする
  • 更新系のリクエストであえて time.Sleep() で待たせて、スコアへの影響が大きいシナリオの処理にリソースを向ける
  • アクセスログを切る (最初は静的ファイルだけ、最後は全部のアクセスログを消す)

ここまでのコミットログは methane/pixiv-private-isucon-2016 に置いてあります。 ですが、できるだけ自力で 500k 点超えを目指してみてください。

最後に、ISUCON の練習にとても良い題材を提供して頂いた pixiv さんに感謝します。


@methane


songofacandy at 18:53
この記事のURLComments(0)TrackBack(0)ISUCON | golang
2016年06月02日

pixiv private isucon 2016 攻略 (4/5)

はてなブックマークに登録

攻略記事一覧:

ここから、いよいよ ISUCON らしくなってきますよ。

現状確認

access.log の集計はこんな感じです。

Request by count
12317 GET /image/*
2797 GET /
1983 POST /login
1218 GET /posts/*
1029 GET /js/jquery-2.2.0.js
1029 GET /favicon.ico
1029 GET /js/jquery.timeago.js
1028 GET /css/style.css
1028 GET /js/jquery.timeago.ja.js
1028 GET /js/main.js
930 GET /@user
655 POST /register
654 GET /admin/banned
579 POST /comment
579 POST /
112 GET /login
83 GET /posts?max_created_at=
56 GET /logout
1 GET /initialize

Request by total time
72.877 0.0260554165177 GET /
34.018 0.0365784946237 GET /@user
18.444 0.22221686747 GET /posts?max_created_at=
15.705 0.0271243523316 POST /
12.566 0.0103169129721 GET /posts/*
8.439 0.000685150604855 GET /image/*
5.644 0.00284619263742 POST /login
1.825 0.00278625954198 POST /register
1.661 0.00286873920553 POST /comment
1.648 0.00251987767584 GET /admin/banned
0.475 0.00424107142857 GET /login
0.45 0.00803571428571 GET /logout
0.026 0.026 GET /initialize

top はこんな感じ

Tasks:  73 total,   1 running,  72 sleeping,   0 stopped,   0 zombie
%Cpu(s): 55.4 us, 10.8 sy,  0.0 ni, 23.5 id,  3.1 wa,  0.0 hi,  6.7 si,  0.5 st
KiB Mem:   1022972 total,   617428 used,   405544 free,    18260 buffers
KiB Swap:        0 total,        0 used,        0 free.   314552 cached Mem
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1122 isucon    20   0  403944  68064   8328 S  76.3  6.7   0:16.87 app.f9aa6c7
  731 mysql     20   0  993756 159744  10756 S  62.6 15.6   0:15.46 mysqld
 1033 www-data  20   0   92024   5136   3056 S   7.0  0.5   0:01.63 nginx
 1069 isucon    20   0   28796   6136   2636 S   2.7  0.6   0:00.80 tmux
  308 memcache  20   0  330528   6060   2228 S   0.7  0.6   0:00.14 memcached

そろそろリクエスト数が増えてきたのと、まだ少し idle が残っているので、念の為ベンチマーク直後の netstat を確認しておきます。

$ netstat -tn
...
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63462         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64494         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63477         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63563         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63877         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64234         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63565         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64008         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63594         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64065         TIME_WAIT  

$ netstat -tn | grep -c TIME_WAIT
1981

まだ詰まるほどじゃないけど一応 /etc/nginx/sites-enabled/isucon.conf で upstream の keepalive を 64 に増やしておきます。

ページキャッシュ

プロファイルを見てみます。

(pprof) top30 -cum
5.66s of 23.80s total (23.78%)
Dropped 584 nodes (cum <= 0.12s)
Showing top 30 nodes out of 326 (cum >= 3.55s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     22.30s 93.70%  runtime.goexit
         0     0%     0%     19.44s 81.68%  net/http.(*conn).serve
     0.01s 0.042% 0.042%     18.79s 78.95%  net/http.serverHandler.ServeHTTP
         0     0% 0.042%     18.78s 78.91%  net/http.(*ServeMux).ServeHTTP
         0     0% 0.042%     18.76s 78.82%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0% 0.042%     18.72s 78.66%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0% 0.042%     18.72s 78.66%  github.com/zenazn/goji/web/middleware.RequestID.func1
         0     0% 0.042%     18.72s 78.66%  net/http.HandlerFunc.ServeHTTP
     0.01s 0.042% 0.084%     18.69s 78.53%  github.com/zenazn/goji/web/middleware.Logger.func1
         0     0% 0.084%     18.27s 76.76%  github.com/zenazn/goji/web/middleware.Recoverer.func1
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web.(*mStack).newStack.func1
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web.(*router).route
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
     0.01s 0.042%  0.13%     14.43s 60.63%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%  0.13%     12.63s 53.07%  main.getIndex
     0.07s  0.29%  0.42%      9.88s 41.51%  main.makePosts
     0.01s 0.042%  0.46%      6.89s 28.95%  github.com/jmoiron/sqlx.(*DB).Get
     0.01s 0.042%   0.5%      6.88s 28.91%  github.com/jmoiron/sqlx.Get
     0.03s  0.13%  0.63%      6.80s 28.57%  database/sql.(*DB).Query
     0.02s 0.084%  0.71%      6.77s 28.45%  database/sql.(*DB).query
     0.03s  0.13%  0.84%      6.43s 27.02%  database/sql.(*DB).queryConn
     0.06s  0.25%  1.09%      6.02s 25.29%  github.com/go-sql-driver/mysql.(*mysqlConn).Query
     0.02s 0.084%  1.18%      4.65s 19.54%  github.com/jmoiron/sqlx.(*DB).QueryRowx
     4.06s 17.06% 18.24%      4.38s 18.40%  syscall.Syscall
     1.17s  4.92% 23.15%      4.08s 17.14%  runtime.mallocgc
         0     0% 23.15%      3.83s 16.09%  github.com/jmoiron/sqlx.(*DB).Select
     0.01s 0.042% 23.19%      3.83s 16.09%  github.com/jmoiron/sqlx.Select
         0     0% 23.19%      3.72s 15.63%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.12s   0.5% 23.70%      3.58s 15.04%  runtime.systemstack
     0.02s 0.084% 23.78%      3.55s 14.92%  syscall.Write

(pprof) list getIndex
Total: 23.80s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
         0     12.63s (flat, cum) 53.07% of Total
         .          .    413:
         .          .    414:   http.Redirect(w, r, "/", http.StatusFound)
         .          .    415:}
         .          .    416:
         .          .    417:func getIndex(w http.ResponseWriter, r *http.Request) {
         .      330ms    418:   me := getSessionUser(r)
         .          .    419:
         .          .    420:   results := []Post{}
         .          .    421:
         .      600ms    422:   err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
         .          .    423:   if err != nil {
         .          .    424:           fmt.Println(err)
         .          .    425:           return
         .          .    426:   }
         .          .    427:
         .      8.43s    428:   posts, merr := makePosts(results, getCSRFToken(r), false)
         .          .    429:   if merr != nil {
         .          .    430:           fmt.Println(merr)
         .          .    431:           return
         .          .    432:   }
         .          .    433:
         .          .    434:   fmap := template.FuncMap{
         .          .    435:           "imageURL": imageURL,
         .          .    436:   }
         .          .    437:
         .       40ms    438:   template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
         .       10ms    439:           getTemplPath("layout.html"),
         .       10ms    440:           getTemplPath("index.html"),
         .          .    441:           getTemplPath("posts.html"),
         .          .    442:           getTemplPath("post.html"),
         .      1.20s    443:   )).Execute(w, struct {
         .          .    444:           Posts     []Post
         .          .    445:           Me        User
         .          .    446:           CSRFToken string
         .          .    447:           Flash     string
         .      2.01s    448:   }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
         .          .    449:}
         .          .    450:
         .          .    451:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
         .          .    452:   user := User{}
         .          .    453:   uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])

テンプレートに渡すための []Post を用意する makePosts 関数が一番重いものの、最初に Post 一覧を取得する select が 600ms, テンプレートのコンパイルと実行を足して 3.2sec ありますね。 テンプレートのコンパイルは起動時に一度やればいい処理なので 1.2sec は無駄です。 また、トップページに表示される内容はユーザーにかかわらず一定なので、レンダリング結果をまるごとページキャッシュできれば、 makePosts の 8.4sec とテンプレートのレンダリングの 2sec の合わせて 10sec をほぼ消し去ることができます。

ページキャッシュが実現できそうかテンプレートの中身を確認してみると、ユーザーごとに異なる内容は、 (1) ヘッダー部分, (2) 全フォームにある csrf token, でした。レンダリングが重いのはポスト一覧の部分でしょうから、ヘッダーはページキャッシュの対象外にして、ポスト一覧部分だけをキャッシュすれば (1) は問題ありません。問題は (2) ですが、レンダリング時に固定のキーワードを入れてレンダリングしておき、ユーザーに返すときに本当の csrf token に文字列置換することにします。

ページキャッシュを作るタイミングですが、 getIndex() が呼ばれた時にするよりも、トップページに何か変更があったとき (画像が投稿された、コメントされた、ユーザーが削除されたなど) にレンダリングするほうが効率的です。 さらに、性能が上がってくるとトップページに変更があるリクエストが並列で来る可能性があるので、レンダリングを Mutex で排他したうえで、 Mutex を待ってる goroutine が同時に複数存在した場合はそのうちの1つだけがレンダリングする方式を採用しました。 この方式は GoCon 2016 Spring で zero time cache パターンとして紹介したもので、全ての POST リクエストがレンダリングを待ってからレスポンスを返すので、キャッシュによる更新が反映されるまでの遅延が存在しません。

diff --git a/app.go b/app.go
index b5a8fac..f246ad6 100644
--- a/app.go
+++ b/app.go
@@ -1,6 +1,7 @@
 package main
 
 import (
+	"bytes"
 	crand "crypto/rand"
 	"crypto/sha512"
 	"encoding/hex"
@@ -109,6 +110,8 @@ func dbInitialize() {
 	for _, sql := range sqls {
 		db.Exec(sql)
 	}
+
+	renderIndexPosts()
 }
 
 func tryLogin(accountName, password string) *User {
@@ -414,38 +410,85 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
 	http.Redirect(w, r, "/", http.StatusFound)
 }
 
-func getIndex(w http.ResponseWriter, r *http.Request) {
-	me := getSessionUser(r)
+var (
+	indexTemplate *template.Template
+	postsTemplate *template.Template
 
-	results := []Post{}
+	indexPostsM         sync.Mutex
+	indexPostsT         time.Time
+	indexPostsRenderedM sync.RWMutex
+	indexPostsRendered  []byte
+)
+
+func init() {
+	fmap := template.FuncMap{
+		"imageURL": imageURL,
+	}
 
+	indexTemplate = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+		getTemplPath("layout.html"),
+		getTemplPath("index.html"),
+	))
+
+	postsTemplate = template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
+		getTemplPath("posts.html"),
+		getTemplPath("post.html"),
+	))
+}
+
+func renderIndexPosts() {
+	now := time.Now()
+	indexPostsM.Lock()
+	defer indexPostsM.Unlock()
+	if indexPostsT.After(now) {
+		return
+	}
+	now = time.Now()
+
+	results := []Post{}
 	err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
 	if err != nil {
-		fmt.Println(err)
+		log.Println(err)
 		return
 	}
 
-	posts, merr := makePosts(results, getCSRFToken(r), false)
+	posts, merr := makePosts(results, "[[[CSRFTOKEN]]]", false)
 	if merr != nil {
-		fmt.Println(merr)
+		log.Println(merr)
 		return
 	}
 
-	fmap := template.FuncMap{
-		"imageURL": imageURL,
+	var b bytes.Buffer
+	if err := postsTemplate.Execute(&b, posts); err != nil {
+		log.Println(err)
+		return
 	}
 
-	template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
-		getTemplPath("layout.html"),
-		getTemplPath("index.html"),
-		getTemplPath("posts.html"),
-		getTemplPath("post.html"),
-	)).Execute(w, struct {
-		Posts     []Post
-		Me        User
-		CSRFToken string
-		Flash     string
-	}{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
+	indexPostsT = now
+	indexPostsRenderedM.Lock()
+	indexPostsRendered = b.Bytes()
+	indexPostsRenderedM.Unlock()
+}
+
+func getIndexPosts(csrf string) template.HTML {
+	indexPostsRenderedM.RLock()
+	t := bytes.Replace(indexPostsRendered, []byte("[[[CSRFTOKEN]]]"), []byte(csrf), -1)
+	indexPostsRenderedM.RUnlock()
+	return template.HTML(string(t))
+}
+
+func getIndex(w http.ResponseWriter, r *http.Request) {
+	me := getSessionUser(r)
+	csrf := getCSRFToken(r)
+	posts := getIndexPosts(csrf)
+
+	indexTemplate.Execute(w,
+		map[string]interface{}{
+			"Me":        me,
+			"CSRFToken": csrf,
+			"Flash":     getFlash(w, r, "notice"),
+			"Posts":     posts},
+	)
 }
 
 func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -708,8 +751,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
 	}
 	tf.Close()
 	copyImage(int(pid), tf.Name(), mime)
+
+	renderIndexPosts()
 	http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
-	return
 }
 
 func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -765,6 +809,7 @@ func postComment(w http.ResponseWriter, r *http.Request) {
 	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
 	db.Exec(query, postID, me.ID, r.FormValue("comment"))
 
+	renderIndexPosts()
 	http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
 }
 
@@ -821,6 +866,7 @@ func postAdminBanned(w http.ResponseWriter, r *http.Request) {
 		db.Exec(query, 1, id)
 	}
 
+	renderIndexPosts()
 	http.Redirect(w, r, "/admin/banned", http.StatusFound)
 }
 
@@ -864,6 +910,15 @@ func main() {
 	db.SetMaxIdleConns(8)
 	defer db.Close()
 
+	for {
+		if db.Ping() == nil {
+			break
+		}
+		log.Println("waiting db...")
+	}
+
+	renderIndexPosts()
+
 	go http.ListenAndServe(":3000", nil)
 
 	goji.Get("/initialize", getInitialize)
diff --git a/templates/index.html b/templates/index.html
index 22ff9c2..8c2b639 100644
--- a/templates/index.html
+++ b/templates/index.html
@@ -19,7 +19,7 @@
   </form>
 </div>
 
-{{ template "posts.html" .Posts }}
+{{ .Posts }}
 
 <div id="isu-post-more">
   <button id="isu-post-more-btn">もっと見る</button>

計測

スコア:

{"pass":true,"score":39743,"success":32254,"fail":0,"messages":[]}

top:

Tasks:  77 total,   1 running,  76 sleeping,   0 stopped,   0 zombie
%Cpu(s): 44.7 us,  8.3 sy,  0.0 ni, 35.3 id,  5.1 wa,  0.0 hi,  6.0 si,  0.5 st
KiB Mem:   1022972 total,   961900 used,    61072 free,    23704 buffers
KiB Swap:        0 total,        0 used,        0 free.   604328 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1337 isucon    20   0  207476  68192   8880 S  63.6  6.7   0:13.73 app.dc4a3eaa
  731 mysql     20   0 1059292 181996  10552 S  45.6 17.8   1:49.68 mysqld
 1033 www-data  20   0   92008   5092   3056 S   8.0  0.5   0:11.70 nginx
 1069 isucon    20   0   32140   9332   2636 S   4.0  0.9   0:07.71 tmux
    3 root      20   0       0      0      0 S   0.3  0.0   0:15.56 ksoftirqd/0
   13 root      20   0       0      0      0 S   0.3  0.0   0:29.07 ksoftirqd/1
   43 root      20   0       0      0      0 S   0.3  0.0   0:00.15 kworker/u30:1
  308 memcache  20   0  332576   7896   2228 S   0.3  0.8   0:00.89 memcached
  968 isucon    20   0   80656   3496   2656 S   0.3  0.3   0:00.28 sshd

CPU がだいぶ遊んできましたね。どこか別のところにあるボトルネックを見つけないといけません。

myprofiler:

  34 SELECT * FROM `users` WHERE `id` = N
  30 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
  23 SELECT * FROM `posts` WHERE `id` = N
  19 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
  11 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
  10 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   8 SELECT `id` FROM `posts` WHERE `user_id` = N
   2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S)
   1 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC
   1 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N)

user を PK で取得する部分が重いみたいです。

access.log:

Request by count
12394 GET /image/*
4149 GET /
2791 POST /login
1395 GET /posts/*
1207 POST /register
1207 GET /admin/banned
1049 GET /@user
1021 GET /js/jquery-2.2.0.js
1021 GET /css/style.css
1021 GET /js/jquery.timeago.ja.js
1021 GET /favicon.ico
1021 GET /js/jquery.timeago.js
1021 GET /js/main.js
704 POST /comment
698 POST /
120 GET /login
77 GET /posts?max_created_at=
61 GET /logout
1 GET /initialize

Request by total time
30.646 0.0292144899905 GET /@user
24.051 0.0344570200573 POST /
14.411 0.187155844156 GET /posts?max_created_at=
12.099 0.00867311827957 GET /posts/*
11.879 0.0168735795455 POST /comment
9.296 0.00224053988913 GET /
6.612 0.00236904335364 POST /login
3.355 0.00277961888981 POST /register
2.882 0.00023253187026 GET /image/*
2.21 0.00183098591549 GET /admin/banned
0.448 0.00373333333333 GET /login
0.443 0.00726229508197 GET /logout
0.038 0.038 GET /initialize

Request by out bytes
3847419944 310426 GET /image/*
264074503 258643 GET /js/jquery-2.2.0.js
99628388 24012 GET /
...

GET / が 2.2msec まで速くなりました。まだ速く出来る余地はあるけど、先に GET /@user などの高速化が先でしょうね。

まとめ

スコア: 4745 (初期状態) -> 32771 (前回) -> 39743 (トップページのページキャッシュ)

ボトルネックがCPU以外に移っているので、スコアが期待したほど伸びませんでした。次回はそのボトルネックを調査・解決します。

ページキャッシュに利用した zero time cache パターンは Go だから簡単に実現できるものなので、 prefork 型のアプリサーバーを使う他の言語ではちょっと難しいです。 (node.js なら、2コアマシンならシングルプロセスで頑張れるかも知れません)

他の言語では、普通に getIndex でページキャッシュしてベンチが完走するようにキャッシュの生存期間を調整するとか、バックグラウンドで動くデーモンが定期的にページキャッシュを生成するようにしてベンチが通るようにその生成間隔を調整するといったやり方がISUCONでは一般的だと思います。

しかし、今回の pixiv private isucon ではルールに POST が返ってからその内容が別の GET リクエストに反映されるまでの猶予が明記されていないので、調整のために複数回ベンチを走らせる必要があるかもしれません。 (Go 推し)


@methane


songofacandy at 17:51
この記事のURLComments(0)TrackBack(0)ISUCON | golang
このブログについて
DSASとは、KLab が構築し運用しているコンテンツサービス用のLinuxベースのインフラです。現在5ヶ所のデータセンタにて構築し、運用していますが、我々はDSASをより使いやすく、より安全に、そしてより省力で運用できることを目指して、日々改良に勤しんでいます。
このブログでは、そんな DSAS で使っている技術の紹介や、実験してみた結果の報告、トラブルに巻き込まれた時の経験談など、広く深く、色々な話題を織りまぜて紹介していきたいと思います。
KLabについて
KLab株式会社は、信頼性の高いクラウドサービス、ソフトウェアパッケージ、自社で企画・開発したソーシャルアプリやデジタルコンテンツを提供しています。
Blog内検索
最新コメント
最新トラックバック
Archives
Syndicate this site