Slow application start (25 seconds?) over even localhost
When debugging an unrelated issue with waypipe
I noticed that each build/iteration takes quite a while to test as applications are quite slow to launch. I initially though it's a networking round-trip. But after checking against localhost
I noticed the issue still persists:
$ waypipe --debug ssh localhost es2gears_wayland
c2188362: 94.172641 [src/client.c:705] I'm a client listening on '/tmp/' / 'waypipe-client-2BWzSgyG.sock'
c2188362: 94.172652 [src/client.c:707] version: 0.8.6
c2188362: 94.172694 [src/client.c:752] A wayland compositor is available. Proceeding.
s2188367: 94.373937 [src/server.c:591] I'm a server connecting on /tmp x waypipe-server-2BWzSgyG.sock, running: nix-shell
s2188367: 94.373943 [src/server.c:594] version: 0.8.6
s2188367: 94.374191 [src/server.c:407] Connection token header: 00010980
s2188367: 99.698968 [src/server.c:516] New connection to server
c2188362: 99.699175 [src/client.c:664] New connection to client
s2191026: 99.699411 [src/mainloop.c:1180] Running main loop on application side
c2191029: 99.699703 [src/mainloop.c:1180] Running main loop on compositor side
s2191026: 99.699708 [src/mainloop.c:900] Read 0 new file descriptors, have 0 total now
s2191026: 99.699759 [src/mainloop.c:991] We are transferring a data buffer with 24 bytes
s2191026: 99.699777 [src/mainloop.c:1026] Channel message start (0 blobs, 0 bytes, 1 trailing, 0 tasks)
s2191026: 99.699807 [src/mainloop.c:856] Sent 28-byte message from application to channel; 28-bytes in flight
c2191029: 99.699899 [src/mainloop.c:339] Received WMSG_PROTOCOL with 24 bytes of messages
c2191029: 99.699909 [src/mainloop.c:568] Wrote to compositor, 24/24 bytes in chunk 24, 0/0 fds
c2191029: 99.699912 [src/mainloop.c:590] Write to the compositor succeeded
c2191029: 99.699961 [src/mainloop.c:900] Read 0 new file descriptors, have 0 total now
c2191029: 99.724237 [src/mainloop.c:991] We are transferring a data buffer with 1996 bytes
c2191029: 99.724248 [src/mainloop.c:1026] Channel message start (0 blobs, 0 bytes, 1 trailing, 0 tasks)
c2191029: 99.724402 [src/mainloop.c:856] Sent 2008-byte message from compositor to channel; 2008-bytes in flight
s2191026: 99.724463 [src/mainloop.c:282] Received WMSG_ACK_NBLOCKS: remote recvd 1
s2191026: 99.724500 [src/mainloop.c:339] Received WMSG_PROTOCOL with 1996 bytes of messages
s2191026: 99.750218 [src/mainloop.c:568] Wrote to application, 1996/1996 bytes in chunk 1996, 0/0 fds
s2191026: 99.750225 [src/mainloop.c:590] Write to the application succeeded
s2191026: 99.751275 [src/mainloop.c:900] Read 0 new file descriptors, have 0 total now
s2191026: 99.751285 [src/mainloop.c:991] We are transferring a data buffer with 96 bytes
s2191026: 99.751287 [src/mainloop.c:1026] Channel message start (0 blobs, 0 bytes, 1 trailing, 0 tasks)
s2191026: 99.751294 [src/mainloop.c:856] Sent 108-byte message from application to channel; 108-bytes in flight
c2191029: 99.751412 [src/mainloop.c:282] Received WMSG_ACK_NBLOCKS: remote recvd 1
c2191029: 99.751420 [src/mainloop.c:339] Received WMSG_PROTOCOL with 96 bytes of messages
c2191029: 99.751429 [src/mainloop.c:568] Wrote to compositor, 96/96 bytes in chunk 96, 0/0 fds
c2191029: 99.751431 [src/mainloop.c:590] Write to the compositor succeeded
c2191029: 99.751476 [src/mainloop.c:900] Read 0 new file descriptors, have 0 total now
c2191029: 99.751484 [src/mainloop.c:991] We are transferring a data buffer with 2028 bytes
c2191029: 99.751485 [src/mainloop.c:1026] Channel message start (0 blobs, 0 bytes, 1 trailing, 0 tasks)
c2191029: 99.751492 [src/mainloop.c:856] Sent 2040-byte message from compositor to channel; 2040-bytes in flight
s2191026: 99.751557 [src/mainloop.c:282] Received WMSG_ACK_NBLOCKS: remote recvd 2
s2191026: 99.751560 [src/mainloop.c:339] Received WMSG_PROTOCOL with 2028 bytes of messages
s2191026: 99.751569 [src/mainloop.c:568] Wrote to application, 2028/2028 bytes in chunk 2028, 0/0 fds
s2191026: 99.751570 [src/mainloop.c:590] Write to the application succeeded
s2191026: 99.751602 [src/mainloop.c:900] Read 0 new file descriptors, have 0 total now
s2191026: 99.751605 [src/mainloop.c:991] We are transferring a data buffer with 68 bytes
s2191026: 99.751606 [src/mainloop.c:1026] Channel message start (0 blobs, 0 bytes, 1 trailing, 0 tasks)
s2191026: 99.751610 [src/mainloop.c:856] Sent 80-byte message from application to channel; 80-bytes in flight
c2191029: 99.751686 [src/mainloop.c:282] Received WMSG_ACK_NBLOCKS: remote recvd 2
c2191029: 99.751690 [src/mainloop.c:339] Received WMSG_PROTOCOL with 68 bytes of messages
c2191029: 99.751697 [src/mainloop.c:568] Wrote to compositor, 68/68 bytes in chunk 68, 0/0 fds
c2191029: 99.751698 [src/mainloop.c:590] Write to the compositor succeeded
c2191029: 99.751729 [src/mainloop.c:900] Read 1 new file descriptors, have 1 total now
c2191029: 99.751734 [src/shadow.c:584] Creating new FDC_FILE shadow RID=-1 for local fd 12
c2191029: 99.751738 [src/shadow.c:601] Initial mmap for RID=-1 failed, trying private+readonly
c2191029: 99.751745 [src/parsing.c:487] Tagging message with 1 fds.
c2191029: 99.751747 [src/parsing.c:461] Dropping zwp_linux_dmabuf_feedback_v1.tranche_target_device, with 0 fds
c2191029: 99.751748 [src/parsing.c:461] Dropping zwp_linux_dmabuf_feedback_v1.tranche_flags, with 0 fds
c2191029: 99.751749 [src/parsing.c:461] Dropping zwp_linux_dmabuf_feedback_v1.tranche_formats, with 0 fds
c2191029: 99.751750 [src/parsing.c:461] Dropping zwp_linux_dmabuf_feedback_v1.tranche_done, with 0 fds
c2191029: 99.751764 [src/mainloop.c:991] We are transferring a data buffer with 188 bytes
c2191029: 99.751765 [src/mainloop.c:1026] Channel message start (1 blobs, 12 bytes, 2 trailing, 1 tasks)
c2191029: 99.751796 [src/shadow.c: 75] Destroying FDC_FILE RID=-1
c2191029: 99.751804 [src/mainloop.c:856] Sent 1640-byte message from compositor to channel; 1640-bytes in flight
s2191026: 99.751952 [src/mainloop.c:282] Received WMSG_ACK_NBLOCKS: remote recvd 3
s2191026: 99.751956 [src/mainloop.c:386] Received WMSG_OPEN_FILE for RID=-1 (len 12)
s2191026: 99.751958 [src/shadow.c:1471] Introducing new fd, remoteid=-1
s2191026: 99.751973 [src/mainloop.c:386] Received WMSG_BUFFER_DIFF for RID=-1 (len 1420)
s2191026: 99.751979 [src/mainloop.c:306] Received WMSG_INJECT_RIDS with 1 fds
s2191026: 99.751980 [src/mainloop.c:339] Received WMSG_PROTOCOL with 188 bytes of messages
s2191026: 99.751982 [src/parsing.c:377] Reading message tagged with 1 fds.
s2191026: 99.751984 [src/parsing.c:461] Dropping zwp_linux_dmabuf_feedback_v1.tranche_target_device, with 0 fds
s2191026: 99.751985 [src/parsing.c:461] Dropping zwp_linux_dmabuf_feedback_v1.tranche_flags, with 0 fds
s2191026: 99.751986 [src/parsing.c:461] Dropping zwp_linux_dmabuf_feedback_v1.tranche_formats, with 0 fds
s2191026: 99.751987 [src/parsing.c:461] Dropping zwp_linux_dmabuf_feedback_v1.tranche_done, with 0 fds
s2191026: 99.751990 [src/mainloop.c:131] Writing 1 fds to cmsg data
s2191026: 99.751996 [src/mainloop.c:568] Wrote to application, 188/188 bytes in chunk 188, 1/1 fds
s2191026: 99.751997 [src/shadow.c: 75] Destroying FDC_FILE RID=-1
s2191026: 99.752002 [src/mainloop.c:590] Write to the application succeeded
s2191026: 24.808432 [src/mainloop.c:900] Read 0 new file descriptors, have 0 total now
s2191026: 24.808542 [src/mainloop.c:991] We are transferring a data buffer with 68 bytes
s2191026: 24.808566 [src/mainloop.c:1026] Channel message start (0 blobs, 0 bytes, 1 trailing, 0 tasks)
s2191026: 24.808614 [src/mainloop.c:856] Sent 80-byte message from application to channel; 80-bytes in flight
There was a pause of 25 seconds before before es2gears_wayland
window opened and started.