作業ログ

[fujisawaryohei]

環境設定と計測・改善ログ （諸事情により、チューニングサーバーとベンチサーバーは同じサーバー）

参考記事: https://isucon.net/archives/56082639.html 環境構築: https://fusic.slack.com/archives/C9C9UR5QC/p1653775452478759

[fujisawaryohei]

ubuntu ユーザーでログインする。

ssh -i 秘密鍵のパス ubuntu@ip address

isucon ユーザーで直接SSHできるように、ubuntu 配下の /.ssh/authorized_keys を isucon 配下の /.ssh へコピーし、コピーした authorized_keys や .ssh に対して、所有者を isucon として設定する。

# ubuntuユーザーのルートにあるauthorized_keysをisuconルート配下の./ssh配下へ設置
$ sudo cp .ssh/authorized_keys /home/isucon/.ssh/

# isuconユーザーの .ssh に読み書き実行権限, authorized_keys に読み書き権限付与
$ sudo chmod 700 /home/isucon/.ssh
$ sudo chmod 600 /home/isucon/.ssh/authorized_keys

# ↑の.ssh 配下と authorized_key の所有権をisuconユーザーに設定
$ sudo chown isucon:isucon /home/isucon/.ssh/
$ sudo chown isucon:isucon /home/isucon/.ssh/authorized_keys

以降はisuconユーザーとして作業する。

[fujisawaryohei]

Github用の秘密鍵を競技用サーバーへコピー。

git config して、競技用サーバーに存在するソースコード一式をpushする。 （ついでに git のデフォルトエディタを vim にしておく）

$ git config --global user.email 'xxxx@example.com'
$ git config --global user.name 'fujisawaryohei'
$ git config --global core.editor vim
$ git commit -m '~'
$ git remote add origin git@github.com:fujisawaryohei/isucon11-qualify-go.git
$ git branch -M main
$ git push -u origin main

[fujisawaryohei]

競技用サーバーのコードはVSCode Remote SSH エージェントを用いて編集する。 参考URL: https://qiita.com/nlog2n2/items/1d1358f6913249f3e186

1. ローカルの ~/.ssh/config に下記を追加する。

   Host isucon-server
   HostName 競技用サーバーのIP
   IdentityFile ~/.ssh/isucon/isucon.pem
   User isucon
   IdentitiesOnly yes

2. VSCode 左下にあるマークをクリック後、connect to Host を選択して、SSH先 Host の選択画面を表示。

   

3. ↑ の config にある isucon-server をSSH先 Host として選択する。

4. isucon ルートだと下記が出てしまうため、開くフォルダは webapp 配下とする。

   

5. Remote SSH 経由でGoの拡張ツールをインストール

[fujisawaryohei]

起動している サービスデーモン一覧のチェック

systemctl list-units --type=service --state=running

  UNIT                        LOAD   ACTIVE SUB     DESCRIPTION
  accounts-daemon.service     loaded active running Accounts Service
  acpid.service               loaded active running ACPI event daemon
  atd.service                 loaded active running Deferred execution scheduler
  cron.service                loaded active running Regular background program processing daemon
  dbus.service                loaded active running D-Bus System Message Bus
  getty@tty1.service          loaded active running Getty on tty1
  isucondition.go.service     loaded active running isucondition.go
  jiaapi-mock.service         loaded active running jiaapi-mock
  mariadb.service             loaded active running MariaDB 10.3.34 database server
  ModemManager.service        loaded active running Modem Manager
  multipathd.service          loaded active running Device-Mapper Multipath Device Controller
  networkd-dispatcher.service loaded active running Dispatcher daemon for systemd-networkd
  nginx.service               loaded active running A high performance web server and a reverse proxy server
  packagekit.service          loaded active running PackageKit Daemon
  polkit.service              loaded active running Authorization Manager
  rsyslog.service             loaded active running System Logging Service
  serial-getty@ttyS0.service  loaded active running Serial Getty on ttyS0
  ssh.service                 loaded active running OpenBSD Secure Shell server
  systemd-journald.service    loaded active running Journal Service
  systemd-logind.service      loaded active running Login Service
  systemd-networkd.service    loaded active running Network Service
  systemd-resolved.service    loaded active running Network Name Resolution
  systemd-timesyncd.service   loaded active running Network Time Synchronization
  systemd-udevd.service       loaded active running udev Kernel Device Manager
  udisks2.service             loaded active running Disk Manager
  unattended-upgrades.service loaded active running Unattended Upgrades Shutdown
  user@1100.service           loaded active running User Manager for UID 1100

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

27 loaded units listed.

[fujisawaryohei]

サーバーの状態チェック

# Linux ディストリビューションチェック → ubuntu
$ uname -a
20.04.1-Ubuntu SMP Thu Apr 7 22:10:15 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

# コア数チェック → コア数 1
$ grep processor /proc/cpuinfo
processor   : 0

# メモリ → 約1GB
$ free -m
Mem:            967         384          83           0         499         409
Swap:             0           0           0

# Go version → 1.16.5
$ go version
go1.16.5 linux/amd64

# Web Server → Nginx
$ sudo systemctl status nginx
● nginx.service - A high performance web server and a reverse proxy server
     Loaded: loaded (/lib/systemd/system/nginx.service; enabled; vendor preset: enabled)
     Active: active (running) since Sun 2022-07-03 15:26:43 JST; 1h 41min ago

# DB → Maria DB
# このタイミングでTablePlusのSettingを行う（envをチェックして接続情報を入力して、over-sshで接続）
$ sudo systemctl status mysql
● mariadb.service - MariaDB 10.3.34 database server
     Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
     Active: active (running) since Sun 2022-07-03 15:26:48 JST; 1h 52min ago
       Docs: man:mysqld(8)
             https://mariadb.com/kb/en/library/systemd/
   Main PID: 582 (mysqld)
     Status: "Taking your SQL requests now..."
      Tasks: 33 (limit: 1145)
     Memory: 137.6M
     CGroup: /system.slice/mariadb.service
             └─582 /usr/sbin/mysqld

# go module =>フレームワークはecho、jwt-goで認証していると思われる

$ cat go/go.mod
module github.com/isucon/isucon11-qualify/isucondition

go 1.16

require (
    github.com/dgrijalva/jwt-go v3.2.0+incompatible
    github.com/go-sql-driver/mysql v1.6.0
    github.com/gorilla/sessions v1.2.1
    github.com/jmoiron/sqlx v1.3.4
    github.com/labstack/echo/v4 v4.3.0
    github.com/labstack/gommon v0.3.0
    golang.org/x/crypto v0.0.0-20210513164829-c07d793c2f9a // indirect
)

[fujisawaryohei]

ベンチマーカーを起動してスコアチェック（起動方法は各大会で異なるため注意）

# ベンチ配下へ移動
$ cd ~/bench

$ ./bench -all-addresses 10.0.0.xxx -target 10.0.0.xxx:443 -tls -jia-service-url http://10.0.0.xxx:4999

score: 1896(1926 - 30)

[fujisawaryohei]

使用するツールのインストール（pprof UI出力用のgraphvizとhtop, nginxのprofiler alpを入れておく）

# htop, graphviz
$ sudo apt-get install graphviz htop

# alp
$ wget https://github.com/tkuchiki/alp/releases/download/v1.0.8/alp_linux_amd64.zip
$ unzip alp_linux_amd64.zip
$ sudo install ./alp /usr/local/bin

[fujisawaryohei]

Nginx, MriaDBの設定ファイルをリポジトリに追加

$ cd webapp

$ cp -a /etc/nginx ./

$ sudo chmod +r /etc/mysql/debian.cnf
$ cp -a /etc/mysql ./mysql

# どの設定ファイルが有効になっているか確認
$ sudo mariadb --help | grep cnf

295c603af5875f7a2fd5707894bcd9f2beaa7c94

[fujisawaryohei]

Makefile 追加 58482084a96b3a6c3ec187b2e2e30e59a1ab7d60

[fujisawaryohei]

pprof 追加

d407b7a258900e0575c2aae5f69a042f0eed200a

[fujisawaryohei]

初期時点での解析結果

ER図

alp

+--------+-----+--------+-----+------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
| COUNT  | 1XX |  2XX   | 3XX | 4XX  | 5XX | METHOD |            URI            |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+--------+-----+--------+-----+------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
|      2 |   0 |      2 |   0 |    0 |   0 | POST   | /initialize               | 0.204 | 0.220 |    0.424 | 0.212 | 0.220 | 0.220 | 0.220 |  0.008 |    23.000 |     23.000 |       46.000 |    23.000 |
|      6 |   0 |      2 |   4 |    0 |   0 | GET    | /register                 | 0.000 | 0.000 |    0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |     0.000 |    528.000 |     1056.000 |   176.000 |
|     60 |   0 |     36 |  24 |    0 |   0 | GET    | /isu/[a-z0-9-]+           | 0.000 | 0.004 |    0.024 | 0.000 | 0.000 | 0.004 | 0.004 |  0.001 |     0.000 |    528.000 |    19008.000 |   316.800 |
|     78 |   0 |     47 |   0 |   31 |   0 | POST   | /api/signout              | 0.000 | 0.664 |    3.244 | 0.042 | 0.096 | 0.272 | 0.664 |  0.098 |    21.000 |     21.000 |      651.000 |     8.346 |
|    103 |   0 |     19 |   0 |   84 |   0 | GET    | /api/trend                | 0.024 | 1.012 |   87.460 | 0.849 | 1.000 | 1.004 | 1.004 |  0.329 |     0.000 |   6322.000 |    85160.000 |   826.796 |
|    110 |   0 |    102 |   0 |    8 |   0 | POST   | /api/isu                  | 0.004 | 0.152 |    7.636 | 0.069 | 0.092 | 0.108 | 0.136 |  0.025 |    15.000 |    160.000 |    14248.000 |   129.527 |
|    133 |   0 |     63 |   0 |   70 |   0 | GET    | /api/user/me              | 0.000 | 0.312 |    2.748 | 0.021 | 0.056 | 0.136 | 0.292 |  0.054 |    21.000 |     43.000 |     3789.000 |    28.489 |
|    203 |   0 |    172 |  31 |    0 |   0 | GET    | /                         | 0.000 | 0.012 |    0.200 | 0.001 | 0.004 | 0.004 | 0.008 |  0.002 |     0.000 |    528.000 |    90816.000 |   447.369 |
|    261 |   0 |    134 |   0 |  127 |   0 | GET    | /api/isu/[a-z0-9-]+/graph | 0.472 | 1.004 |   39.612 | 0.152 | 0.368 | 0.660 | 1.000 |  0.226 |     0.000 |   7212.000 |   571613.000 |  2190.088 |
|    356 |   0 |    275 |   0 |   81 |   0 | GET    | /api/isu/[a-z0-9-]+       | 3.000 | 3.000 |   35.172 | 0.099 | 0.240 | 0.440 | 1.004 |  0.273 |     0.000 |    160.000 |    39152.000 |   109.978 |
|    367 |   0 |    142 |   0 |  225 |   0 | POST   | /api/auth                 | 0.008 | 3.000 |   26.348 | 0.072 | 0.100 | 0.252 | 1.108 |  0.305 |     0.000 |     19.000 |     2484.000 |     6.768 |
|    616 |   0 |    437 |   0 |  179 |   0 | GET    | /api/condition/[a-z0-9-]+ | 1.000 | 1.004 |  139.776 | 0.227 | 0.576 | 0.832 | 1.000 |  0.251 |     0.000 |   6958.000 |  2051687.000 |  3330.661 |
|    758 |   0 |    238 |   0 |  520 |   0 | GET    | /api/isu                  | 0.196 | 3.000 |  572.272 | 0.755 | 1.000 | 1.004 | 1.004 |  0.395 |     0.000 |   4731.000 |   621067.000 |   819.350 |
|   1127 |   0 |    652 | 475 |    0 |   0 | GET    | /assets/[a-z0-9-]+        | 0.000 | 0.020 |    1.876 | 0.002 | 0.004 | 0.008 | 0.012 |  0.003 |     0.000 | 743417.000 | 86791759.000 | 77011.321 |
|   1645 |   0 |   1512 |   0 |  133 |   0 | GET    | /api/isu/[a-z0-9-]+/icon  | 3.004 | 3.004 |  262.964 | 0.160 | 0.420 | 0.772 | 1.000 |  0.257 |     0.000 | 135259.000 | 39257707.000 | 23864.867 |
| 140243 |   0 | 130597 |   0 | 9646 |   0 | POST   | /api/condition/[a-z0-9-]+ | 0.012 | 0.140 | 1374.544 | 0.010 | 0.036 | 0.100 | 0.100 |  0.027 |     0.000 |     14.000 |      140.000 |     0.001 |
+--------+-----+--------+-----+------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+

slow-query-log

Reading mysql slow query log from /tmp/slow-query.log
Count: 4612  Time=0.16s (754s)  Lock=0.00s (0s)  Rows_sent=1.0 (4553), Rows_examined=41219.8 (190105694), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT N

Count: 6443  Time=0.06s (366s)  Lock=0.00s (0s)  Rows_sent=194.1 (1250366), Rows_examined=14833.8 (95573958), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC

Count: 14055  Time=0.00s (66s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
  COMMIT

Count: 363  Time=0.06s (19s)  Lock=0.00s (0s)  Rows_sent=159.1 (57754), Rows_examined=12945.7 (4699271), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S'  AND `timestamp` < 'S'   ORDER BY `timestamp` DESC

Count: 4319  Time=0.00s (17s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=1.0 (4319), isucon[isucon]@localhost
  INSERT INTO `isu_condition`   (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', N, 'S', 'S')

Count: 6167  Time=0.00s (15s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
  #

Count: 107  Time=0.04s (4s)  Lock=0.00s (0s)  Rows_sent=196.0 (20976), Rows_examined=10679.6 (1142719), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` ASC

pprof

[fujisawaryohei]

isu_condition テーブルに 複合PKを設定

1451fc30dc2a60cd6bd75ff63437a92965da71dd

score: 19844(19846 - 2) : pass

[fujisawaryohei]

bulk insert データ量そのものが多いためあまりスコアは変わらず・・

95ae510a57fbcb544ce9ddb852ad69878ca708f6

score: 19476(19478 - 2)

[fujisawaryohei]

get/trend LIMIT 1 に設定

a2d8ed82441b06689fed80842d5538228c5e609a

score: 27690(27692 - 2)