Zenn
Open37

ISCON自分用メモ

もじゃなりもじゃなり

AMI ID?からEC2を作る
無料のt2でログインまでやってみる
作って立ち上がったけどどうやってアクセスできるんだ？

もじゃなりもじゃなり

セキュリティのインバウンドルールとアウトバウンドルールを以下のようにした
これしたら誰でもIPがわかったらアクセス出来てしまうけど、今回のテスト用ではいいや

ただ、変更してからアクセスできるようになるまで3分ぐらいかかった
t2.microだから遅い

もじゃなりもじゃなり

作ったキーの権限を変更する

chmod 0600 [pemファイル]

EC2作った時にsshキーも作ったので、これで入る
ssh -l ubuntu -i [pemファイル] [ipアドレス]

ubuntuユーザーが自動で作成されてるのか

もじゃなりもじゃなり

sshとかじゃなくてブラウザでsshして中身を見たいときは以下の手順

その後、「接続」を押して入る

もじゃなりもじゃなり

ログのjson設定を変更したら、ログの形式が変わった

119.25.102.8 - - [20/Oct/2024:22:41:49 +0900] "GET /image/9987.jpg HTTP/1.1" 200 367388 "http://13.114.17.42/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36"
119.25.102.8 - - [20/Oct/2024:22:41:49 +0900] "GET /image/9981.jpg HTTP/1.1" 200 81386 "http://13.114.17.42/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36"
time:20/Oct/2024:23:01:53 +0900	host:44.234.252.20	forwardedfor:-	req:GET / HTTP/1.1	status:200	method:GET	uri:/	size:5472	referer:-	ua:Mozilla/5.0 (iPod; U; CPU iPhone OS 6_1 like Mac OS X; en-HK) AppleWebKit/534.35 (KHTML, like Gecko) Chrome/11.0.696.65 Safari/534.35 Puffin/3.9174IP Mobile	reqtime:1.716	cache:-	runtime:-	apptime:1.716	vhost:13.114.17.42
time:20/Oct/2024:23:02:22 +0900	host:119.25.102.8	forwardedfor:-	req:GET / HTTP/1.1	status:200	method:GET	uri:/	size:5573	referer:http://13.114.17.42/	ua:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36	reqtime:1.592	cache:-	runtime:-	apptime:1.593	vhost:13.114.17.42
time:20/Oct/2024:23:02:22 +0900	host:119.25.102.8	forwardedfor:-	req:GET /image/9999.jpg HTTP/1.1	status:200	method:GET	uri:/image/9999.jpg	size:89928	referer:http://13.114.17.42/	ua:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36	reqtime:0.005	cache:-	runtime:-	apptime:0.005	vhost:13.114.17.42
time:20/Oct/2024:23:02:22 +0900	host:119.25.102.8	forwardedfor:-	req:GET /image/9998.jpg HTTP/1.1	status:200	method:GET	uri:/image/9998.jpg	size:61656	referer:http://13.114.17.42/	ua:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36	reqtime:0.005	cache:-	runtime:-	apptime:0.006	vhost:13.114.17.42
time:20/Oct/2024:23:02:22 +0900	host:119.25.102.8	forwardedfor:-	req:GET /image/9997.jpg HTTP/1.1	status:200	method:GET	uri:/image/9997.jpg	size:176404	referer:http://13.114.17.42/	ua:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36	reqtime:0.023	cache:-	runtime:-	apptime:0.001	vhost:13.114.17.42

最初のデフォルトの形式はこれっぽい
https://zenn.dev/yuucu/scraps/03458fc98196a6

もじゃなりもじゃなり

usersの中にもこんなにデータ入ってるんか

mysql> SELECT * FROM users;
+------+--------------+----------------------------------------------------------------------------------------------------------------------------------+-----------+---------+---------------------+
| id   | account_name | passhash                                                                                                                         | authority | del_flg | created_at          |
+------+--------------+----------------------------------------------------------------------------------------------------------------------------------+-----------+---------+---------------------+
|    1 | mary         | 645766c6b14e14fedf963fab8126161bdfaa6ed60fb0667c8b35d441c5042eade7c4a63345e3550e210bd67964bbbbc19fd9a76cec9ee7bd1be4b039dd699c9f |         1 |       0 | 2016-01-01 09:00:01 |
|    2 | patricia     | 276d5826b4b4d23163e03be78881cc1971a2e64bbf77383b71d96a2ebc52934680448905f259c466dab4c75c82e4f27d264a2320093e0234c2dc5050e38d6864 |         1 |       0 | 2016-01-01 09:00:02 |
|    3 | linda        | 93ac5e881fb7035b8f07980b6ec3dc9e1ddd6a230509b855d75760c3a3a7b4cc9d0c20857e463909258fb934853b262c667d6f17eee436371ee5d25674b45a60 |         1 |       0 | 2016-01-01 09:00:03 |
|    4 | barbara      | c0bddc3d4a2163f7e9d3c144daf424975a8e26c932ce1f14ef4ed33986cca5600ab8813d0055e73153c99cecb7165703c7d27beef0e9c5cc7e27df300b0ffdd6 |         1 |       0 | 2016-01-01 09:00:04 |
|    5 | elizabeth    | 110f7efc8dbbdc2302de920721b0e0408ff06c86c08930619d3b88b142abc7feb3c6ec637fa211987e78d41fc7ca8170a41842eecc51560805c9d3942b8b957b |         1 |       0 | 2016-01-01 09:00:05 |
|    6 | jennifer     | f156b44984f2910916371ee5112a1d0a32b2105c8cbe8fb9ed3011bdafa3a20ca01a5f1be8e4e921b959e0f1cea667b2d1f80dbe08c1b3de5310a915bf3e5849 |         1 |       0 | 2016-01-01 09:00:06 |
|    7 | maria        | 5cf37f233fe61b20ef882e88b3a0cea99caf7e714e60ff4f4e52f3099236b765ce7c1712d98bde8529e707f7577f8f46be7e6a43931a3056460ca0c9937dec91 |         1 |       0 | 2016-01-01 09:00:07 |
|    8 | susan        | 2a4a4d042136a6649e81a3a30b3d33e4b8c8958cf9071c3d8ea4e264e732296c89a7123eec7d1766260a7c589ce8b2ebe8190d11158add69b32cadfa45fca81a |         1 |       0 | 2016-01-01 09:00:08 |
|    9 | margaret     | c49f29f969fe23764e51cfee47079aedcbc5d5d6f1e597834f52e3db384c72635eefcac4366abdf81208c1b526ccdb3341083dfa4fa7f91c1bdc15b8d4d388cb |         1 |       0 | 2016-01-01 09:00:09 |
もじゃなりもじゃなり

テーブルは3つだけ

mysql> SHOW TABLES;
+-------------------+
| Tables_in_isuconp |
+-------------------+
| comments          |
| posts             |
| users             |
+-------------------+
もじゃなりもじゃなり

mysqlのコマンドで
SELECT * FROM comments\G
と
SELECT * FROM comments;
で表示が異なるんですけどこれってどうやって使い分ける？

`SELECT * FROM comments\G` と `SELECT * FROM comments;` の違いは、出力形式にあります。

- `SELECT * FROM comments;` は、標準的なテーブル形式で結果を表示します。通常、複数の行と列が横に並んだ状態で表示され、各行が一行に出力されます。

- `SELECT * FROM comments\G` は、`G` フォーマットと呼ばれるもので、出力結果を縦に表示します。各行が個別のレコードとして1列ずつ詳細に表示されるため、列の名前と値が1行ごとに対になって表示されます。

### 使い分け方
- **テーブル全体をざっくり確認したい場合** は、通常の `;` を使ってテーブル形式で確認します。
- **レコードの詳細や、テーブルの列数が多い場合に各レコードを丁寧に確認したい場合** は、`\G` を使うと見やすくなります。

例えば、列の数が多いときや、特定のレコードを一つずつ詳しく確認したいときには `\G` の方が適しています。
もじゃなりもじゃなり

インデックス貼る前

mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 9999 ORDER BY `created_at` DESC LIMIT 3\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: comments
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 99666
     filtered: 10.00
        Extra: Using where; Using filesort
1 row in set, 1 warning (0.00 sec)
もじゃなりもじゃなり

インデックスを貼ったあと

mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 9999 ORDER BY `created_at` DESC LIMIT 3\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: comments
   partitions: NULL
         type: ref
possible_keys: index_post_id
          key: index_post_id
      key_len: 4
          ref: const
         rows: 11
     filtered: 100.00
        Extra: Using filesort
1 row in set, 1 warning (0.00 sec)

less コマンドでGで最後尾に行って確認すると確かに9行の読み取りに減ってる

# Query_time: 0.000096  Lock_time: 0.000001 Rows_sent: 3  Rows_examined: 9
SET timestamp=1729775568;
SELECT * FROM `comments` WHERE `post_id` = 9982 ORDER BY `created_at` DESC LIMIT 3;
もじゃなりもじゃなり

ログローテートで

sudo rm /var/log/mysql/mysql-slow.log

とかしたら、mysqlを再起動させる

sudo systemctl restart mysql

じゃないとログが再度生成されない
そらそう

もじゃなりもじゃなり

ab -c 1 -t 30

Requests per second:    6.79 [#/sec] (mean)
Time per request:       147.171 [ms] (mean)
Time per request:       147.171 [ms] (mean, across all concurrent requests)

ab -c 2 -t 30

Requests per second:    13.10 [#/sec] (mean)
Time per request:       152.729 [ms] (mean)
Time per request:       76.365 [ms] (mean, across all concurrent requests)

ab -c 4 -t 30

Requests per second:    13.82 [#/sec] (mean)
Time per request:       289.349 [ms] (mean)
Time per request:       72.337 [ms] (mean, across all concurrent requests)

並列度は2でCPUのが頭打ちになってた
だから1→2で一つのリクエストを処理するRequests per secondは増えたけど、2→4は増加なし
なんで、並列度を4にするとTime per requestは倍になった？
→これ以上増やせなかったからか

もじゃなりもじゃなり

unicornの並列化後
ab -c 1 -t 30

Requests per second:    6.42 [#/sec] (mean)
Time per request:       155.856 [ms] (mean)
Time per request:       155.856 [ms] (mean, across all concurrent requests)

ab -c 2 -t 30

Requests per second:    12.43 [#/sec] (mean)
Time per request:       160.918 [ms] (mean)
Time per request:       80.459 [ms] (mean, across all concurrent requests)

ab -c 4 -t 30

Requests per second:    12.37 [#/sec] (mean)
Time per request:       323.464 [ms] (mean)
Time per request:       80.866 [ms] (mean, across all concurrent requests)
もじゃなりもじゃなり
k6 run --vus 1 --duration 30s ab.js

http_req_duration..............: avg=81.21ms  min=78.65ms med=80.16ms  max=126.76ms p(90)=83.69ms p(95)=86.18ms
http_reqs......................: 369   12.290851/s
もじゃなりもじゃなり
k6 run --vus 2 --duration 30s ab.js

http_req_duration..............: avg=136.72ms min=103.84ms med=134.36ms max=232.58ms p(90)=143.67ms p(95)=149.33ms
http_reqs......................: 439
もじゃなりもじゃなり
k6 run --vus 4 --duration 30s ab.js

http_req_duration..............: avg=284.75ms min=165.2ms  med=282.02ms max=449.45ms p(90)=328.48ms p(95)=339.65ms
http_reqs......................: 422   14.019726/s
もじゃなりもじゃなり

5章にはいって、mysqlにrootで入って、プロセスを見たけどおかしいな

sudo mysql -u root

mysql> SHOW FULL PROCESSLIST;
+----+-----------------+-----------+---------+---------+------+------------------------+-----------------------+
| Id | User            | Host      | db      | Command | Time | State                  | Info                  |
+----+-----------------+-----------+---------+---------+------+------------------------+-----------------------+
|  5 | event_scheduler | localhost | NULL    | Daemon  |  434 | Waiting on empty queue | NULL                  |
| 11 | root            | localhost | NULL    | Query   |    0 | init                   | SHOW FULL PROCESSLIST |
| 12 | isuconp         | localhost | isuconp | Sleep   |   39 |                        | NULL                  |
| 13 | isuconp         | localhost | isuconp | Sleep   |   41 |                        | NULL                  |
| 14 | isuconp         | localhost | isuconp | Sleep   |   41 |                        | NULL                  |
| 15 | isuconp         | localhost | isuconp | Sleep   |   41 |                        | NULL                  |
+----+-----------------+-----------+---------+---------+------+------------------------+-----------------------+
6 rows in set, 1 warning (0.00 sec)
もじゃなりもじゃなり

とりあえずベンチ回したら629点になった

isucon@ip-172-31-8-207:~/private_isu.git/benchmarker$ ./bin/benchmarker -u ./userdata -t http://3.112.3/
{"pass":true,"score":629,"success":571,"fail":2,"messages":["リクエストがタイムアウトしました (POST /login)"]}
もじゃなりもじゃなり
top - 22:08:03 up 29 min,  1 user,  load average: 0.16, 0.13, 0.07
Tasks: 122 total,   1 running, 121 sleeping,   0 stopped,   0 zombie
%Cpu(s): 50.7 us,  1.2 sy,  0.0 ni, 48.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.2 st 
MiB Mem :   3816.9 total,   1900.7 free,   1055.2 used,   1100.7 buff/cache     
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   2761.7 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                       
   1028 mysql     20   0 1789512 466612  36736 S  97.7  11.9   1:26.73 mysqld                        
   1049 isucon    20   0  613404  76176   9856 S   3.3   1.9   0:03.22 ruby                          
   2470 ubuntu    20   0 1321564  92116  44672 S   1.3   2.4   0:02.17 node                          
   2507 ubuntu    20   0 1263920  61868  41856 S   0.7   1.6   0:00.66 node                          
   2421 ubuntu    20   0   32624  18788  13568 S   0.3   0.5   0:02.02 code-38c31bc77e               
      1 root      20   0   22676  13636   9412 S   0.0   0.3   0:02.69 systemd                       
      2 root      20   0       0      0      0 S   0.0   0.0   0:00.00 kthreadd                      
      3 root      20   0       0      0      0 S   0.0   0.0   0:00.00 pool_workqueue_release        
      4 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/R-rcu_g               
      5 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/R-rcu_p

ベンチ回してるとmysqlが高いね

もじゃなりもじゃなり
isucon@ip-172-31-8-180:~$ sudo mysqldumpslow /var/log/mysql/mysql-slow.log

Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 17  Time=0.04s (0s)  Lock=0.00s (0s)  Rows=7.8 (133), isuconp[isuconp]@localhost
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC

Count: 1237  Time=0.04s (49s)  Lock=0.00s (0s)  Rows=2.7 (3384), isuconp[isuconp]@localhost
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

Count: 5  Time=0.02s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isuconp[isuconp]@localhost
  INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (N,'S','S','S')

スロークエリを見ると17回しか呼ばれてないのに一番時間の長い処理がある

もじゃなりもじゃなり
isucon@ip-172-31-8-207:~/private_isu.git/benchmarker$ ./bin/benchmarker -u ./userdata -t http://3.112.33.123/
{"pass":true,"score":9283,"success":7906,"fail":0,"messages":[]}

インデックス貼ったらスコアめっちゃ伸びた
あと、リクエストタイムアウトがなくなった