Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

WebSocket loop hangs with 100% CPU usage (with chrome) #382

Open
acieroid opened this issue Jan 19, 2025 · 1 comment
Open

WebSocket loop hangs with 100% CPU usage (with chrome) #382

acieroid opened this issue Jan 19, 2025 · 1 comment

Comments

@acieroid
Copy link
Contributor

Hi!

Consider the following example, adapted from k-websocket. The main change is using a loop in the websocket handler to continuously receive messages:

let home =
  <html>
  <body>
    <script>

    var socket = new WebSocket("ws://" + window.location.host + "/websocket");

    socket.onopen = function () {
      socket.send("Hello?");
    };

    socket.onmessage = function (e) {
        console.log(e.data)
    };

    </script>
  </body>
  </html>

let () =
  Dream.run ~port:8081
  @@ Dream.logger
  @@ Dream.router [

    Dream.get "/"
      (fun _ ->
        Dream.html home);

    Dream.get "/websocket"
      (fun _ ->
        Dream.websocket (fun websocket ->
            let rec loop = fun () ->
              match%lwt Dream.receive websocket with
              | Some x ->
                let%lwt () = Dream.send websocket x in
                loop ()
              | None ->
                Lwt.return ()
            in
            loop ()

          ));

  ]

Opening up localhost:8081 on chromium (see logs below), and refreshing the page multiple times makes the dream server eventually hang; everytime. It seems that it detects that the connection was closed when the page was refreshed, but never got to receiving the new request to /websocket.

This is what the logs contain eventually. Here, it hangs after one refresh, but it can take up to 20 refreshes to hang:

19.01.25 01:01:43.731                       Running at http://localhost:8081
19.01.25 01:01:43.731                       Type Ctrl+C to stop
19.01.25 01:01:48.511    dream.logger  INFO REQ 1 GET / ::1:53282 fd 7 Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/122.0.0.0 Safari/537.36
19.01.25 01:01:48.512    dream.logger  INFO REQ 1 200 in 708 μs
19.01.25 01:01:48.567    dream.logger  INFO REQ 2 GET /websocket ::1:53298 fd 8 Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/122.0.0.0 Safari/537.36
19.01.25 01:01:48.567    dream.logger  INFO REQ 2 101 in 185 μs
19.01.25 01:01:48.571                       REQ 2 incoming message
19.01.25 01:01:48.571                       REQ 2 looping
19.01.25 01:01:49.715    dream.logger  INFO REQ 3 GET / ::1:53282 fd 7 Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/122.0.0.0 Safari/537.36
19.01.25 01:01:49.716    dream.logger  INFO REQ 3 200 in 161 μs
19.01.25 01:01:49.726                       REQ 2 closed
^C

Looking at the process manager, we see that the dream server uses 100% CPU. Some investigation with perf shows that Lwt.catch is the function where most of the time is spent

$ perf record --call-graph dwarf ./_build/default/example/k-websocket/websocket.exe
$ perf report > perf.txt
$ head -100 perf.txt
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 44K of event 'cycles:P'
# Event count (approx.): 33492007139
#
# Children      Self  Command        Shared Object         Symbol
# ........  ........  .............  ....................  .........................................................
#
    64.56%     6.27%  websocket.exe  websocket.exe         [.] Lwt.catch_1489
            |
            |--58.30%--Lwt.catch_1489
            |          |
            |          |--41.42%--Gluten_lwt.write_loop_step_756
            |          |          |
            |          |          |--16.55%--Lwt.catch_1489
            |          |          |          |
            |          |          |          |--15.19%--Faraday_lwt_unix.fun_1059
            |          |          |          |          |
            |          |          |          |          |--10.09%--Lwt_unix.writev_1943
            |          |          |          |          |          |
            |          |          |          |          |           --8.24%--Lwt_unix.check_io_vectors_1923
            |          |          |          |          |                     |
            |          |          |          |          |                     |--3.48%--Lwt_unix.flatten_1894
            |          |          |          |          |                     |          |
            |          |          |          |          |                     |          |--1.29%--Stdlib.List.rev_append_308
            |          |          |          |          |                     |          |
            |          |          |          |          |                     |           --1.08%--caml_modify
            |          |          |          |          |                     |
            |          |          |          |          |                      --2.80%--Stdlib.List.iter_507
            |          |          |          |          |                                |
            |          |          |          |          |                                 --0.94%--Lwt_unix.check_1915
            |          |          |          |          |
            |          |          |          |          |--1.89%--Lwt.bind_1363
            |          |          |          |          |
            |          |          |          |          |--1.17%--Lwt_unix.fun_4307
            |          |          |          |          |
            |          |          |          |           --1.09%--Lwt_unix.wrap_syscall_1427
            |          |          |          |                     |
            |          |          |          |                      --0.76%--Lwt_unix.check_descriptor_1323
            |          |          |          |
            |          |          |          |--0.68%--Lwt.fail_1216
            |          |          |          |
            |          |          |           --0.63%--Lwt.underlying_655
            |          |          |
            |          |          |--8.61%--Httpun_ws.Wsd.next_820
            |          |          |          |
            |          |          |           --7.04%--Faraday.operation_1069
            |          |          |                     |
            |          |          |                     |--2.80%--Faraday.map_to_list_408
            |          |          |                     |
            |          |          |                     |--1.61%--Faraday.has_pending_output_1043
            |          |          |                     |
            |          |          |                      --0.56%--Faraday.flush_buffer_717
            |          |          |
            |          |          |--7.01%--Faraday_lwt_unix.writev_of_fd_367
            |          |          |          |
            |          |          |           --4.53%--Stdlib.List.iter_507
            |          |          |                     |
            |          |          |                     |--1.34%--Lwt_unix.append_1878
            |          |          |                     |
            |          |          |                     |--1.06%--Lwt_unix.append_bigarray_1888
            |          |          |                     |
            |          |          |                      --0.55%--Faraday_lwt_unix.fun_1056
            |          |          |
            |          |          |--1.96%--Faraday_lwt_unix.fun_1072
            |          |          |
            |          |          |--1.03%--Httpun_ws.Server_connection.next_write_operation_1191
            |          |          |
            |          |          |--0.87%--Gluten.next_write_operation_482
            |          |          |
            |          |          |--0.65%--Lwt.return_1210
            |          |          |
            |          |          |--0.62%--Lwt.run_callback_or_defer_it_inner_3123
            |          |          |
            |          |           --0.55%--Lwt.fun_3421
            |          |
            |          |--11.84%--Gluten_lwt.fun_1326
            |          |          |
            |          |          |--3.97%--caml_apply2
            |          |          |          |
            |          |          |          |--1.67%--Gluten.report_write_result_500
            |          |          |          |
            |          |          |           --0.76%--caml_curry2
            |          |          |
            |          |          |--3.08%--Httpun_ws.Wsd.wakeup_434
            |          |          |          |
            |          |          |           --2.56%--caml_modify
            |          |          |                     |
            |          |          |                      --0.87%--caml_darken
            |          |          |                                |
            |          |          |                                 --0.57%--caml_page_table_lookup
            |          |          |
            |          |          |--2.06%--Httpun_ws.Wsd.close_792
            |          |          |          |
            |          |          |           --0.77%--Faraday.flush_buffer_717
            |          |          |
            |          |          |--0.61%--Httpun_ws.Server_connection.report_write_result_1196

I haven't been able to reproduce it with Firefox, with 50+ refreshes.
Trying with requests from chrome and firefox at the same time makes it hang less on chrome it seems, but I don't have anything conclusive there.

Extra info if it can be helful:

$ ocaml --version
The OCaml toplevel, version 4.14.2
$ opam list | grep dream
dream                       1.0.0~alpha7 Tidy, feature-complete Web framework
dream-httpaf                1.0.0~alpha3 Internal: shared http/af stack for Dream (server) and Hyper (client)
dream-pure                  1.0.0~alpha2 Internal: shared HTTP types for Dream (server) and Hyper (client)
$ uname -a
Linux localhost 6.11.10-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.11.10-1 (2024-11-23) x86_64 GNU/Linux
@eWert-Online
Copy link

This happens to me as well.
In my tests, it happened in every browser. So I don't think chrome has anything to do with it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@acieroid @eWert-Online