Open doowonee opened 2 years ago
뭔가 알거같은게 https://redis.io/docs/reference/optimization/benchmarks/ 보면 SET
명령을 초당 74239건 처리함 즉 ms 단위로는 74건 처리 한다는건데 앱 서버 로그 보면 publish 명령어를 클라가 몰릴때 ms에 20건 까지도 하는걸 볼수있음
수신은 ws의 요청 값을 검사하고 redis에 publish 하는데 이걸 자체적으로 mpsc 사용해서 버퍼링 처리하고 여러개의 전달 하는 채팅건을 리스트로 만들어서 publish 횟수를 줄이면 되지 않을까 생각함 이건 수신쪽도 바뀌는 거긴해
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 명령 날리고 서버 행됬음
tokio_util
fred
이 두개만 tracing
레벨로 찍고 나머지는 info
로 앱 서버 로그를 봐야 할거 같고 redis 의존성 제거한 버전을 만들어서 다시 테스트 해봐야 할거 같음 한계치 파악은했음 3a1c81c 참고
d8bc2a6 redis 제거하고 테스트 해봤는데 그래도 죽어 오 그럼 이번엔 axum 없이 해보자 이게 network io 한계에 도달하면 걍 서버가 죽나? 원래? 네트워크 OS 에서 어캐 처리하나 봐야되나ㅋㅋ
https://channel.io/ko/blog/real-time-chat-server-2-redis-pub-sub 채널톡이 싱글 레디스 클러스터로 pub sub 사용했다가 nats 로 마이그레이션 하려고 하는듯 근데 nats는 클러스터로 세팅하고 pub sub 처리도 가능 하기 때문에 redis 보다 더 scalable 함 pub sub 용으로는 이게 더 적당 한거 같기도 하네
여러명의 유저 적은 채팅
이상없음 50MB 까지 갔도 웹 서버 안죽음 커넥션 다끊어도 ㄱㅊ음 웹페이지 응답도 빠르고 웹 브라우저에서 ws 응답도 빠름 4천명의 유저 채팅 전파 10ms 이내로 끝남
적은 유저 많은 채팅
초당 300개 정도의 채팅은 문제없이 처리함 50MB 정도임 근데 그이상 하면 어느순간 서버 동작안함 CPU 120% 까지 올라가다가 그냥 낮아짐 웹페이지 응답도 없고 기다려봐도 회복안됨 웹소켓도 어느순간 응답없음 근데 이렇게 되기 직전까지만 해도 웹 브라우저에서 웹소켓 응답 매우 빠름 접속한 클라수가 적어서 전체 전파 처리 1ms 미만임
server stuck 될때 서버 로그
보다시피 아예 로그가 그냥 없음 cpu 사용률 낮아지고 io 성능도 안나오고 그냥 코드가 실행 안되는거 같음 deadlock 인가? 일단 redis 클라로 pubsub만 테스트 해봐야겠음 서버 띄워서 소켓에 전달은 안하고 그냥 로그만 찍게 해서 어캐되나 보고 계속 publish 하는 클라로 테스트 해봐야겠음