kavo’s diary

備忘録

ISUCON10本選 練習環境構築 ベンチマーカーを動作させる

ISUCON10本選に挑戦してみたくてまずは環境構築したメモ。

とりあえずベンチ実行してスコアが出てアプリが見えるところまでやった。

ISUCON10 本選当日マニュアルは以下。

isucon10-final/manual.md at master · isucon/isucon10-final · GitHub

インスタンス起動、SSH接続

「ISUCONの過去問にチャレンジするためのシンプルな環境構築」を使う(ISUCON9予選) - kavo’s diary と同様にami-0f7362c1bbc7e30ecを使ってインスタンスを立ち上げ、SSH接続。

isuconユーザに切り替え。

$ sudo -i -u isucon

サービス起動

立ち上げた直後は起動していないので、起動する。 参考実装の切り替え方法

sudo systemctl enable --now xsuportal-web-golang.service
sudo systemctl enable --now xsuportal-api-golang.service

仮想ポータルアクセス

どこから仮想ポータルを見られるのかは当日マニュアルとアプリケーションマニュアルをざっと見ただけだと分からなかった。が、xsuportal-api-golang.serviceのログで9292で受けてるっぽいことに気づく。

$ sudo systemctl status xsuportal-api-golang.service
...
 http server started on [::]:9292

curlしてみると弾かれる。ポート開けてなかった。

$ curl localhost:9292

AWSコンソールで9292を開けたらcurlでhtmlが返ってきた。

$ curl localhost:9292
<!doctype html><html lang="ja" class="has-background-grey-lighter"><head><title>XSUCON Portal</title><meta name="viewport" content="width=device-width,initial-scale=1"/><meta name="xsu:api-base-url" content="/"/><link href="/packs/vendor.css" rel="stylesheet"></head><body><div id="app"></div><script src="/packs/vendor.js"></script><script src="/packs/audience.js"></script></body></html>i

ブラウザでhttp://x.x.x.x:9292/ を開くとタイトルだけ出て中身はカラのページが見えた。

f:id:kavohtn:20210617042044p:plain

ベンチマーク実行

ポータルの中身はカラに見えるのは以下の理由のよう。

なお、初期状態ではアプリケーションの動作に必要なデータが不足しているため、アプリケーションをブラウザから動作確認するためには、一度負荷走行を実行してください (後述)。

Running a benchmarker locallyのコマンドを参考に実行してみる。そのままだと下記エラーになる。3000番ポートで待ってなさそうだし、本番と同じ構成になってなさそう。

dial tcp [::1]:3000: connect: connection refused

$ sudo lsof -i:3000
$

試しにtargetのポートをapiが受けてる9292に変更し実行してみる。

$ ./bin/benchmarker     -exit-status     -target app.t.isucon.dev:9292     -host-advertise local.t.isucon.dev     -tls-cert ../secrets/cert.pem     -tls-key ../secrets/key.pem 
16:56:17.000277 ISUCON10 benchmarker e858b2588a199f9c7407baacf48b53126b8aeed6+dirty
16:56:17.001955 ===> PREPARE
16:56:26.754919 Language: go
16:56:26.754936 HTTP: http://app.t.isucon.dev:9292/(tls=false)
16:56:26.754942 gRPC: localhost:50051
16:56:26.755009 ===> LOAD
16:56:26.755049 LOAD INFO
  Registration Open at: 2021-06-16 16:56:27 +0000 UTC
  Contest Start at: 2021-06-16 16:56:37 +0000 UTC
  Contest Freeze at: 2021-06-16 16:57:17 +0000 UTC
  Contest Ends at: 2021-06-16 16:57:27 +0000 UTC
16:57:36.762065 ===> VALIDATION
16:57:47.793989 ERR: validation: critical: http: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context canceled
16:57:47.794491 ERR: validation: timeout: critical: timeout: http: timeout: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context deadline exceeded
16:57:47.794515 ERR: validation: timeout: critical: timeout: http: timeout: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context deadline exceeded
16:57:47.794636 ERR: validation: critical: http: Post "http://app.t.isucon.dev:9292/api/login": context canceled
16:57:47.794724 ERR: validation: critical: http: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context canceled
16:57:47.794820 ERR: validation: critical: http: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context canceled
16:57:47.794877 ERR: validation: critical: http: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context canceled
16:57:47.794933 ERR: validation: critical: http: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context canceled
16:57:47.794989 ERR: validation: critical: http: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context canceled
16:57:47.795089 ERR: validation: critical: http: Get "http://app.t.isucon.dev:9292/api/contestant/dashboard": context canceled
16:57:47.805110 ===> SCORE
Count: 
  admin-answer-clarification: 8
  admin-get-clarification: 8
  admin-get-clarifications: 73
  audience-get-dashboard: 370
  create-team: 10
  enqueue-benchmark: 118
  finish-benchmark: 109
  get-clarification: 8
  get-dashboard: 60
  join-member: 20
  list-notifications: 1491
  post-clarification: 8
  resolve-clarification: 8
(1290 * 1.0) + 37 - 400(err: 0, timeout: 405)
Pass: false / score: 927 (1327 - 400)
Fail reason: Critical error

Pass: falseとあるが、一応スコアは出ている。

ポータルサイトもタイムラインチャートやリーダーボードが見えるようになった。

f:id:kavohtn:20210617035556p:plain

ユーザとしてログインして管理者・競技者のページも見えた。

XSUCON Admin f:id:kavohtn:20210617044914p:plain

XSUCON Contestant f:id:kavohtn:20210617045059p:plain

最低限ベンチ動作とアプリが見えるようになった。

「ISUCONの過去問にチャレンジするためのシンプルな環境構築」を使う(ISUCON9予選)

公式で用意されているお手軽構築を使ったメモ https://isucon.net/archives/54946542.html

今回はISUCON9予選をやってみる。

キーペア作成

f:id:kavohtn:20210615005301p:plain

EC2>インスタンスを起動

f:id:kavohtn:20210615005704p:plain

AMI検索

https://github.com/matsuu/aws-isucon のAMI IDで検索。今回は「ami-03b1b78bb1da5122f」で検索し、コミュニティ AMI (1)を選択。

f:id:kavohtn:20210615005758p:plain

インスタンスタイプ選択

今回はt3.smallにしてみる。 https://aws.amazon.com/jp/ec2/pricing/on-demand/ f:id:kavohtn:20210615005941p:plain

安くしたいのでスポットインスタンスを使う。

f:id:kavohtn:20210615010046p:plain

セキュリティグループ

SSH接続と、アプリをブラウザから見たいので22と80を開けておく。(IP縛った方が安全。)

f:id:kavohtn:20210615010128p:plain

起動>キーペア選択

さっき作ったのを選ぶ。 f:id:kavohtn:20210615010303p:plain

起動後にSSH接続しようとするとConnection timed out。

ネットワーク設定修正

こちらのチェックリストに助けられた。 https://qiita.com/yokoto/items/338bd80262d9eefb152e

インターネットゲートウェイがdetachedになっていたのでVPCにアタッチ。 f:id:kavohtn:20210615010713p:plain

また、ルートテーブルにIPv4のルートがなかったので追加。 f:id:kavohtn:20210615010957p:plain

SSH接続

ローカルPCのgit bashからつないでみる。接続成功。

$ ssh -i "2021-06-14-isucon-renshu.pem" ubuntu@18.x.x.x
Welcome to Ubuntu 18.04.5 LTS (GNU/Linux 5.4.0-1045-aws x86_64)
...

アプリ画面を見る

https://18.x.x.x/ にブラウザでアクセスする。警告が出るが、続行するとアプリ画面が見えた。 f:id:kavohtn:20210615011622p:plain

めっちゃお手軽でありがたみがすごい。

Open-Lowcodeを触ってみようとして途中で諦めた

Open-Lowcodeを触ってみようぜという話が出たので見てみる。 ISUCONで使えるなんらかのアプリとか作れたらいいな。

情報

とりあえずOperation-Guide読んで動かす

ガイドのPrerequisitesの部分

Open Lowcode Operation Guide · openlowcode/Open-Lowcode Wiki · GitHub

ある程度ubuntu上で作業してから気づいたが、手順にbatファイルがあってwindowsの方が良かった。Windows Serverでやり直す。

f:id:kavohtn:20210424171203p:plain

インストール

ガイドのInstallationの部分

「Open Lowcode zip file」って何?

ISUCON練習日記2021-03-13 ISUCON10予選

ISUCON10予選問題で練習した。色々忘れないようにメモ。

DB分割

DBの設定複製

estate/chairを触るSQLごとに振り分け

・DBインスタンス複製

分割前測定

{"pass":true,"score":902,"messages":[],"reason":"OK","language":"go"}

1,2号機CPU

f:id:kavohtn:20210313162221j:plain

## アプリプロファイル
16:20
key                                    count  sum     avg
main.searchChairs                      1729   154460  150.25
main.searchChairs: part2               1729   114261  111.15
main.searchEstateNazotte               102    101176  991.92
main.searchEstateNazotte: part2        102    88169   864.40
main.searchEstates                     2824   87232   84.86
main.searchEstates: part2              2824   60437   58.79
main.getEstateDetail                   4712   43916   42.72
main.getChairDetail                    3848   42513   41.36
main.searchChairs: part3               1729   38794   37.74
main.searchEstates: part3              2824   24082   23.43
main.searchEstateNazotte: part1        102    12918   126.65
main.getLowPricedEstate                744    11152   14.99
main.searchRecommendedEstateWithChair  459    11142   24.27
main.getLowPricedChair                 744    10286   13.83
16:20
## nginxログ
16:20
+-------+-----+-------+-----+-----+-----+--------+------------------------------+---------+-------+-------+-------+-----------+-----------+
| COUNT | 1XX |  2XX  | 3XX | 4XX | 5XX | METHOD |             URI              |   SUM   |  AVG  |  MIN  |  MAX  | MIN(BODY) | MAX(BODY) |
+-------+-----+-------+-----+-----+-----+--------+------------------------------+---------+-------+-------+-------+-----------+-----------+
|  1729 |   0 |  1714 |   0 |  15 |   0 | GET    | /api/chair/search            | 224.296 | 0.130 | 0.005 | 1.132 |     0.000 | 17925.000 |
|  2824 |   0 |  2811 |   0 |  13 |   0 | GET    | /api/estate/search           | 203.415 | 0.072 | 0.004 | 1.062 |     0.000 | 27095.000 |
|  4712 |   0 |  4667 |   0 |  45 |   0 | GET    | /api/estate/\d+              | 171.501 | 0.036 | 0.004 | 0.984 |     0.000 |   705.000 |
|  3848 |   0 |  3823 |   0 |  25 |   0 | GET    | /api/chair/\d+               | 154.742 | 0.040 | 0.004 | 1.080 |     0.000 |   647.000 |
|   102 |   0 |    99 |   0 |   3 |   0 | POST   | /api/estate/nazotte          | 100.232 | 0.983 | 0.676 | 1.464 |     0.000 | 33942.000 |
|   744 |   0 |   744 |   0 |   0 |   0 | GET    | /api/estate/low_priced       |  12.096 | 0.016 | 0.004 | 0.340 | 13383.000 | 13426.000 |
|   459 |   0 |   459 |   0 |   0 |   0 | GET    | /api/recommended_estate/\d+  |  11.752 | 0.026 | 0.004 | 0.404 | 13081.000 | 13712.000 |
|   744 |   0 |   743 |   0 |   1 |   0 | GET    | /api/chair/low_priced        |  10.976 | 0.015 | 0.004 | 0.684 |     0.000 | 12186.000 |
|   674 |   0 |   674 |   0 |   0 |   0 | POST   | /api/estate/req_doc/\d+      |   5.288 | 0.008 | 0.004 | 0.148 |     0.000 |     0.000 |
|   228 |   0 |   228 |   0 |   0 |   0 | POST   | /api/chair/buy/\d+           |   4.048 | 0.018 | 0.004 | 0.168 |     0.000 |     0.000 |
|     1 |   0 |     1 |   0 |   0 |   0 | POST   | /initialize                  |   4.044 | 4.044 | 4.044 | 4.044 |    23.000 |    23.000 |
|     3 |   0 |     3 |   0 |   0 |   0 | POST   | /api/estate                  |   3.404 | 1.135 | 0.528 | 1.516 |     0.000 |     0.000 |
|     4 |   0 |     3 |   0 |   1 |   0 | POST   | /api/chair                   |   3.403 | 0.851 | 0.187 | 1.380 |     0.000 |     0.000 |
|   414 |   0 |   414 |   0 |   0 |   0 | GET    | /api/estate/search/condition |   0.444 | 0.001 | 0.000 | 0.008 |  2563.000 |  2563.000 |
...
+-------+-----+-------+-----+-----+-----+--------+------------------------------+---------+-------+-------+-------+-----------+-----------+
| 16720 |   0 | 16617 |   0 | 103 |   0 |                                                                                                  
+-------+-----+-------+-----+-----+-----+--------+------------------------------+---------+-------+-------+-------+-----------+-----------+


# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0xB718722664D79180DE3386CFE9C21BF6   84.6158 23.1%   102 0.8296  0.02 SELECT estate
#    2 0x4E8EAE12D58B73C2F3EFAD4903F0402F   27.5122  7.5%   281 0.0979  0.01 SELECT chair
#    3 0x929E86BFE887C4E10B23D92EDD8D61BC   11.7012  3.2%   204 0.0574  0.01 SELECT estate
#    4 0xE010F89F59F07FE84177E58CAC7321CE   10.8306  3.0%   102 0.1062  0.01 SELECT estate
#    5 0xED731470FE91D25E31E27AD9C15C891F   10.3488  2.8%   191 0.0542  0.01 SELECT estate
#    6 0x85EDDA9F02FE0A0E65DBB57A0B593F83    7.3063  2.0%   133 0.0549  0.01 SELECT chair
#    7 0x3636444F1E726DFB63C508D1F648A860    6.6427  1.8%    80 0.0830  0.00 SELECT estate
# MISC 0xMISC                              207.6529 56.6%  6234 0.0333   0.0 <279 ITEMS>


分割後測定

{"pass":true,"score":1261,"messages":[],"reason":"OK","language":"go"}

1.5倍くらいになった。DB分割の効果がでている。

1,2,3号機CPU(右端の山)

f:id:kavohtn:20210313163523j:plain

## アプリプロファイル
16:30
key                                    count  sum     avg
main.searchEstateNazotte               210    162128  772.04
main.searchEstateNazotte: part2        210    138214  658.16
main.searchChairs                      2784   125966  122.53
main.searchEstates                     3374   117236  114.04
main.searchChairs: part2               2784   79401   77.24
main.searchEstates: part2              3374   74178   72.16
main.getEstateDetail                   8151   51884   50.47
main.searchChairs: part3               2784   50158   48.79
main.searchEstates: part3              3374   35627   34.66
main.getChairDetail                    7103   35234   34.27
main.searchEstateNazotte: part1        210    23718   112.94
main.getLowPricedEstate                1022   20305   19.87
main.searchRecommendedEstateWithChair  710    19414   27.34
main.postEstateRequestDocument         910    13805   15.17
16:30
## nginxログ
16:30
+-------+-----+-------+-----+-----+-----+--------+------------------------------+---------+-------+-------+-------+-----------+-----------+
| COUNT | 1XX |  2XX  | 3XX | 4XX | 5XX | METHOD |             URI              |   SUM   |  AVG  |  MIN  |  MAX  | MIN(BODY) | MAX(BODY) |
+-------+-----+-------+-----+-----+-----+--------+------------------------------+---------+-------+-------+-------+-----------+-----------+
|  8158 |   0 |  8112 |   0 |  46 |   0 | GET    | /api/estate/\d+              | 385.097 | 0.047 | 0.016 | 1.168 |   538.000 |   713.000 |
|  3374 |   0 |  3366 |   0 |   8 |   0 | GET    | /api/estate/search           | 307.486 | 0.091 | 0.004 | 0.940 |     0.000 | 20715.000 |
|  2784 |   0 |  2772 |   0 |  12 |   0 | GET    | /api/chair/search            | 287.663 | 0.103 | 0.012 | 1.084 |     0.000 | 20851.000 |
|  7103 |   0 |  7075 |   0 |  28 |   0 | GET    | /api/chair/\d+               | 237.831 | 0.033 | 0.004 | 0.820 |     0.000 |   659.000 |
|   210 |   0 |   206 |   0 |   4 |   0 | POST   | /api/estate/nazotte          | 161.540 | 0.769 | 0.062 | 1.560 |     0.000 | 34291.000 |
|  1022 |   0 |  1022 |   0 |   0 |   0 | GET    | /api/estate/low_priced       |  22.344 | 0.022 | 0.008 | 0.564 | 13323.000 | 13427.000 |
|   710 |   0 |   707 |   0 |   3 |   0 | GET    | /api/recommended_estate/\d+  |  20.386 | 0.029 | 0.004 | 0.684 |     0.000 | 13727.000 |
|   910 |   0 |   910 |   0 |   0 |   0 | POST   | /api/estate/req_doc/\d+      |  14.880 | 0.016 | 0.004 | 0.908 |     0.000 |     0.000 |
|  1022 |   0 |  1022 |   0 |   0 |   0 | GET    | /api/chair/low_priced        |  14.548 | 0.014 | 0.004 | 0.264 | 12139.000 | 12186.000 |
|     7 |   0 |     7 |   0 |   0 |   0 | POST   | /api/estate                  |  11.976 | 1.711 | 0.464 | 2.352 |     0.000 |     0.000 |
|     7 |   0 |     7 |   0 |   0 |   0 | POST   | /api/chair                   |  11.736 | 1.677 | 0.484 | 2.768 |     0.000 |     0.000 |
|     1 |   0 |     1 |   0 |   0 |   0 | POST   | /initialize                  |   7.304 | 7.304 | 7.304 | 7.304 |    23.000 |    23.000 |
|   351 |   0 |   351 |   0 |   0 |   0 | POST   | /api/chair/buy/\d+           |   5.736 | 0.016 | 0.004 | 0.120 |     0.000 |     0.000 |
|   458 |   0 |   458 |   0 |   0 |   0 | GET    | /api/estate/search/condition |   0.620 | 0.001 | 0.004 | 0.020 |  2563.000 |  2563.000 |
...
+-------+-----+-------+-----+-----+-----+--------+------------------------------+---------+-------+-------+-------+-----------+-----------+
| 26478 |   0 | 26377 |   0 | 101 |   0 |                                                                                                  
+-------+-----+-------+-----+-----+-----+--------+------------------------------+---------+-------+-------+-------+-----------+-----------+


# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x4E8EAE12D58B73C2F3EFAD4903F0402F   11.5774  5.1%   328 0.0353  0.02 SELECT chair
#    2 0x4FA7F17A15BCD31A08C4C2F052598EB7    5.8728  2.6%    74 0.0794  0.02 SELECT chair
#    3 0x929787B1FE641900E3DD23571CAC3AB6    5.5240  2.4%    72 0.0767  0.02 SELECT chair
#    4 0x17813360728C84E63F19DC57445EC358    4.3238  1.9%    29 0.1491  0.10 SELECT chair
#    5 0x9CCCD1D3E32D61BB18B4ECD908E723B4    4.1910  1.8%    59 0.0710  0.02 SELECT chair
#    6 0xF6CBE5E7B4D4ECE4095626C611F2D411    3.8432  1.7%    47 0.0818  0.01 SELECT chair
#    7 0x7A3943FC5D195AC5C0824B77FDBE8C4F    2.9514  1.3%    24 0.1230  0.01 SELECT chair
# MISC 0xMISC                              190.5975 83.3%  4891 0.0390   0.0 <567 ITEMS>


# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0xB718722664D79180DE3386CFE9C21BF6  135.2677 41.9%   207 0.6535  0.06 SELECT estate
#    2 0xE010F89F59F07FE84177E58CAC7321CE   17.7821  5.5%   207 0.0859  0.01 SELECT estate
#    3 0x3636444F1E726DFB63C508D1F648A860    9.3767  2.9%   129 0.0727  0.01 SELECT estate
#    4 0x3A6102F5BB1888CE18692940986AC2AD    8.2232  2.5%   111 0.0741  0.00 SELECT estate
#    5 0xAA809559207975DC00087902517AC50D    6.6264  2.1%    97 0.0683  0.01 SELECT estate
#    6 0x9874FCB909778990D4BDA82D2EB9C996    6.5708  2.0%    90 0.0730  0.00 SELECT estate
#    7 0x63EDCA18912C7FEE67A0CB124E70256F    5.7084  1.8%    74 0.0771  0.01 SELECT estate
# MISC 0xMISC                              133.2300 41.3%  4788 0.0278   0.0 <135 ITEMS>

ISUCON練習日記2021-03-07 ISUCON10予選

ISUCON10予選問題で練習した。色々忘れないようにメモ。

IP取得

wget -q -O - http://checkip.amazonaws.com/

ファイルサイズ

sudo ls -lh /var/log/mysql/mysql-slow.log |awk '{print $5}'

nazotteのN+1をなんとかしようとする

方針は複数ある

  • POINT 型
  • アプリ側で内外判定する

geo系sqlを簡易テスト

結局syntax errorを越えられずできなかった。

$     sudo mysql isuumo -e "SELECT ST_Contains(ST_PolygonFromText('POLYGON((1 1,1 2,2 2,2 1,3 3))'), ST_GeomFromText('POINT(1 1
)'))"
ERROR 3037 (22023) at line 1: Invalid GIS data provided to function st_geometryfromtext.

MySQL Bugs: #76595: "Invalid GIS data provided" reported with valid geometries 記法ミスなのかバグなのかバージョン差異なのか不明

アプリログ出す

【systemd】StandardOutput=fileはログをファイルに出力できるけど追記されない | 純規の暇人趣味ブログ

 journalctl -u isuumo.go.service 
でチラ見はできる、でも長いので実用性低い

sudo vi /etc/systemd/system/isuumo.go.service 

[Service]
StandardOutput=append:/tmp/test.log

sudo systemctl daemon-reload
sre

$ sudo journalctl --version
systemd 237
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid

240未満だったので意味なかった。

sudo vi /etc/systemd/system/isuumo.go.service 

$ sudo systemctl daemon-reload && sre && sst
● isuumo.go.service - isuumo.go
   Loaded: loaded (/etc/systemd/system/isuumo.go.service; enabled; vendor preset: enabled)
   Active: activating (auto-restart) (Result: exit-code) since Sat 2021-03-06 15:16:46 UTC; 29ms ago
  Process: 11467 ExecStart=/bin/sh -c exec /home/isucon/isuumo/webapp/go/isuumo >> /var/log/isuapp.log (code=exited, status=2)
 Main PID: 11467 (code=exited, status=2)

Mar 06 15:16:46 ix systemd[1]: isuumo.go.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Mar 06 15:16:46 ix systemd[1]: isuumo.go.service: Failed with result 'exit-code'.


 sudo touch  /var/log/isuapp.log

sudo chmod 666  /var/log/isuapp.log
sudo ls -l  /var/log/isuapp.log
-rw-rw-rw- 1 root root 0 Mar  6 15:17 /var/log/isuapp.log

$ sudo systemctl daemon-reload && sre && sst
● isuumo.go.service - isuumo.go
   Loaded: loaded (/etc/systemd/system/isuumo.go.service; enabled; vendor preset: enabled)
   Active: active (running) since Sat 2021-03-06 15:17:25 UTC; 54ms ago
 Main PID: 11724 (isuumo)
    Tasks: 4 (limit: 2333)
   CGroup: /system.slice/isuumo.go.service
           └─11724 /home/isucon/isuumo/webapp/go/isuumo

Mar 06 15:17:25 ix systemd[1]: Started isuumo.go.

ログファイルが存在しないときもINVALIDARGUMENTになる。ちょっとわかりにくい。

tail -f /var/log/isuapp.log

nazotte N+1 part0 ソースコード構造変化

読み解き(L1049くらいのestatesInPolygon := []Estate{}から15行くらい)

内容を整理するとこんな感じ

  • IN: coordinates
  • 長方形に絞ったestate群を得る
  • for: estate(長方形に絞ったestate群)
    • select: lat/lonとidを条件に内外判定し、内なら1件得る
    • 結果があるならappend
  • 数を制限する
  • OUT: Estates

このSQLをforの外に出すことを考える

SQL文の代入箇所を変数名で埋めるとこうなる

SELECT * FROM estate 
WHERE id = estate.ID 
AND
 ST_Contains(
   ST_PolygonFromText(
     coordinates.coordinatesToText()
  ),
  ST_GeomFromText(
    'POINT(estate.Latitude estate.Longitude)'
  )
)

条件部に代入値ではなくテーブルが持つ列を渡してしまえば一気に結果を得られる。

SELECT * FROM estate
AND
 ST_Contains(
   ST_PolygonFromText(
     'POLYGON((10.0 10.0,100.0 10.0,100.0 100.0,10.0 100.0))'
  ),
  ST_GeomFromText(
    'POINT(latitude longitude)'
  )
)

このSQLが正しいか、どう試すのがもっとも早いか?

文法レベルはオンラインのシンタックスチェッカーが早いかも。

MySQLの構文チェック

$ sudo mysql isuumo -e "
> SELECT * FROM estate
> WHERE
>  ST_Contains(
>    ST_PolygonFromText(
>      'POLYGON((10.0 10.0,100.0 10.0,100.0 100.0,10.0 100.0))'
>   ),
>   ST_GeomFromText(
>     'POINT(latitude longitude)'
>   )
> ) limit 1
> "
ERROR 3037 (22023) at line 2: Invalid GIS data provided to function st_geometryfromtext.

st_geometryfromtext噛んでるから列名が読めるわけないか。 CONCAT('POINT(', latitude, ' ', longitude, ')'))とかにする必要がある。まあでもpoint型作るか・・・

POINT型を作る(次項)

nazotte N+1 part1 point型列の追加

 vi 0_Schema.sql 
point POINT AS (POINT(latitude, longitude)) STORED NOT NULL,

 ./init.sh 

$     sudo mysql isuumo -e "describe estate"
+-----------------+---------------+------+-----+---------+-------------------+
| Field           | Type          | Null | Key | Default | Extra             |
+-----------------+---------------+------+-----+---------+-------------------+
| id              | int(11)       | NO   | PRI | NULL    |                   |
| name            | varchar(64)   | NO   |     | NULL    |                   |
| description     | varchar(4096) | NO   |     | NULL    |                   |
| thumbnail       | varchar(128)  | NO   |     | NULL    |                   |
| address         | varchar(128)  | NO   |     | NULL    |                   |
| latitude        | double        | NO   |     | NULL    |                   |
| longitude       | double        | NO   |     | NULL    |                   |
| rent            | int(11)       | NO   | MUL | NULL    |                   |
| door_height     | int(11)       | NO   |     | NULL    |                   |
| door_width      | int(11)       | NO   |     | NULL    |                   |
| features        | varchar(64)   | NO   |     | NULL    |                   |
| popularity      | int(11)       | NO   |     | NULL    |                   |
| popularity_desc | int(11)       | NO   | MUL | NULL    | VIRTUAL GENERATED |
+-----------------+---------------+------+-----+---------+-------------------+

エラーは出てないけど型にも追加されてない。

反映先DBが別サーバだったからだった。

$ sudo mysql isuumo -e "describe estate"

| point           | point         | NO   |     | NULL    | VIRTUAL GENERATED |


$  sudo mysql isuumo -e "SELECT latitude, longitude,point, ST_X(point), ST_Y(POINT) from estate limit 1" 
+-------------------+-------------------+---------------------------+-------------------+-------------------+
| latitude          | longitude         | point                     | ST_X(point)       | ST_Y(POINT)       |
+-------------------+-------------------+---------------------------+-------------------+-------------------+
| 37.71778813321466 | 140.2540394463388 |        F{B@i=U!a@      | 37.71778813321466 | 140.2540394463388 |
+-------------------+-------------------+---------------------------+-------------------+-------------------+


STOREDの意味は以下。 SPATIAL INDEX の有効化のため。

> Generated Columnには、「VIRTUAL」 or 「STORED」が指定できます。
> 「VIRTUAL」は実データを持たず、読み込むタイミングで計算します。
> 「STORED」は計算結果を記憶領域に保存し、通常の列情報のように読み取ります。
> 既定値は「VIRTUAL」です。

[https://www.dcom-web.co.jp/lab/database/mysql/generated_column:title]


nazotte N+1 part2 SQL変形

1.SQL変形
query2 := fmt.Sprintf(`/*[N1] */SELECT * FROM estate WHERE ST_Contains(ST_PolygonFromText(%s), point)`, coordinates.coordinatesToText())

2.受け皿用意
estates2 := []Estate{}

3.SQL実行(getで複数取れる)
err = db.Get(&estates2, query2)

4.ログ出してみる
c.Echo().Logger.Debugf(" N1 length:%d", len(estates2))


$ go build && sre && curl localhost/api/stats
key,count,sum,avg

この時点でビルドは成功、アプリ起動成功はしてる。ただなぞってをやってみるとエラー出ている

$ tail -f /var/log/isuapp.log | ./colorizer.sed 

{"time":"2021-03-07T01:45:22.06709935Z","level":"ERROR","prefix":"echo","file":"main.go","line":"1005","message":"Database execution error : missing destination name point in *[]main.Estate"}
{"time":"2021-03-07T01:45:22.070117889Z","id":"","remote_ip":"127.0.0.1","host":"localhost:1323","method":"GET","uri":"/api/recommended_estate/10831","user_agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.190 Safari/537.36","status":500,"error":"","latency":7294970,"latency_human":"7.29497ms","bytes_in":0,"bytes_out":0}

missing destination name point
つまりpointの詰め先がない、Estateに追加し忘れていた

{"time":"2021-03-13T04:16:28.149906619Z","level":"ERROR","prefix":"echo","file":"main.go","line":"736","message":"Database Execution error : sql: Scan error on column index 12, name \"point\": converting driver.Value type []uint8 
(\"\\x00\\x00\\x00\\x00\\x01\\x01\\x00\\x00\\x00\\x8a\\x1a\\xc49\\xe1/B@\\xc4\\xee\\xf6\\x15s_a@\") to a int64: invalid syntax"}

intだと怒られた



    // err = db.Get(&estates2, query2)
    err = db.Select(&estates2, query2)
複数なのでselectにする必要がある

{"pass":false,"score":0,"messages":[{"text":"POST /api/estate/nazotte: レスポンスが不正です","count":4}],"reason":"スコアが0点を下回りました","language":"go"}

ようやくN+1を解消できた スコアはむしろちょっと下がってしまったが、 main.searchEstateNazotteがavgが半分くらいになってcountが1.5倍くらいになった。

{"pass":true,"score":878,"messages":[{"text":"POST /api/estate/nazotte: リクエストに失敗しました (タイムアウトしました)","count":21}],"reason":"OK","language":"go"}

key                                    count  sum     avg
main.searchEstateNazotte               64     151911  2373.61
main.searchEstateNazotte: part2        64     143798  2246.84
main.searchChairs                      1755   130583  127.03
main.searchChairs: part2               1755   101552  98.79
main.searchEstates                     2757   80959   78.75
main.searchEstates: part2              2757   57661   56.09
main.searchChairs: part3               1755   31096   30.25
main.getEstateDetail                   4619   30148   29.33
main.getChairDetail                    3813   29353   28.55
main.searchEstates: part3              2757   21818   21.22
main.searchRecommendedEstateWithChair  475    11247   23.68
main.getLowPricedChair                 703    8763    12.47
main.searchEstateNazotte: part1        64     8065    126.02
main.getLowPricedEstate                703    7742    11.01

{"pass":true,"score":862,"messages":[],"reason":"OK","language":"go"}

key                                    count  sum     avg
main.searchChairs                      1618   145225  141.27
main.searchChairs: part2               1618   112470  109.41
main.searchEstateNazotte               92     90917   988.23
main.searchEstates                     2706   81321   79.11
main.searchEstateNazotte: part2        92     79046   859.19
main.searchEstates: part2              2706   60499   58.85
main.getChairDetail                    3515   37648   36.62
main.getEstateDetail                   4358   33131   32.23
main.searchChairs: part3               1618   32321   31.44
main.searchEstates: part3              2706   23101   22.47
main.searchEstateNazotte: part1        92     11795   128.21
main.searchRecommendedEstateWithChair  437    11189   25.60
main.getLowPricedChair                 706    9845    13.95
main.getLowPricedEstate                706    9203    13.04

ログを見やすくする

tail

https://github.com/shimodatkh/colorizer/blob/master/colorizer.sed

cd
wget https://raw.githubusercontent.com/shimodatkh/colorizer/master/colorizer.sed
chmod 777 colorizer.sed
tail -f /var/log/isuapp.log | ~/colorizer.sed 

less

sudo apt-get install source-highlight
export LESS='-R'
 export LESSOPEN='| /usr/share/source-highlight/src-hilite-lesspipe.sh %s'
less  /var/log/isuapp.log 

ISUCON練習日記2021-02-26 ISUCON10予選

ISUCON10予選問題で練習した。色々忘れないようにメモ。

generated columns追加

とりあえず入れてみる popularity_desc INTEGER AS (-popularity) NOT NULL,

2021/02/22 19:35:29 bench.go:102: verify failed
{"pass":false,"score":0,"messages":[{"text":"GET /api/estate/:id: レスポンスが不正です","count":5},{"text":"GET /api/estate/low_priced: レスポンスが不正です","count":1},{"text":"GET /api/estate/search: レスポンスが不正です","count":5},{"text":"GET /api/recommended_estate/:id: レスポンスが不正です","count":5},{"text":"POST /api/estate/nazotte: レスポンスが不正です","count":5},{"text":"登録済み物件の詳細取得に失敗しました","count":1}],"reason":"スコアが0点を下回りました","language":"go"}

単に入れただけだとダメ。アプリログにエラー出てる。

[19:52:02 isucon@ix ~]$ sudo systemctl status isuumo.go.service
● isuumo.go.service - isuumo.go
   Loaded: loaded (/etc/systemd/system/isuumo.go.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2021-02-22 19:35:22 UTC; 16min ago
  Process: 25939 ExecStop=/bin/kill -s QUIT $MAINPID (code=exited, status=0/SUCCESS)
 Main PID: 25940 (isuumo)
    Tasks: 5 (limit: 2333)
   CGroup: /system.slice/isuumo.go.service
           └─25940 /home/isucon/isuumo/webapp/go/isuumo

Feb 22 19:35:29 ix isuumo[25940]: {"time":"2021-02-22T19:35:29.141867316Z","level":"ERROR","prefix":"echo","file":"main.go","line":"733","message":"Database Execution error : missing destination name popularity_desc in *main.Estate"}

733行目見ると代入失敗っぽい。struct定義にPopularityDesc int64 db:"popularity_desc" json:"-"``を追加する。

   var estate Estate
    err = db.Get(&estate, "SELECT * FROM estate WHERE id = ?", id)
    if err != nil {
        if err == sql.ErrNoRows {
            c.Echo().Logger.Infof("getEstateDetail estate id %v not found", id)
            return c.NoContent(http.StatusNotFound)
        }
        c.Echo().Logger.Errorf("Database Execution error : %v", err)
        return c.NoContent(http.StatusInternalServerError)
    }

SQLコメント

GoでSQLにトレーシングコメントを埋め込んで実行する | おそらくはそれさえも平凡な日々

これやってみたいなと思ったけど、sqlx使ってるコードに大してあまり書き換えずにやる方法あるのかな?分からなかった。記事はdatabase/sql、ISUCON10予選問題はgithub.com/jmoiron/sqlx。

generated columns使って5.7でも有効なインデックスを作成

インデックス追加

,INDEX popularity_desc_id(popularity_desc,id)

追加前後のexplain f:id:kavohtn:20210225010359j:plain

これをやったあとは"score":607くらいになって、スロークエリの上位は椅子と不動産に条件色々くっつけるやつと位置情報の3種になっている。

]$ cat ~/slowq-state.log |sort
/*[11] L1031 */SELECT * FROM estate WHERE latitude <= 36.53227509710664 AND latitude >= 35.58900608516611 AND longitude <= 137.92007832283616 AND longitude >= 137.34442150965003 ORDER BY popularity_desc ASC, id ASC\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE color = 'ピンク' AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE depth >= 80 AND depth < 110 AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE height < 80 AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE height >= 110 AND height < 150 AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE height >= 150 AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE kind = 'エルゴノミクス' AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE price < 3000 AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE price >= 15000 AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE price >= 9000 AND price < 12000 AND stock > 0\G
/*[3] L586 */SELECT COUNT(*) FROM chair WHERE width >= 110 AND width < 150 AND stock > 0\G
/*[7] L909 */SELECT COUNT(*) FROM estate WHERE door_height < 80\G
/*[7] L909 */SELECT COUNT(*) FROM estate WHERE door_height >= 150\G
/*[7] L909 */SELECT COUNT(*) FROM estate WHERE door_height >= 80 AND door_height < 110\G
/*[7] L909 */SELECT COUNT(*) FROM estate WHERE door_width < 80\G
/*[7] L909 */SELECT COUNT(*) FROM estate WHERE door_width >= 110 AND door_width < 150\G
/*[7] L909 */SELECT COUNT(*) FROM estate WHERE door_width >= 150\G
/*[7] L909 */SELECT COUNT(*) FROM estate WHERE rent >= 150000\G
/*[7] L909 */SELECT COUNT(*) FROM estate WHERE rent >= 50000 AND rent < 100000\G

hub createコマンドが動かなくなった件

現在パスワード認証だとダメらしい。 Unable to authorize with my GitHub password (Unathorized/Not Found) · Issue #2655 · github/hub · GitHub

ISUCON練習日記2021-02-22 ISUCON10予選

ISUCON10予選問題で練習した。色々忘れないようにメモ。

流れ

  • アプリ立てる
  • ベンチ流す
  • ベンチスクリプトで各データが自動で取れるようにしていく
    • nginx
    • app measure
    • slow query
    • netdata

他に自動化したい部分

  • app log
  • index
  • explain

インスタンス複製

  • スナップショット取得
  • 同様のインスタンスを作成
  • オプション:静的IP付与

これも自動化したい。

最新のGoインストール

最新版のGo言語をLinuxにインストールする手順をやった上で、パスが変わってなかったので以下をやる。

sudo rm /usr/bin/go 
export PATH=$PATH:/usr/local/go/bin
go version

でもsnapを使うほうが楽かも

sudo snap install --channel=1.16/stable --classic go
snap info go

slack通知でファイルを飛ばす

Slackのfiles.upload APIを使ってファイルを簡単に連携する - バナーナナブログ

Slack API | Slack

OAuth & PermissionsでBot Token Scopesにfile:write権限を追加したけどうまく行かず、User Token Scopesの方に追加したらいけた。

curl -F file=@/home/isucon/pt.log -F channels=#notify_stats_result \
 -H "Authorization: Bearer xoxp-hogehoge" https://slack.com/api/files.upload

MySQLWorkbenchで表示してみる

isucon10参加記 | カオスの坩堝

・クライアント上にツールインストール

・サーバ上で次のコマンド実行

sudo grep bind /etc/mysql/ -rni

sudo vi /etc/mysql/mysql.conf.d/mysqld.cnf
 bind_addressをコメントアウト

sudo mysql -e "grant all privileges on isuumo.* to isucon@'%' identified by 'isucon' with grant option;"

sudo systemctl restart mysql.service

インデックス追加

スロークエリで出てくる SELECT * FROM chair WHERE stock > 0 ORDER BY price ASC, id ASC LIMIT 20 用に INDEX stock_price_id (stock, price, id)を貼った場合、さらにINDEX price_id (price, id)を貼った場合の実行計画。

mysql> mysql> explain SELECT * FROM chair WHERE stock > 0 ORDER BY price ASC, id ASC LIMIT 20;
+----+-------------+-------+------------+------+----------------+------+---------+------+-------+----------+-----------------------------+
| id | select_type | table | partitions | type | possible_keys  | key  | key_len | ref  | rows  | filtered | Extra                       |
+----+-------------+-------+------------+------+----------------+------+---------+------+-------+----------+-----------------------------+
|  1 | SIMPLE      | chair | NULL       | ALL  | stock_price_id | NULL | NULL    | NULL | 29281 |    50.00 | Using where; Using filesort |
+----+-------------+-------+------------+------+----------------+------+---------+------+-------+----------+-----------------------------+

$ sudo mysql -e "use isuumo; explain SELECT * FROM chair WHERE stock > 0 ORDER BY price ASC, id ASC LIMIT 20;"
+----+-------------+-------+------------+-------+----------------+----------+---------+------+------+----------+-------------+
| id | select_type | table | partitions | type  | possible_keys  | key      | key_len | ref  | rows | filtered | Extra       |
+----+-------------+-------+------------+-------+----------------+----------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | chair | NULL       | index | stock_price_id | price_id | 8       | NULL |   40 |    50.00 | Using where |
+----+-------------+-------+------------+-------+----------------+----------+---------+------+------+----------+-------------+

Using filesortはクイックソートのことらしい。 漢(オトコ)のコンピュータ道: Using filesort