バルクインサート

txxxxc commented 3 months ago

一旦journalctlでログをダンプしたい journalctl --since "1 hour ago" こんな感じで行けるらしい

txxxxc commented 3 months ago

とりあえず別に調べなくてもいいけど、POST conditionのreqがどんな感じで送信されているかみたいので、ログを仕込む

そして、ログを出力してPOSTの中身を把握する

次にバルクインサート実装してベンチ取るぞ！

txxxxc commented 3 months ago

一旦サーバー再起動して、benchを途中まで走らせてログを取りたい

txxxxc commented 3 months ago

毎回sudoって打つのめんどいから、journalctlにsudo journalctlとかでalias登録したらいい説あります。

txxxxc commented 3 months ago

ええ感じにいけました


sudo journalctl --since "1 hour ago" > go.log

cat go.log | grep -A 1 "###"

Jun 05 18:15:41 ip-10-0-1-227 isucondition[14079]: {"time":"2024-06-05T18:15:41.494652866+09:00","level":"INFO","prefix":"echo","file":"main.go","line":"1178","message":"req: [
{true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855363} {true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855416} {true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855481}
{true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855543} {true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855596} {true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855659} 
{true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855719} {true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855781} {true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855837} 
{true is_dirty=true,is_overweight=true,is_broken=true ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！ 1628855901}]"}

txxxxc commented 3 months ago

grepのAとBはAfterとBeforeらしいですわわかりやすい

isucon@7:~$ grep --help

Context control:
  -B, --before-context=NUM  print NUM lines of leading context
  -A, --after-context=NUM   print NUM lines of trailing context
  -C, --context=NUM         print NUM lines of output context
  -NUM                      same as --context=NUM
      --color[=WHEN],
      --colour[=WHEN]       use markers to highlight the matching strings;
                            WHEN is 'always', 'never', or 'auto'
  -U, --binary              do not strip CR characters at EOL (MSDOS/Windows)

txxxxc commented 3 months ago

一旦バルクインサートでパフォーマンス改善できそうなのは判明したのでやりましょう。

txxxxc commented 3 months ago

バルクインサートを実装した一旦これがうまく言ってるかcurlコマンドで叩いてみよう

txxxxc commented 3 months ago

これでいい感じにbulk insertできてそう！

curl -X POST -H "Content-Type: application/json" -d '[
{"is_sitting": true, "condition": "is_dirty=true,is_overweight=true,is_broken=true", "message": "ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！", "timestamp": 1628855363},
        {"is_sitting": true, "condition": "is_dirty=true,is_overweight=true,is_broken=true", "message": "ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！", "timestamp": 1628855363},
                {"is_sitting": true, "condition": "is_dirty=true,is_overweight=true,is_broken=true", "message": "ドロドロのボロボロのヘロヘロだ！\u3000なんとかしてくれ！", "timestamp": 1628855363}
                ]' http://127.0.0.11:3000/api/condition/023c8e56-4410-484d-b7fa-702d48188d3c

slow-query.log

# administrator command: Prepare;
# User@Host: isucon[isucon] @ localhost [127.0.0.1]
# Thread_id: 36  Schema: isucondition  QC_hit: No
# Query_time: 0.003989  Lock_time: 0.000032  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 3  Bytes_sent: 52
SET timestamp=1717693168;
INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('023c8e56-4410-484d-b7fa-702d48188d3c', '2021-08-13 20:49:23', 1, 'is_dirty=true,is_overweight=true,is_broken=true', 'ドロドロのボロボロのヘロヘロだ！　なんとかしてくれ！'),('023c8e56-4410-484d-b7fa-702d48188d3c', '2021-08-13 20:49:23', 1, 'is_dirty=true,is_overweight=true,is_broken=true', 'ドロドロのボロボロのヘロヘロだ！　なんとかしてくれ！'),('023c8e56-4410-484d-b7fa-702d48188d3c', '2021-08-13 20:49:23', 1, 'is_dirty=true,is_overweight=true,is_broken=true', 'ドロドロのボロボロのヘロヘロだ！　なんとかしてくれ！');

txxxxc commented 3 months ago

それでもベンチは変わらないんだが、、、

02:01:29.773927 score: 959(1000 - 41) : pass
02:01:29.774063 deduction: 0 / timeout: 413
02:01:29.775039 <=== sendResult finish

txxxxc commented 3 months ago

でもエンドポイントのパフォーマンス改善はできてそう！！えぐい！

bulk insert後

+-------+--------+------------------------------+-------+-------+-------+----------+
| COUNT | METHOD |             URI              |  MIN  |  AVG  |  MAX  |   SUM    |
+-------+--------+------------------------------+-------+-------+-------+----------+
| 24473 | POST   | ^/api/condition/[\w\d-]+$    | 0.008 | 0.099 | 0.124 | 2433.376 |
| 303   | POST   | /api/isu                     | 0.004 | 0.890 | 1.012 | 269.664  |
| 124   | GET    | ^/api/isu/[\w\d-]+$          | 0.004 | 0.714 | 3.004 | 88.512   |
| 72    | GET    | /api/isu                     | 0.792 | 0.904 | 3.000 | 65.112   |
| 67    | GET    | ^/api/isu/[\w\d-]+/icon$     | 0.012 | 0.410 | 3.000 | 27.496   |
| 69    | POST   | /api/auth                    | 0.008 | 0.235 | 3.004 | 16.216   |
| 30    | GET    | ^/api/isu/[\w\d-]+/graph$    | 0.004 | 0.266 | 2.988 | 7.992    |
| 9     | GET    | /api/trend                   | 0.032 | 0.793 | 1.000 | 7.136    |
| 34    | GET    | ^/api/condition/[\w\d-]+$    | 0.012 | 0.103 | 1.000 | 3.496    |
| 1     | POST   | /initialize                  | 0.324 | 0.324 | 0.324 | 0.324    |
| 51    | GET    | /assets/index.23dac98b.js    | 0.004 | 0.004 | 0.024 | 0.220    |
| 51    | GET    | /assets/favicon.d0f5f504.svg | 0.004 | 0.004 | 0.024 | 0.212    |
| 51    | GET    | /assets/index.144d8ca8.css   | 0.004 | 0.004 | 0.020 | 0.196    |
| 51    | GET    | /assets/vendor.ee7444dd.js   | 0.004 | 0.004 | 0.028 | 0.184    |
| 29    | GET    | /                            | 0.008 | 0.005 | 0.020 | 0.156    |
| 15    | GET    | /api/user/me                 | 0.012 | 0.007 | 0.016 | 0.104    |
| 51    | GET    | /assets/logo_white.svg       | 0.012 | 0.001 | 0.012 | 0.064    |
| 9     | POST   | /api/signout                 | 0.004 | 0.004 | 0.024 | 0.040    |
| 6     | GET    | ^/isu/[\w\d-]+$              | 0.004 | 0.003 | 0.004 | 0.016    |
| 11    | GET    | /assets/logo_orange.svg      | 0.000 | 0.001 | 0.008 | 0.012    |
| 18    | GET    | ^/isu/[\w\d-]+/condition$    | 0.000 | 0.000 | 0.004 | 0.008    |
| 6     | GET    | ^/isu/[\w\d-]+/graph$        | 0.000 | 0.000 | 0.000 | 0.000    |
| 3     | GET    | /register                    | 0.000 | 0.000 | 0.000 | 0.000    |
+-------+--------+------------------------------+-------+-------+-------+----------+

txxxxc commented 3 months ago

一旦いい感じにできたっぽいので、とりあえずマージします。

txxxxc / isucon11-qualify

バルクインサート #13