redis pusub app server hang 문제

[doowonee]

여러명의 유저 적은 채팅

이상없음 50MB 까지 갔도 웹 서버 안죽음 커넥션 다끊어도 ㄱㅊ음 웹페이지 응답도 빠르고 웹 브라우저에서 ws 응답도 빠름 4천명의 유저 채팅 전파 10ms 이내로 끝남

[2022-08-16T14:38:22.344Z INFO  ws_client] status: Status(0, 0, 0)
[2022-08-16T14:38:25.343Z INFO  ws_client] status: Status(282, 1, 95)
[2022-08-16T14:38:28.344Z INFO  ws_client] status: Status(1711, 9, 191)
[2022-08-16T14:38:31.343Z INFO  ws_client] status: Status(4468, 19, 287)
[2022-08-16T14:38:34.344Z INFO  ws_client] status: Status(7834, 27, 383)
[2022-08-16T14:38:37.344Z INFO  ws_client] status: Status(11935, 35, 479)
[2022-08-16T14:38:40.344Z INFO  ws_client] status: Status(18519, 47, 575)
[2022-08-16T14:38:43.344Z INFO  ws_client] status: Status(25745, 58, 671)
[2022-08-16T14:38:46.343Z INFO  ws_client] status: Status(33996, 69, 767)
[2022-08-16T14:38:49.343Z INFO  ws_client] status: Status(43205, 80, 863)
[2022-08-16T14:38:52.344Z INFO  ws_client] status: Status(57195, 95, 959)
[2022-08-16T14:38:55.344Z INFO  ws_client] status: Status(72687, 109, 1054)
[2022-08-16T14:38:58.344Z INFO  ws_client] status: Status(89642, 124, 1150)
[2022-08-16T14:39:01.343Z INFO  ws_client] status: Status(105480, 137, 1246)
[2022-08-16T14:39:04.343Z INFO  ws_client] status: Status(130422, 156, 1342)
[2022-08-16T14:39:07.343Z INFO  ws_client] status: Status(154508, 173, 1438)
[2022-08-16T14:39:10.344Z INFO  ws_client] status: Status(184688, 193, 1534)
[2022-08-16T14:39:13.343Z INFO  ws_client] status: Status(215062, 212, 1630)
[2022-08-16T14:39:16.343Z INFO  ws_client] status: Status(254052, 235, 1726)
[2022-08-16T14:39:19.344Z INFO  ws_client] status: Status(297135, 259, 1822)
[2022-08-16T14:39:22.343Z INFO  ws_client] status: Status(344395, 284, 1918)
[2022-08-16T14:39:25.344Z INFO  ws_client] status: Status(395978, 309, 2014)
[2022-08-16T14:39:28.343Z INFO  ws_client] status: Status(450005, 334, 2110)
[2022-08-16T14:39:31.343Z INFO  ws_client] status: Status(508733, 361, 2206)
[2022-08-16T14:39:34.344Z INFO  ws_client] status: Status(565575, 386, 2301)
[2022-08-16T14:39:37.344Z INFO  ws_client] status: Status(627121, 412, 2397)
[2022-08-16T14:39:40.344Z INFO  ws_client] status: Status(693606, 439, 2493)
[2022-08-16T14:39:43.344Z INFO  ws_client] status: Status(762683, 466, 2589)
[2022-08-16T14:39:46.344Z INFO  ws_client] status: Status(836944, 493, 2685)
[2022-08-16T14:39:49.344Z INFO  ws_client] status: Status(916600, 522, 2780)
[2022-08-16T14:39:52.343Z INFO  ws_client] status: Status(999065, 551, 2876)
[2022-08-16T14:39:55.343Z INFO  ws_client] status: Status(1095478, 584, 2972)
[2022-08-16T14:39:58.343Z INFO  ws_client] status: Status(1178172, 611, 3068)
[2022-08-16T14:40:01.343Z INFO  ws_client] status: Status(1278272, 643, 3164)
[2022-08-16T14:40:04.344Z INFO  ws_client] status: Status(1371946, 672, 3260)
[2022-08-16T14:40:07.344Z INFO  ws_client] status: Status(1490623, 708, 3356)
[2022-08-16T14:40:10.344Z INFO  ws_client] status: Status(1594353, 737, 3452)
[2022-08-16T14:40:13.343Z INFO  ws_client] status: Status(1720869, 772, 3547)
[2022-08-16T14:40:16.343Z INFO  ws_client] status: Status(1838699, 805, 3643)
[2022-08-16T14:40:19.344Z INFO  ws_client] status: Status(1984567, 843, 3739)
[2022-08-16T14:40:22.344Z INFO  ws_client] status: Status(2110144, 876, 3834)
[2022-08-16T14:40:25.343Z INFO  ws_client] status: Status(2250370, 912, 3930)
[2022-08-16T14:40:28.343Z INFO  ws_client] status: Status(2394038, 948, 4026)
[2022-08-16T14:40:31.343Z INFO  ws_client] status: Status(2557625, 988, 4121)

##적은 유저 많은 채팅

초당 300개 정도의 채팅은 문제없이 처리함 50MB 정도임 근데 그이상 하면 어느순간 서버 동작안함 CPU 120% 까지 올라가다가 그냥 낮아짐 웹페이지 응답도 없고 기다려봐도 회복안됨 웹소켓도 어느순간 응답없음 근데 이렇게 되기 직전까지만 해도 웹 브라우저에서 웹소켓 응답 매우 빠름 접속한 클라수가 적어서 전체 전파 처리 1ms 미만임

[2022-08-16T14:50:18.532Z INFO  ws_client] status: Status(0, 0, 0)
[2022-08-16T14:50:21.532Z INFO  ws_client] status: Status(18, 0, 9)
[2022-08-16T14:50:24.532Z INFO  ws_client] status: Status(98, 3, 19)
[2022-08-16T14:50:27.532Z INFO  ws_client] status: Status(241, 8, 29)
[2022-08-16T14:50:30.531Z INFO  ws_client] status: Status(682, 20, 39)
[2022-08-16T14:50:33.532Z INFO  ws_client] status: Status(1286, 32, 49)
[2022-08-16T14:50:36.531Z INFO  ws_client] status: Status(2299, 50, 59)
[2022-08-16T14:50:39.532Z INFO  ws_client] status: Status(3425, 67, 69)
[2022-08-16T14:50:42.532Z INFO  ws_client] status: Status(5536, 94, 79)
[2022-08-16T14:50:45.532Z INFO  ws_client] status: Status(7758, 120, 89)
[2022-08-16T14:50:48.532Z INFO  ws_client] status: Status(10984, 154, 99)
[2022-08-16T14:50:51.532Z INFO  ws_client] status: Status(14558, 188, 109)
[2022-08-16T14:50:54.532Z INFO  ws_client] status: Status(19737, 232, 119)
[2022-08-16T14:50:57.532Z INFO  ws_client] status: Status(25493, 278, 129)
[2022-08-16T14:51:00.532Z INFO  ws_client] status: Status(33307, 336, 139)
[2022-08-16T14:51:03.532Z INFO  ws_client] status: Status(42559, 399, 149)
[2022-08-16T14:51:06.532Z INFO  ws_client] status: Status(54007, 473, 159)
[2022-08-16T14:51:09.532Z INFO  ws_client] status: Status(66686, 550, 169)
[2022-08-16T14:51:12.532Z INFO  ws_client] status: Status(82207, 638, 179)
[2022-08-16T14:51:15.532Z INFO  ws_client] status: Status(99531, 731, 189)
[2022-08-16T14:51:18.532Z INFO  ws_client] status: Status(120138, 836, 199)
[2022-08-16T14:51:21.532Z INFO  ws_client] status: Status(141806, 942, 209)
[2022-08-16T14:51:24.532Z INFO  ws_client] status: Status(167090, 1059, 219)
[2022-08-16T14:51:27.532Z INFO  ws_client] status: Status(194887, 1183, 229)
[2022-08-16T14:51:30.532Z INFO  ws_client] status: Status(226261, 1316, 239)
[2022-08-16T14:51:33.532Z INFO  ws_client] status: Status(259955, 1454, 248)
[2022-08-16T14:51:36.531Z INFO  ws_client] status: Status(297553, 1601, 258)
[2022-08-16T14:51:39.532Z INFO  ws_client] status: Status(337941, 1754, 268)
[2022-08-16T14:51:42.532Z INFO  ws_client] status: Status(382874, 1918, 278)
[2022-08-16T14:51:45.532Z INFO  ws_client] status: Status(430580, 2086, 288)
[2022-08-16T14:51:48.532Z INFO  ws_client] status: Status(482301, 2262, 298)
[2022-08-16T14:51:51.532Z INFO  ws_client] status: Status(537900, 2445, 308)
[2022-08-16T14:51:54.532Z INFO  ws_client] status: Status(598147, 2637, 318)
[2022-08-16T14:51:57.532Z INFO  ws_client] status: Status(661923, 2834, 328)
[2022-08-16T14:52:00.532Z INFO  ws_client] status: Status(731663, 3043, 338)
[2022-08-16T14:52:03.532Z INFO  ws_client] status: Status(804520, 3255, 348)
[2022-08-16T14:52:06.532Z INFO  ws_client] status: Status(883015, 3476, 358)
[2022-08-16T14:52:09.532Z INFO  ws_client] status: Status(965901, 3703, 368)
[2022-08-16T14:52:12.532Z INFO  ws_client] status: Status(1054800, 3941, 378)
[2022-08-16T14:52:15.532Z INFO  ws_client] status: Status(1147614, 4183, 388)
[2022-08-16T14:52:18.532Z INFO  ws_client] status: Status(1245965, 4433, 398)
[2022-08-16T14:52:21.532Z INFO  ws_client] status: Status(1349618, 4690, 408)
[2022-08-16T14:52:24.532Z INFO  ws_client] status: Status(1461221, 4960, 418)
[2022-08-16T14:52:27.532Z INFO  ws_client] status: Status(1576367, 5232, 428)
[2022-08-16T14:52:30.532Z INFO  ws_client] status: Status(1697673, 5512, 438)
[2022-08-16T14:52:33.532Z INFO  ws_client] status: Status(1824855, 5799, 448)
[2022-08-16T14:52:36.532Z INFO  ws_client] status: Status(1960816, 6099, 458)
[2022-08-16T14:52:39.532Z INFO  ws_client] status: Status(2099773, 6399, 468)
[2022-08-16T14:52:42.532Z INFO  ws_client] status: Status(2205925, 6710, 478)
[2022-08-16T14:52:45.532Z INFO  ws_client] status: Status(2205925, 7026, 488)
[2022-08-16T14:52:48.531Z INFO  ws_client] status: Status(2205925, 7347, 497)
[2022-08-16T14:52:51.532Z INFO  ws_client] status: Status(2205925, 7664, 507)
[2022-08-16T14:52:54.531Z INFO  ws_client] status: Status(2205925, 7982, 517)
[2022-08-16T14:52:57.532Z INFO  ws_client] status: Status(2205925, 8298, 527)
[2022-08-16T14:53:00.532Z INFO  ws_client] status: Status(2205925, 8618, 537)
[2022-08-16T14:53:03.532Z INFO  ws_client] status: Status(2205925, 8936, 547)
[2022-08-16T14:53:06.532Z INFO  ws_client] status: Status(2205925, 9253, 557)
[2022-08-16T14:53:09.532Z INFO  ws_client] status: Status(2205925, 9569, 567)
[2022-08-16T14:53:12.532Z INFO  ws_client] status: Status(2205925, 9889, 577)
[2022-08-16T14:53:15.532Z INFO  ws_client] status: Status(2205925, 10208, 587)

server stuck 될때 서버 로그

2022-08-16T14:52:42.067198Z  INFO rust_chat_server: 레디스로 부터 받아서 전파 처리시간 996.549µs String("{\"o\":102,\"c\":\"-7074417638366484559 안녕 나는 3371201843159091406 이야\",\"r\":\"room_id\",\"n\":\"user_name\",\"i\":\"s-7809923759079676728\"}")
2022-08-16T14:52:42.068501Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-7814048473095066545 안녕 나는 2823023149792715994 이야"}
2022-08-16T14:52:42.068555Z  INFO rust_chat_server: 수신 처리 완료 처리시간 55.989µs "{\"o\":101, \"r\":\"room_id\", \"c\":\"-7814048473095066545 안녕 나는 2823023149792715994 이야\"}"
2022-08-16T14:52:42.068619Z DEBUG fred::multiplexer::commands: fred-I99rPFKfSr: Skip blocking multiplexer after sending PUBLISH    
2022-08-16T14:52:42.068663Z DEBUG fred::multiplexer::utils: fred-I99rPFKfSr: Writing command PUBLISH to 127.0.0.1:6379    
2022-08-16T14:52:42.069265Z DEBUG rust_chat_server: on_message 수신 String("{\"o\":102,\"c\":\"-7814048473095066545 안녕 나는 2823023149792715994 이야\",\"r\":\"room_id\",\"n\":\"user_name\",\"i\":\"s-1953090765452921048\"}") on channel zxc
2022-08-16T14:52:42.069515Z DEBUG rust_chat_server::protocol: SendTextRequest 성공 1 ws62fbaed77387744983878621 {"o":102,"c":"-7814048473095066545 안녕 나는 2823023149792715994 이야","r":"room_id","n":"user_name","i":"s-1953090765452921048"}
2022-08-16T14:52:42.069660Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"6590974506035844467 안녕 나는 -4876715158812685226 이야"}
2022-08-16T14:52:42.069744Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-3813453513051382170 안녕 나는 3489163036920971932 이야"}
2022-08-16T14:52:42.070197Z  INFO rust_chat_server: 레디스로 부터 받아서 전파 처리시간 939.766µs String("{\"o\":102,\"c\":\"-7814048473095066545 안녕 나는 2823023149792715994 이야\",\"r\":\"room_id\",\"n\":\"user_name\",\"i\":\"s-1953090765452921048\"}")
2022-08-16T14:52:42.070301Z  INFO rust_chat_server: 수신 처리 완료 처리시간 647.099µs "{\"o\":101, \"r\":\"room_id\", \"c\":\"6590974506035844467 안녕 나는 -4876715158812685226 이야\"}"
2022-08-16T14:52:42.070336Z  INFO rust_chat_server: 수신 처리 완료 처리시간 594.941µs "{\"o\":101, \"r\":\"room_id\", \"c\":\"-3813453513051382170 안녕 나는 3489163036920971932 이야\"}"
2022-08-16T14:52:42.070348Z DEBUG fred::multiplexer::commands: fred-I99rPFKfSr: Skip blocking multiplexer after sending PUBLISH    
2022-08-16T14:52:42.070378Z DEBUG fred::multiplexer::utils: fred-I99rPFKfSr: Writing command PUBLISH to 127.0.0.1:6379    
2022-08-16T14:52:42.070387Z DEBUG fred::multiplexer::commands: fred-I99rPFKfSr: Skip blocking multiplexer after sending PUBLISH    
2022-08-16T14:52:42.070422Z DEBUG fred::multiplexer::utils: fred-I99rPFKfSr: Writing command PUBLISH to 127.0.0.1:6379    
2022-08-16T14:52:42.071016Z DEBUG rust_chat_server: on_message 수신 String("{\"o\":102,\"c\":\"6590974506035844467 안녕 나는 -4876715158812685226 이야\",\"r\":\"room_id\",\"n\":\"user_name\",\"i\":\"s5692850217770495063\"}") on channel zxc
2022-08-16T14:52:42.071035Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"1568940647828849730 안녕 나는 619636243374918764 이야"}
2022-08-16T14:52:42.071253Z DEBUG rust_chat_server::protocol: SendTextRequest 성공 1 ws62fbaf1673877449838786f1 {"o":102,"c":"-3813453513051382170 안녕 나는 3489163036920971932 이야","r":"room_id","n":"user_name","i":"s8406686398779605144"}
2022-08-16T14:52:42.071286Z DEBUG rust_chat_server::protocol: SendTextRequest 성공 1 ws62fbaeab738774498387858f {"o":102,"c":"6590974506035844467 안녕 나는 -4876715158812685226 이야","r":"room_id","n":"user_name","i":"s5692850217770495063"}
2022-08-16T14:52:42.071826Z  INFO rust_chat_server: 레디스로 부터 받아서 전파 처리시간 815.826µs String("{\"o\":102,\"c\":\"6590974506035844467 안녕 나는 -4876715158812685226 이야\",\"r\":\"room_id\",\"n\":\"user_name\",\"i\":\"s5692850217770495063\"}")
2022-08-16T14:52:42.071885Z DEBUG rust_chat_server: on_message 수신 String("{\"o\":102,\"c\":\"-3813453513051382170 안녕 나는 3489163036920971932 이야\",\"r\":\"room_id\",\"n\":\"user_name\",\"i\":\"s8406686398779605144\"}") on channel zxc
2022-08-16T14:52:42.072645Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-3992030309895890110 안녕 나는 1956929992746875437 이야"}
2022-08-16T14:52:42.077054Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"8633732954028802645 안녕 나는 6965692817602668892 이야"}
2022-08-16T14:52:42.079576Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-203066992333318139 안녕 나는 -5586701451631185952 이야"}
2022-08-16T14:52:42.084992Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"1506661437632694690 안녕 나는 4945574265831678479 이야"}
2022-08-16T14:52:42.085010Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"5297382152278688791 안녕 나는 462871885483542483 이야"}
2022-08-16T14:52:42.092736Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"3132152986606531724 안녕 나는 5894376479214996794 이야"}
2022-08-16T14:52:42.093888Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-8738520541087444320 안녕 나는 7851824306485983069 이야"}
2022-08-16T14:52:42.099230Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-1006922171077632706 안녕 나는 7403525707166348912 이야"}
2022-08-16T14:52:42.106529Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-6169490932701215484 안녕 나는 -6094097474058922387 이야"}
2022-08-16T14:52:42.109446Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-6743062520588847014 안녕 나는 6456705516375240164 이야"}
2022-08-16T14:52:42.110630Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-270059997798689144 안녕 나는 -401978027732989695 이야"}
2022-08-16T14:52:42.111797Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"4912259392160574597 안녕 나는 -7808444331082195484 이야"}
2022-08-16T14:52:42.114056Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-3528867682750444335 안녕 나는 -73679279460005764 이야"}
2022-08-16T14:52:42.117457Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"7261818206820638077 안녕 나는 -267458101887098685 이야"}
2022-08-16T14:52:42.119445Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-1698246436182688309 안녕 나는 4956797619147479320 이야"}
2022-08-16T14:52:42.122673Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"282957458532003524 안녕 나는 2307360579022827276 이야"}
2022-08-16T14:52:42.124945Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"5344802343284009107 안녕 나는 -5893955232577470039 이야"}
2022-08-16T14:52:42.127279Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"8382922858393054819 안녕 나는 8733777309007207169 이야"}
2022-08-16T14:52:42.129470Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-2209476158345209234 안녕 나는 -3420621667103369605 이야"}
2022-08-16T14:52:42.139878Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-1520237330141590752 안녕 나는 2345498901787579472 이야"}
2022-08-16T14:52:42.139936Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-3088443309925456824 안녕 나는 7129881651501593499 이야"}
2022-08-16T14:52:42.147403Z DEBUG rust_chat_server: 수신 패킷 {"o":101, "r":"room_id", "c":"-8577837077146830134 안녕 나는 -2892606461542336435 이야"}

보다시피 아예 로그가 그냥 없음 cpu 사용률 낮아지고 io 성능도 안나오고 그냥 코드가 실행 안되는거 같음 deadlock 인가? 일단 redis 클라로 pubsub만 테스트 해봐야겠음 서버 띄워서 소켓에 전달은 안하고 그냥 로그만 찍게 해서 어캐되나 보고
계속 publish 하는 클라로 테스트 해봐야겠음

[doowonee]

뭔가 알거같은게 https://redis.io/docs/reference/optimization/benchmarks/ 보면 SET 명령을 초당 74239건 처리함 즉 ms 단위로는 74건 처리 한다는건데 앱 서버 로그 보면 publish 명령어를 클라가 몰릴때 ms에 20건 까지도 하는걸 볼수있음

수신은 ws의 요청 값을 검사하고 redis에 publish 하는데 이걸 자체적으로 mpsc 사용해서 버퍼링 처리하고 여러개의 전달 하는 채팅건을 리스트로 만들어서 publish 횟수를 줄이면 되지 않을까 생각함 이건 수신쪽도 바뀌는 거긴해

[doowonee]

e9511a3 에서 mpsc publish 버퍼링 적용했는데 150MB 까지는 간거 같음 그리고 CPU 사용률이 3배 정도 높아짐

[2022-08-18T08:28:42.346Z INFO  ws_client] status: Status(1137775, 5322, 355)
[2022-08-18T08:28:43.342Z INFO  ws_client] status: Status(1209954, 5538, 365)
[2022-08-18T08:28:44.340Z INFO  ws_client] status: Status(1289989, 5754, 375)
[2022-08-18T08:28:45.340Z INFO  ws_client] status: Status(1372372, 5971, 385)
[2022-08-18T08:28:46.339Z INFO  ws_client] status: Status(1457215, 6188, 395)
[2022-08-18T08:28:47.347Z INFO  ws_client] status: Status(1551000, 6404, 405)
[2022-08-18T08:28:48.339Z INFO  ws_client] status: Status(1633467, 6620, 414)
[2022-08-18T08:28:49.340Z INFO  ws_client] status: Status(1726120, 6837, 424)
[2022-08-18T08:28:50.344Z INFO  ws_client] status: Status(1821289, 7053, 434)
[2022-08-18T08:28:51.340Z INFO  ws_client] status: Status(1915403, 7270, 444)
[2022-08-18T08:28:52.345Z INFO  ws_client] status: Status(2017233, 7487, 454)
[2022-08-18T08:28:53.339Z INFO  ws_client] status: Status(2091966, 7704, 464)
[2022-08-18T08:28:54.339Z INFO  ws_client] status: Status(2220796, 7937, 474)
[2022-08-18T08:28:55.339Z INFO  ws_client] status: Status(2311154, 8170, 483)
[2022-08-18T08:28:56.339Z INFO  ws_client] status: Status(2425183, 8403, 493)
[2022-08-18T08:28:57.338Z INFO  ws_client] status: Status(2549209, 8632, 503)
[2022-08-18T08:28:58.339Z INFO  ws_client] status: Status(2645423, 8866, 513)
[2022-08-18T08:28:59.341Z INFO  ws_client] status: Status(2773909, 9097, 523)
[2022-08-18T08:29:00.339Z INFO  ws_client] status: Status(2901424, 9331, 533)
[2022-08-18T08:29:01.339Z INFO  ws_client] status: Status(3014572, 9565, 543)
[2022-08-18T08:29:02.339Z INFO  ws_client] status: Status(3161169, 9799, 553)
[2022-08-18T08:29:03.338Z INFO  ws_client] status: Status(3262772, 10033, 563)
[2022-08-18T08:29:04.339Z INFO  ws_client] status: Status(3421011, 10267, 572)
[2022-08-18T08:29:05.339Z INFO  ws_client] status: Status(3561328, 10499, 582)
[2022-08-18T08:29:06.339Z INFO  ws_client] status: Status(3670995, 10750, 592)
[2022-08-18T08:29:07.338Z INFO  ws_client] status: Status(3846236, 11003, 602)
[2022-08-18T08:29:08.339Z INFO  ws_client] status: Status(3973722, 11254, 612)
[2022-08-18T08:29:09.341Z INFO  ws_client] status: Status(4112803, 11502, 622)
[2022-08-18T08:29:10.339Z INFO  ws_client] status: Status(4152782, 11753, 632)
[2022-08-18T08:29:11.339Z INFO  ws_client] status: Status(4152782, 12002, 641)
[2022-08-18T08:29:12.339Z INFO  ws_client] status: Status(4152782, 12253, 651)
[2022-08-18T08:29:13.340Z INFO  ws_client] status: Status(4152782, 12504, 661)
[2022-08-18T08:29:14.339Z INFO  ws_client] status: Status(4152782, 12755, 671)
[2022-08-18T08:29:15.339Z INFO  ws_client] status: Status(4152782, 13006, 681)
[2022-08-18T08:29:16.339Z INFO  ws_client] status: Status(4152782, 13257, 691)
[2022-08-18T08:29:17.340Z INFO  ws_client] status: Status(4152782, 13508, 701)

위 정도 일떄 hang 문제 발생했고 앱서버 로그 보면

2022-08-18T08:29:09.419899Z DEBUG rust_chat_server: 최근 PUBLISH 시간 보다 3ms 미만으로 발송 안함 버퍼링
2022-08-18T08:29:09.419901Z DEBUG rust_chat_server: on_publish 수신 {"o":102,"c":"-8297428928190373905 안녕 나는 -720337510608935963 이야","r":"room_id","n":"user_name","i":"s-7433846035588707566"}
2022-08-18T08:29:09.419903Z DEBUG rust_chat_server: 최근 PUBLISH 시간 보다 3ms 미만으로 발송 안함 버퍼링
2022-08-18T08:29:09.419905Z DEBUG rust_chat_server: on_publish 수신 {"o":102,"c":"-1228903063112300375 안녕 나는 6250275457970261271 이야","r":"room_id","n":"user_name","i":"s-7433846035588707566"}
2022-08-18T08:29:09.419933Z DEBUG rust_chat_server: 최근 PUBLISH 시간 보다 3ms 미만으로 발송 안함 버퍼링
2022-08-18T08:29:09.419940Z DEBUG rust_chat_server: on_publish 수신 {"o":102,"c":"500798651312342882 안녕 나는 -482771992873217093 이야","r":"room_id","n":"user_name","i":"s-7433846035588707566"}
2022-08-18T08:29:09.419943Z DEBUG rust_chat_server: 최근 PUBLISH 시간 보다 3ms 미만으로 발송 안함 버퍼링
2022-08-18T08:29:09.419945Z DEBUG rust_chat_server: on_publish 수신 {"o":102,"c":"1066334455541077851 안녕 나는 -4959917321199784827 이야","r":"room_id","n":"user_name","i":"s5678359685271672143"}
2022-08-18T08:29:09.419948Z DEBUG rust_chat_server: 최근 PUBLISH 시간 보다 3ms 미만으로 발송 안함 버퍼링
2022-08-18T08:29:09.419950Z DEBUG rust_chat_server: on_publish 수신 {"o":102,"c":"7493544128119982822 안녕 나는 8345250478443199546 이야","r":"room_id","n":"user_name","i":"s-5544779349250144476"}
2022-08-18T08:29:09.419952Z DEBUG rust_chat_server: 최근 PUBLISH 시간 보다 3ms 미만으로 발송 안함 버퍼링
2022-08-18T08:29:09.419954Z DEBUG rust_chat_server: on_publish 수신 {"o":102,"c":"792711346926583615 안녕 나는 -8827067837222764009 이야","r":"room_id","n":"user_name","i":"s-5544779349250144476"}
2022-08-18T08:29:09.419956Z DEBUG rust_chat_server: 최근 PUBLISH 시간 보다 3ms 미만으로 발송 안함 버퍼링
2022-08-18T08:29:09.419998Z DEBUG fred::multiplexer::commands: fred-MsJSVovjJZ: Skip blocking multiplexer after sending PUBLISH    
2022-08-18T08:29:09.420035Z DEBUG fred::multiplexer::utils: fred-MsJSVovjJZ: Writing command PUBLISH to 127.0.0.1:6379    
2022-08-18T08:29:09.420678Z DEBUG rust_chat_server: redis publish 완료 2 [{"o":102,"c":"7675757824945916817 안녕 나는 4008364576285205805 이야","r":"room_id","n":"user_name","i":"s9046270716624540836"},{"o":102,"c":"2604753327695782668 안녕 나는 -8816115554792723855 이야","r":"room_id","n":"user_name","i":"s9046270716624540836"},{"o":102,"c":"-4393004010904786854 안녕 나는 -5894722253855103167 이야","r":"room_id","n":"user_name","i":"s9046270716624540836"},{"o":102,"c":"2400258033495498544 안녕 나는 -6248752321898794202 이야","r":"room_id","n":"user_name","i":"s9046270716624540836"},{"o":102,"c":"-3242932059317105298 안녕 나는 -8705827670899657479 이야","r":"room_id","n":"user_name","i":"s9046270716624540836"},{"o":102,"c":"-5181371525721781686 안녕 나는 2439232517635518629 이야","r":"room_id","n":"user_name","i":"s4320413617079939131"},{"o":102,"c":"-6843209096873418087 안녕 나는 -2531063079473858773 이야","r":"room_id","n":"user_name","i":"s4320413617079939131"},{"o":102,"c":"-1141324778996239655 안녕 나는 -7421201851976573775 이야","r":"room_id","n":"user_name","i":"s4320413617079939131"},{"o":102,"c":"2301872744448603141 안녕 나는 81362858291102431 이야","r":"room_id","n":"user_name","i":"s4320413617079939131"},{"o":102,"c":"2622629294227878459 안녕 나는 4779035902177255732 이야","r":"room_id","n":"user_name","i":"s4320413617079939131"},{"o":102,"c":"5735123002696950727 안녕 나는 -991977866025362467 이야","r":"room_id","n":"user_name","i":"s4320413617079939131"},{"o":102,"c":"-4382321334865616350 안녕 나는 8137084381798080642 이야","r":"room_id","n":"user_name","i":"s4320413617079939131"},{"o":102,"c":"656637193452666672 안녕 나는 -2949612702320409870 이야","r":"room_id","n":"user_name","i":"s-2742285238197320813"},{"o":102,"c":"2959737592403059896 안녕 나는 -5409110557858294862 이야","r":"room_id","n":"user_name","i":"s3787079638244660561"},{"o":102,"c":"2305612267905612073 안녕 나는 1503014394849469044 이야","r":"room_id","n":"user_name","i":"s2693845542437657858"},{"o":102,"c":"701398738394393348 안녕 나는 -6603767768534359863 이야","r":"room_id","n":"user_name","i":"s-1298166851562757115"},{"o":102,"c":"-7024808272124210232 안녕 나는 -5850139007458590364 이야","r":"room_id","n":"user_name","i":"s-1298166851562757115"},{"o":102,"c":"-870163602152705019 안녕 나는 -2788112544967063808 이야","r":"room_id","n":"user_name","i":"s-1298166851562757115"},{"o":102,"c":"-1291055357148369981 안녕 나는 2020430704749694530 이야","r":"room_id","n":"user_name","i":"s-1298166851562757115"},{"o":102,"c":"-2399255148263556185 안녕 나는 3470957973479153333 이야","r":"room_id","n":"user_name","i":"s-1298166851562757115"}]
2022-08-18T08:29:09.519991Z DEBUG hyper::proto::h1::io: parsed 5 headers
2022-08-18T08:29:09.520043Z DEBUG hyper::proto::h1::conn: incoming body is empty
2022-08-18T08:29:09.520135Z DEBUG hyper::proto::h1::io: flushed 166 bytes
2022-08-18T08:29:09.520174Z DEBUG rust_chat_server: ws62fdf8555447570fe51a0cb0 연결 수립

마지막 publish 가 몰려서 버퍼링되었고 redis에 publish 명령 날리고 서버 행됬음

[doowonee]

tokio_util fred 이 두개만 tracing 레벨로 찍고 나머지는 info로 앱 서버 로그를 봐야 할거 같고 redis 의존성 제거한 버전을 만들어서 다시 테스트 해봐야 할거 같음 한계치 파악은했음 3a1c81c 참고

[doowonee]

d8bc2a6 redis 제거하고 테스트 해봤는데 그래도 죽어 오 그럼 이번엔 axum 없이 해보자 이게 network io 한계에 도달하면 걍 서버가 죽나? 원래? 네트워크 OS 에서 어캐 처리하나 봐야되나ㅋㅋ

[doowonee]

https://channel.io/ko/blog/real-time-chat-server-2-redis-pub-sub 채널톡이 싱글 레디스 클러스터로 pub sub 사용했다가 nats 로 마이그레이션 하려고 하는듯 근데 nats는 클러스터로 세팅하고 pub sub 처리도 가능 하기 때문에 redis 보다 더 scalable 함 pub sub 용으로는 이게 더 적당 한거 같기도 하네