search

izumin5210-sandbox / isucon7-q-20180430

0 stars 0 forks source link

タイムライン #2

Open izumin5210 opened 6 years ago

izumin5210 commented 6 years ago 
{
  "job_id": "",
  "ip_addrs": "52.68.78.7",
  "pass": true,
  "score": 6055,
  "message": "ok",
  "error": [
    "2018-04-30 04:38:24.300726972 +0000 UTC m=+15.142075848 リクエストがタイムアウトしました (POST /login )",
    "2018-04-30 04:38:24.34027693 +0000 UTC m=+15.181625615 リクエストがタイムアウトしました (POST /login )",
    "2018-04-30 04:38:24.347451273 +0000 UTC m=+15.188800029 リクエストがタイムアウトしました (POST /login )",
    "...",
    "04/30 04:39:07 エラーが発生した ため負荷レベルを上げられませんでした。2018-04-30 04:39:07.73033934 +0000 UTC m=+58.571688050 リクエストがタイムアウトしました (GET /icons/ec48374ca1b2693ca643041659fb8372c72d1ddd.png )",
    "04/30 04:39:08 エラーが発生したため負荷レベルを上げられませんでした。2018-04-30 04:39:08.294033211 +0000 UTC m=+59.135381937 リクエストがタイムアウトしました (GET /icons/e58ed7194ed4a99d9d6ada9e3383983edcbd1edc.png )"
  ],
  "load_level": 1,
  "start_time": "2018-04-30T04:38:09.451911163Z",
  "end_time": "2018-04-30T04:39:09.970959755Z"
}
izumin5210 commented 6 years ago

image server #6

{
  "job_id": "",
  "ip_addrs": "52.68.78.7",
  "pass": true,
  "score": 6541,
  "message": "ok",
  "error": [
    "2018-04-30 10:04:33.086139761 +0000 UTC m=+9.460538788 リクエストがタイムアウトしました (POST /message )",
    "2018-04-30 10:04:33.087344572 +0000 UTC m=+9.461743678 リクエストがタイムアウトしました (POST /message )",
    "...",
    "04/30 10:05:21 レスポンスが遅いため負荷レベルを上げられませんでした。/history/10?page=4",
    "04/30 10:05:22 レスポンスが遅いため負荷レベルを上げられませんでした。/history/10?page=17",
    "04/30 10:05:23 レスポンスが遅いため負荷レベルを上げられませんでした。/history/10?page=17"
  ],
  "load_level": 1,
  "start_time": "2018-04-30T10:04:23.918369843Z",
  "end_time": "2018-04-30T10:05:24.449948011Z"
}
isucon@ip-172-31-25-48:~$ cat /var/log/nginx/access.alp.log | ./alp -c alp.yaml --sum -r
+-------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+--------+--------------------+
| COUNT |  MIN  |  MAX  |   SUM    |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) | METHOD |        URI         |
+-------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+--------+--------------------+
|   359 | 0.230 | 8.086 | 1152.958 | 3.212 | 0.546 | 3.043 | 7.960 |  1.220 |     0.000 |   3098.000 |  1043187.000 |  2905.813 | GET    | /fetch             |
|   212 | 0.001 | 3.001 |  128.709 | 0.607 | 0.001 | 0.009 | 3.000 |  1.061 |     0.000 |      0.000 |        0.000 |     0.000 | POST   | /login             |
|    92 | 0.004 | 4.024 |  113.856 | 1.238 | 0.000 | 0.887 | 3.942 |  1.091 |     2.000 |  52648.000 |  2374987.000 | 25815.076 | GET    | /message           |
|    23 | 0.004 | 3.001 |   65.061 | 2.829 | 0.004 | 3.000 | 3.001 |  0.617 |     0.000 |      0.000 |        0.000 |     0.000 | POST   | /message           |
|    18 | 0.002 | 3.001 |   32.311 | 1.795 | 0.002 | 2.126 | 3.000 |  1.105 |     0.000 |      0.000 |        0.000 |     0.000 | POST   | /profile           |
|    21 | 0.001 | 6.043 |   28.885 | 1.375 | 0.001 | 1.201 | 5.532 |  1.642 |     0.000 |   3128.000 |    52228.000 |  2487.048 | GET    | /profile/.+        |
|    26 | 0.011 | 6.104 |   27.042 | 1.040 | 0.000 | 0.686 | 1.991 |  1.271 |     0.000 |   9127.000 |   143619.000 |  5523.808 | GET    | /history/\d+       |
|    56 | 0.002 | 5.795 |   22.902 | 0.409 | 0.002 | 0.155 | 2.225 |  0.876 |  3015.000 |   3037.000 |   163561.000 |  2920.732 | GET    | /channel/\d+       |
|    17 | 0.003 | 2.521 |   18.934 | 1.114 | 0.003 | 1.363 | 1.956 |  0.844 |     0.000 |      0.000 |        0.000 |     0.000 | POST   | /register          |
|    11 | 0.432 | 2.090 |   13.188 | 1.199 | 0.000 | 0.660 | 1.975 |  0.714 |     0.000 |      0.000 |        0.000 |     0.000 | GET    | /logout            |
|     3 | 0.001 | 5.532 |    5.543 | 1.848 | 0.001 | 0.001 | 0.010 |  2.605 |     0.000 |   2995.000 |     2995.000 |   998.333 | GET    | /add_channel       |
|  2233 | 0.000 | 0.015 |    3.886 | 0.002 | 0.000 | 0.001 | 0.008 |  0.002 | 52267.000 | 768501.000 | 85608994.000 | 38338.107 | GET    | /icons/.+          |
|    93 | 0.001 | 0.033 |    0.324 | 0.003 | 0.001 | 0.003 | 0.004 |  0.003 |     0.000 |      0.000 |        0.000 |     0.000 | POST   | /add_channel       |
|   561 | 0.000 | 0.017 |    0.228 | 0.000 | 0.000 | 0.000 | 0.009 |  0.002 |  1741.000 | 150996.000 | 27058764.000 | 48233.091 | GET    | /(js|css|fonts)/.+ |
|     2 | 0.002 | 0.199 |    0.201 | 0.101 | 0.002 | 0.002 | 0.002 |  0.099 |   904.000 |    904.000 |     1808.000 |   904.000 | GET    | /login             |
|     2 | 0.002 | 0.038 |    0.040 | 0.020 | 0.002 | 0.002 | 0.002 |  0.018 |   906.000 |    906.000 |     1812.000 |   906.000 | GET    | /register          |
|     1 | 0.020 | 0.020 |    0.020 | 0.020 | 0.020 | 0.020 | 0.020 |  0.000 |     0.000 |      0.000 |        0.000 |     0.000 | GET    | /initialize        |
|     2 | 0.002 | 0.008 |    0.010 | 0.005 | 0.002 | 0.002 | 0.002 |  0.003 |   884.000 |    884.000 |     1768.000 |   884.000 | GET    | /                  |
|    51 | 0.000 | 0.000 |    0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |   318.000 |    318.000 |    16218.000 |   318.000 | GET    | /favicon.ico       |
+-------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+--------+--------------------+
izumin5210 commented 6 years ago

index #7

{
  "job_id": "",
  "ip_addrs": "52.68.78.7",
  "pass": true,
  "score": 10075,
  "message": "ok",
  "error": [
    "2018-04-30 11:10:50.651226894 +0000 UTC m=+9.256490520 リクエストがタイムアウトしました (POST /message )",
    "2018-04-30 11:10:50.684470149 +0000 UTC m=+9.289733842 リクエストがタイムアウトしました (POST /login )",
    "...",
      "04/30 11:11:40 レスポンスが遅いため負荷レベルを上げられませんでした。/message?channel_id=10&last_message_id=10032",
    "04/30 11:11:41 レスポンスが遅いため負荷レベルを上げられませんでした。/message?channel_id=10&last_message_id=10032"
  ],
  "load_level": 1,
  "start_time": "2018-04-30T11:10:41.68709615Z",
  "end_time": "2018-04-30T11:11:42.217742909Z"
}
isucon@ip-172-31-25-48:~$ cat /var/log/nginx/access.alp.log | ./alp -c alp.yaml --sum -r
+-------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+--------+--------------------+
| COUNT |  MIN  |  MAX  |   SUM    |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |   SUM(BODY)   | AVG(BODY) | METHOD |        URI         |
+-------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+--------+--------------------+
|   536 | 0.105 | 4.787 | 1497.146 | 2.793 | 0.276 | 2.813 | 4.667 |  0.715 |     0.000 |   3101.000 |   1573852.000 |  2936.291 | GET    | /fetch             |
|   390 | 0.001 | 3.460 |  626.934 | 1.608 | 0.005 | 1.659 | 3.047 |  0.627 |     0.000 |  52648.000 |   3752995.000 |  9623.064 | GET    | /message           |
|   315 | 0.004 | 3.001 |  602.873 | 1.914 | 0.276 | 1.870 | 3.000 |  0.499 |     0.000 |      0.000 |         0.000 |     0.000 | POST   | /message           |
|   239 | 0.001 | 3.001 |  140.002 | 0.586 | 0.001 | 0.023 | 2.999 |  0.848 |     0.000 |      0.000 |         0.000 |     0.000 | POST   | /login             |
|    80 | 0.002 | 3.663 |  103.523 | 1.294 | 0.002 | 0.208 | 3.609 |  1.483 |  3031.000 |   3054.000 |    237105.000 |  2963.812 | GET    | /channel/\d+       |
|    56 | 0.001 | 3.163 |   77.829 | 1.390 | 0.001 | 1.663 | 3.159 |  0.948 |     0.000 |   9203.000 |    267907.000 |  4784.054 | GET    | /history/\d+       |
|    26 | 0.001 | 3.389 |   36.661 | 1.410 | 0.001 | 1.518 | 3.288 |  1.109 |     0.000 |   3141.000 |     68099.000 |  2619.192 | GET    | /profile/.+        |
|    23 | 0.002 | 3.000 |   36.287 | 1.578 | 0.002 | 1.594 | 3.000 |  0.985 |     0.000 |      0.000 |         0.000 |     0.000 | POST   | /profile           |
|    16 | 0.001 | 3.281 |   28.963 | 1.810 | 0.001 | 1.768 | 2.512 |  0.743 |     0.000 |      0.000 |         0.000 |     0.000 | GET    | /logout            |
|    22 | 0.003 | 2.418 |   27.962 | 1.271 | 0.003 | 1.567 | 2.394 |  0.892 |     0.000 |      0.000 |         0.000 |     0.000 | POST   | /register          |
|  3282 | 0.001 | 0.028 |   11.634 | 0.004 | 0.000 | 0.001 | 0.017 |  0.004 |     0.000 | 768501.000 | 125152154.000 | 38132.893 | GET    | /icons/.+          |
|     3 | 0.001 | 3.154 |    3.163 | 1.054 | 0.001 | 0.001 | 0.008 |  1.485 |     0.000 |   3008.000 |      3008.000 |  1002.667 | GET    | /add_channel       |
|    93 | 0.001 | 0.033 |    0.328 | 0.004 | 0.001 | 0.003 | 0.005 |  0.003 |     0.000 |      0.000 |         0.000 |     0.000 | POST   | /add_channel       |
|     2 | 0.001 | 0.187 |    0.188 | 0.094 | 0.001 | 0.001 | 0.001 |  0.093 |   904.000 |    904.000 |      1808.000 |   904.000 | GET    | /login             |
|   825 | 0.000 | 0.006 |    0.099 | 0.000 | 0.000 | 0.000 | 0.003 |  0.001 |  1741.000 | 150996.000 |  39792300.000 | 48233.091 | GET    | /(js|css|fonts)/.+ |
|     2 | 0.001 | 0.042 |    0.043 | 0.022 | 0.001 | 0.001 | 0.001 |  0.021 |   906.000 |    906.000 |      1812.000 |   906.000 | GET    | /register          |
|     1 | 0.027 | 0.027 |    0.027 | 0.027 | 0.027 | 0.027 | 0.027 |  0.000 |     0.000 |      0.000 |         0.000 |     0.000 | GET    | /initialize        |
|     2 | 0.001 | 0.007 |    0.008 | 0.004 | 0.001 | 0.001 | 0.001 |  0.003 |   884.000 |    884.000 |      1768.000 |   884.000 | GET    | /                  |
|    75 | 0.000 | 0.000 |    0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |   318.000 |    318.000 |     23850.000 |   318.000 | GET    | /favicon.ico       |
+-------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+--------+--------------------+
izumin5210 commented 6 years ago

Resolve N + 1 query on GET /message #9

さがった

{
  "job_id": "",
  "ip_addrs": "52.68.78.7",
  "pass": true,
  "score": 8331,
  "message": "ok",
  "error": [
    "2018-04-30 11:49:50.764126804 +0000 UTC m=+8.200839514 リクエストがタイムアウトしました (POST /register )",
    "2018-04-30 11:49:51.022526454 +0000 UTC m=+8.459239140 リクエストがタイムアウトしました (POST /message )",
    "...",
    "04/30 11:50:41 レスポンスが遅いため負荷レベルを上げられませんでした。/message?channel_id=2&last_message_id=10101",
    "04/30 11:50:42 レスポンスが遅いため負荷レベルを上げられませんでした。/message?channel_id=2&last_message_id=10101"
  ],
  "load_level": 1,
  "start_time": "2018-04-30T11:49:42.855063361Z",
  "end_time": "2018-04-30T11:50:43.389893418Z"
}

GET /message 自体は avg 1.608 -> 0.784 に改善している

isucon@ip-172-31-25-48:~$ cat /var/log/nginx/access.alp.log | ./alp -c alp.yaml --avg -r
+-------+-------+-------+----------+-------+-------+-------+-------+--------+------------+------------+---------------+-----------+--------+--------------------+
| COUNT |  MIN  |  MAX  |   SUM    |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |   SUM(BODY)   | AVG(BODY) | METHOD |        URI         |
+-------+-------+-------+----------+-------+-------+-------+-------+--------+------------+------------+---------------+-----------+--------+--------------------+
|   535 | 0.001 | 4.532 | 1075.389 | 2.010 | 0.495 | 1.989 | 4.308 |  0.624 |      0.000 |   3008.000 |   1548428.000 |  2894.258 | GET    | /fetch             |
|   131 | 0.004 | 3.000 |  161.599 | 1.234 | 0.004 | 1.031 | 3.000 |  0.801 |      0.000 |      0.000 |         0.000 |     0.000 | POST   | /message           |
|    53 | 0.002 | 2.615 |   60.486 | 1.141 | 0.002 | 1.141 | 2.184 |  0.581 |      0.000 |      0.000 |         0.000 |     0.000 | POST   | /profile           |
|    51 | 0.003 | 3.000 |   48.066 | 0.942 | 0.003 | 0.972 | 2.432 |  0.560 |      0.000 |      0.000 |         0.000 |     0.000 | POST   | /register          |
|    43 | 0.001 | 1.796 |   40.139 | 0.933 | 0.001 | 0.938 | 1.382 |  0.300 |      0.000 |      0.000 |         0.000 |     0.000 | GET    | /logout            |
|    54 | 0.001 | 3.363 |   49.136 | 0.910 | 0.001 | 0.968 | 2.363 |  0.562 |      0.000 |   3102.000 |    150750.000 |  2791.667 | GET    | /profile/.+        |
|   115 | 0.001 | 3.370 |  104.477 | 0.908 | 0.001 | 0.963 | 3.058 |  0.619 |      0.000 |   8912.000 |    490871.000 |  4268.443 | GET    | /history/\d+       |
|     4 | 0.001 | 2.407 |    3.344 | 0.836 | 0.001 | 0.010 | 0.926 |  0.982 |      0.000 |   2970.000 |      2970.000 |   742.500 | GET    | /add_channel       |
|   304 | 0.001 | 2.926 |  238.279 | 0.784 | 0.003 | 0.826 | 2.115 |  0.441 |      0.000 |  52648.000 |   2358072.000 |  7756.816 | GET    | /message           |
|   347 | 0.001 | 3.000 |  225.193 | 0.649 | 0.001 | 0.494 | 3.000 |  0.796 |      0.000 |      0.000 |         0.000 |     0.000 | POST   | /login             |
|    88 | 0.001 | 3.061 |   47.250 | 0.537 | 0.001 | 0.219 | 2.408 |  0.541 |      0.000 |   3014.000 |    255026.000 |  2898.023 | GET    | /channel/\d+       |
|     3 | 0.002 | 1.024 |    1.200 | 0.400 | 0.002 | 0.002 | 0.174 |  0.447 |    904.000 |    904.000 |      2712.000 |   904.000 | GET    | /login             |
|     3 | 0.001 | 0.674 |    0.677 | 0.226 | 0.001 | 0.001 | 0.002 |  0.317 |    884.000 |    884.000 |      2652.000 |   884.000 | GET    | /                  |
|     3 | 0.002 | 0.623 |    0.662 | 0.221 | 0.002 | 0.002 | 0.037 |  0.285 |    906.000 |    906.000 |      2718.000 |   906.000 | GET    | /register          |
|     1 | 0.023 | 0.023 |    0.023 | 0.023 | 0.023 | 0.023 | 0.023 |  0.000 |      0.000 |      0.000 |         0.000 |     0.000 | GET    | /initialize        |
|    94 | 0.001 | 0.964 |    1.296 | 0.014 | 0.001 | 0.003 | 0.032 |  0.099 |      0.000 |      0.000 |         0.000 |     0.000 | POST   | /add_channel       |
|  1935 | 0.001 | 0.010 |    2.242 | 0.001 | 0.000 | 0.001 | 0.008 |  0.001 | 430334.000 | 768501.000 | 116414151.000 | 60162.352 | GET    | /icons/.+          |
|   869 | 0.000 | 0.019 |    0.223 | 0.000 | 0.000 | 0.000 | 0.006 |  0.001 |   1741.000 | 150996.000 |  41914556.000 | 48233.091 | GET    | /(js|css|fonts)/.+ |
|    79 | 0.000 | 0.000 |    0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |    318.000 |    318.000 |     25122.000 |   318.000 | GET    | /favicon.ico       |
+-------+-------+-------+----------+-------+-------+-------+-------+--------+------------+------------+---------------+-----------+--------+--------------------+