ignore TRY_Q_BLOCK with reliable protocols

[mkicherer]

Hello,

my application uses COAPS with TRY_Q_BLOCK enabled for regular communication. For (very) large transfers, I want to open a separate TCP-based session to benefit from TCP's superior performance under packet loss. However, when using TCP in a Q-BLOCK-enabled context, coap_io_process blocks up to 30 seconds in my case before the transfer really starts. To avoid opening a separate context and as Q-Block is meant for unreliable protocols only anyways, this commit removes TRY_Q_BLOCK for sessions with reliable protocols.

Thank you!

[mrdeep1]

I think we need to understand the 30 second delay here, as reliable transports (i.e. TCP) are supported by RFC9177. See RFC9177 Appendix B.

It is possible that the delay could be the server looking up .well-known/core which is used in the 'Does the server support Q-Block' probe.

It may be that we need a way of enabling / disabling Q-Block on a per session basis.

[mkicherer]

As the regular COAPS session connects without delay I guess this should not be caused by the server side.

I interrupted my client during the delay and gdb showed this state:

#0  0x00007ffff5f05ce3 in coap_session_delay_pdu (session=0x4ae5e30, pdu=0x8cae8c0, node=0x8caf380) at /home/user/libcoap/src/coap_session.c:837
#1  0x00007ffff5eddb85 in coap_send_pdu (session=0x4ae5e30, pdu=0x8cae8c0, node=0x0) at /home/user/libcoap/src/coap_net.c:1276
#2  0x00007ffff5ee079f in coap_send_internal (session=0x4ae5e30, pdu=0x8cae8c0, request_pdu=0x0) at /home/user/libcoap/src/coap_net.c:2176
#3  0x00007ffff5ec813d in coap_send_q_blocks (session=0x4ae5e30, lg_xmit=0x20dd630, block=..., pdu=0x4ade860, send_pdu=COAP_SEND_INC_PDU) at /home/user/libcoap/src/coap_block.c:2324
#4  0x00007ffff5ec8c41 in coap_send_q_block1 (session=0x4ae5e30, block=..., request=0x4ade860, send_request=COAP_SEND_INC_PDU) at /home/user/libcoap/src/coap_block.c:2559
#5  0x00007ffff5edf97d in coap_send_lkd (session=0x4ae5e30, pdu=0x4ade860) at /home/user/libcoap/src/coap_net.c:1899
#6  0x00007ffff5ed9452 in coap_reset_doing_first (session=0x4ae5e30) at /home/user/libcoap/src/coap_io.c:326
#7  0x00007ffff5f06237 in coap_session_connected (session=0x4ae5e30) at /home/user/libcoap/src/coap_session.c:955
#8  0x00007ffff5ee6ab2 in handle_response (context=0x182b670, session=0x4ae5e30, sent=0x0, rcvd=0x4afab70) at /home/user/libcoap/src/coap_net.c:4458
#9  0x00007ffff5ee8993 in coap_dispatch (context=0x182b670, session=0x4ae5e30, pdu=0x4afab70) at /home/user/libcoap/src/coap_net.c:5058
#10 0x00007ffff5ee1dbf in coap_read_session (ctx=0x182b670, session=0x4ae5e30, now=435349) at /home/user/libcoap/src/coap_net.c:2699
#11 0x00007ffff5ee298c in coap_io_do_epoll_lkd (ctx=0x182b670, events=0x7fffffffcc50, nevents=1) at /home/user/libcoap/src/coap_net.c:2996
#12 0x00007ffff5edb1fe in coap_io_process_with_fds_lkd (ctx=0x182b670, timeout_ms=4294967295, enfds=0, ereadfds=0x0, ewritefds=0x0, eexceptfds=0x0) at /home/user/libcoap/src/coap_io_posix.c:494
#13 0x00007ffff5edaf42 in coap_io_process_lkd (ctx=0x182b670, timeout_ms=4294967295) at /home/user/libcoap/src/coap_io_posix.c:147
#14 0x00007ffff5edaef7 in coap_io_process (ctx=0x182b670, timeout_ms=4294967295) at /home/user/libcoap/src/coap_io_posix.c:140

AI concluded: "The backtrace identifies the root cause: the upload session is entering  coap_send_q_block1()  and bulk-queuing Q-Block packets during the CSM callback." I did not verify this yet.

[mrdeep1]

Certainly there needs to be a CSM exchange at the start of a reliable session, there is a delay of 5 seconds if this does not happen.

Using coap+tcp:// works for me with no delay.

$ examples/coap-client -v7 -m put -e aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa coap+tcp://127.0.0.1/example_data -L7 -b 16
Sep 01 15:16:25.652  1 DEBG ***0.0.0.0:0 <-> 127.0.0.1:5683 TCP : session 0x519000000080: created outgoing session
Sep 01 15:16:25.652  1 DEBG ***EVENT: COAP_EVENT_TCP_CONNECTED
Sep 01 15:16:25.652  1 DEBG ***127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : sending CSM
Sep 01 15:16:25.652  1 DEBG *  127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : netif: sent    7 bytes
v:Reliable c:CSM {} [ Max-Message-Size:8388864, Block-Wise-Transfer: ]
Sep 01 15:16:25.652  1 DEBG *  127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : netif: read    7 bytes
v:Reliable c:CSM {} [ Max-Message-Size:8388864, Block-Wise-Transfer: ]
Sep 01 15:16:25.652  1 DEBG ***127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : session connected
Sep 01 15:16:25.652  1 DEBG ***EVENT: COAP_EVENT_SESSION_CONNECTED
Sep 01 15:16:25.652  1 DEBG PDU presented by app.
v:1 t:CON c:PUT i:0000 {} [ Uri-Path:example_data, Q-Block1:0/M/16 ] :: 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa'
Sep 01 15:16:25.653  1 DEBG ** 127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : lg_xmit 0x511000000900 initialized
Sep 01 15:16:25.653  1 DEBG timeout is set to 90 seconds
Sep 01 15:16:25.653  1 DEBG sending CoAP request:
Sep 01 15:16:25.653  1 DEBG Testing for Q-Block support
Sep 01 15:16:25.653  1 DEBG *  127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : netif: sent   23 bytes
v:Reliable c:GET {02} [ Uri-Path:.well-known, Uri-Path:core, Q-Block2:0/_/16 ]
v:Reliable c:PUT {} [ Uri-Path:example_data, Q-Block1:0/M/16, Size1:83, Request-Tag:0xa58464f6 ] :: 'aaaaaaaaaaaaaaaa'
Sep 01 15:16:25.653  1 DEBG ** 127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : mid=0x0000: queued
Sep 01 15:16:25.653  1 DEBG *  127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : netif: read   31 bytes
v:Reliable c:2.05 {02} [ ETag:0xfeacb4fa, Content-Format:application/link-format, Q-Block2:0/M/16 ] :: '</>;title="Gener'
Sep 01 15:16:25.653  1 DEBG Q-Block support available
Sep 01 15:16:25.653  1 DEBG ** 127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : mid=0x0000: released
Sep 01 15:16:25.653  1 DEBG ** 127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : lg_crcv 0x511000000a40 initialized - stateless token xxxxx00000000003
Sep 01 15:16:25.653  1 DEBG *  127.0.0.1:41392 <-> 127.0.0.1:5683 TCP : netif: sent   44 bytes
v:Reliable c:PUT {} [ Uri-Path:example_data, Q-Block1:0/M/16, Size1:83, Request-Tag:0xa58464f6 ] :: 'aaaaaaaaaaaaaaaa'
Sep 01 15:16:25.653  1 DEBG Q-Block: First block 1

[mkicherer]

If the AI is right, this may only be a problem with large payloads? But I will try to investigate this more closely tomorrow. I have to leave now. Thank you so far!

[mrdeep1]

For a 50M file with no losses and #2120

$ ls -l tags
-rw-rw-r-- 1 xxx xxx 51203254 Aug 31 18:26 tags
$ time examples/coap-client -m put -f tags -x  coap+tcp://127.0.0.1/example_data -L7

real    0m10.083s
user    0m9.088s
sys     0m0.273s

[mrdeep1]

Perhaps we need to add COAP_BLOCK_TRY_Q_BLOCK_UDP as an alternative to COAP_BLOCK_TRY_Q_BLOCK which only tries Q-Block for non-reliable protocols.

[mkicherer]

I reproduced this problem also with coap-client. I pushed a new commit that fixes the problem for me.

Without the patch, AI identified the "send" part as cause for the long delay (using custom instrumentation):

libcoap timing 47854 ms: coap_send_q_blocks end session=0x817f480 duration=33654 ms delayqueue=0->77789 sent_blocks=77789
libcoap timing: coap_send_q_blocks detail session=0x817f480 next_pdu=184 ms payload=24 ms send=33434 ms
libcoap timing 47855 ms: coap_send_q_block1 end session=0x817f480 duration=33655 ms delayqueue=0->77789 sent_blocks=0
libcoap timing 47856 ms: coap_io_process end ctx=0x71d51a0 result=33656 duration=33656 ms
libcoapy: coap_io_process took 33.657 s

It suggested to replace the LL_APPEND with an approach using a tail pointer as, in my case, the list is eventually over 77000 elements long and it repeatedly appended elements. Maybe this does not happen on localhost and without TLS. With the patch, the delay is gone:

libcoap timing 41354 ms: coap_io_process start ctx=0x28dfdde0 timeout=4294967295
libcoap timing 41354 ms: coap_send_q_block1 start session=0x28eddcb0 block=0 delayqueue=0
libcoap timing 41354 ms: coap_send_q_blocks start session=0x28eddcb0 block=0 delayqueue=0
libcoap timing 41465 ms: coap_send_q_blocks end session=0x28eddcb0 duration=111 ms delayqueue=0->77789 sent_blocks=77789
libcoap timing: coap_send_q_blocks detail session=0x28eddcb0 next_pdu=86 ms payload=7 ms send=8 ms
libcoap timing 41470 ms: coap_send_q_block1 end session=0x28eddcb0 duration=116 ms delayqueue=0->77789 sent_blocks=0
libcoap timing 41474 ms: coap_io_process end ctx=0x28dfdde0 result=120 duration=120 ms
libcoapy: coap_io_process took 0.120 s 

[mrdeep1]

This make sense now - thanks for researching into it and coming up with a fix. Scanning long chains is not ideal.......

I would like to run a full regression test at my end (which takes hours) to check nothing has been introduced.

[mrdeep1]

The most significant performance change (large magnitudes) I have found has been to use -X 1140 option to the client and server. This disables use of BERT removing much time in building the larger TCP based PDUs. Testing done on a local connection with coaps+tcp://.

Use of -L 7 option on both ends halves the transmission time which I was expecting (but not as much) as each block is not individually answered.

I have tried doing a DL_ (double linked) version alternative fix to your tail change (which makes the code logic cleaner and more obvious), but it is a few percent slower - presumably from the maintenance of the prev pointer.