First message sent via a new UCX connection is orders of magnitude slower than subsequent messages

[ghost]

I'm running UCX version

$ ./ucx_info -v
# Library version: 1.14.1
# Library path: /home/[...]/lib/libucs.so.0
# API headers version: 1.14.1
# Git branch 'v1.14.1', revision 04897a0
# Configured with: --disable-logging --disable-debug --disable-assertions --disable-params-check --prefix=/home/[...]

To measure transfer latency, I've used the ucx_perftest tool with the following configuration

$ ./ucx_perftest -c 0
Waiting for connection...
Accepted connection from [...]
+----------------------------------------------------------------------------------------------------------+
| API:          protocol layer                                                                             |
| Test:         am latency                                                                                 |
| Data layout:  (automatic)                                                                                |
| Send memory:  host                                                                                       |
| Recv memory:  host                                                                                       |
| Message size: 16384                                                                                      |
| AM header size: 0                                                                        |
+----------------------------------------------------------------------------------------------------------+

I've notices that, when setting up a new UCX connection, the first message sent has very poor latency compared to subsequent messages (of same size which use the same UCX connection).

Sending the first message can take something like 482.559 usec, while sending a fourth message of same size can take 4.053 usec.

The significant difference in latency between delivering the first and subsequent messages makes me think some special memory handling happens during the first transfer.

Is there a way to perform some extra UCX setup before the first message is sent, to decrease the latency of the first message and get it closer to the average message latency? I believe my experiments are using rc_verbs as transport.

To see this behavior, I've ran the following tests:

1. Measure the latency for just one iteration with no warm-up iterations

$ ./ucx_perftest 192.168.230.183 -c 0 -t ucp_am_lat -s 16384 -n 1 -w 0
+--------------+--------------+------------------------------+---------------------+-----------------------+
|              |              |        latency (usec)        |   bandwidth (MB/s)  |  message rate (msg/s) |
+--------------+--------------+----------+---------+---------+----------+----------+-----------+-----------+
|    Stage     | # iterations | 50.0%ile | average | overall |  average |  overall |  average  |  overall  |
+--------------+--------------+----------+---------+---------+----------+----------+-----------+-----------+
Final:                     1    480.928   482.559   482.559       32.38      32.38        2072        2072

2. Measure the latency for just one iteration with one warm-up iteration

$ ./ucx_perftest 192.168.230.183 -c 0 -t ucp_am_lat -s 16384 -n 1 -w 1
+--------------+--------------+------------------------------+---------------------+-----------------------+
|              |              |        latency (usec)        |   bandwidth (MB/s)  |  message rate (msg/s) |
+--------------+--------------+----------+---------+---------+----------+----------+-----------+-----------+
|    Stage     | # iterations | 50.0%ile | average | overall |  average |  overall |  average  |  overall  |
+--------------+--------------+----------+---------+---------+----------+----------+-----------+-----------+
Final:                     1      8.854    10.014    10.014     1560.38    1560.38       99864       99864

3. Measure the latency for just one iteration with two warm-up iterations

$ ./ucx_perftest 192.168.230.183 -c 0 -t ucp_am_lat -s 16384 -n 1 -w 2
+--------------+--------------+------------------------------+---------------------+-----------------------+
|              |              |        latency (usec)        |   bandwidth (MB/s)  |  message rate (msg/s) |
+--------------+--------------+----------+---------+---------+----------+----------+-----------+-----------+
|    Stage     | # iterations | 50.0%ile | average | overall |  average |  overall |  average  |  overall  |
+--------------+--------------+----------+---------+---------+----------+----------+-----------+-----------+
Final:                     1      2.863     4.530     4.530     3449.26    3449.26      220753      220753

4. Measure the latency for just one iteration with three warm-up iterations

$ ./ucx_perftest 192.168.230.183 -c 0 -t ucp_am_lat -s 16384 -n 1 -w 3
+--------------+--------------+------------------------------+---------------------+-----------------------+
|              |              |        latency (usec)        |   bandwidth (MB/s)  |  message rate (msg/s) |
+--------------+--------------+----------+---------+---------+----------+----------+-----------+-----------+
|    Stage     | # iterations | 50.0%ile | average | overall |  average |  overall |  average  |  overall  |
+--------------+--------------+----------+---------+---------+----------+----------+-----------+-----------+
Final:                     1      1.660     4.053     4.053     3855.06    3855.06      246724      246724

[ghost]

Any ideas on how to mitigate first message poor latency?