High latencies observed at the SDK entry point during Cloud operations

[NaveenSai1605]

ask: We are currently investigating high latencies observed at the SDK entry point during Cloud operations. Our measurements indicate that these latencies occur when performing Put() operations via the Azure SDK. There have been suggestions that the elevated latencies may be related to CPU utilization within the I/O stack, which appears to be actively engaged in Cloud Put() activities.

This observation seems counterintuitive because our understanding is that Put() calls should primarily wait for server-side acknowledgment of successful completion and therefore should not consume significant CPU resources on the client side. However, profiling consistently shows that I/O threads are on CPU, executing within the SDK, specifically in Put() calls, with the top of the stack being:

Azure::Core::Http::CurlConnection::SendBuffer()

Integration Details

SDK Version: azure-identity-1.5.1
SDK is using the C++ interfaces, as described in https://learn.microsoft.com/en-us/azure/storage/blobs/quickstart-blobs-c-plus-plus?tabs=managed-ide…

• The main entry point from Rubrik code into the SDK for putting a BlockBlok into a container, that we see as occupying the CPU is:

      - Azure::Response<Models::UploadBlockBlobResult> Upload(Azure::Core::IO::BodyStream& content, const UploadBlockBlobOptions& options = UploadBlockBlobOptions(), const Azure::Core::Context& context = Azure::Core::Context()) const
  

• Have attached a detailed thread stack of what it looks like from Upload(), all the way to Azure::Core::Http::CurlConnection::SendBuffer(), in case that is helpful, please see attached file,

thread_stack_bt_upload_sendbuffer.txt

• For completeness, the corresponding Get() interface we use is:
  - Azure::ResponseModels::DownloadBlobToResult DownloadTo(uint8_t* buffer, size_t bufferSize, const DownloadBlobToOptions& options = DownloadBlobToOptions(), const Azure::Core::Context& context = Azure::Core::Context()) const

Key Observations
Threads executing SendBuffer() are consistently in the ‘R’ state (as seen in top -H output), indicating active CPU usage.
This behavior raises questions about why these threads are spinning on CPU rather than being idle while awaiting server acknowledgment.
Request to SDK Team:

We seek clarity on the following points:
Root Cause Analysis:
Why are threads in SendBuffer() consuming CPU cycles during Put() operations? Is this expected behavior or indicative of an underlying issue?
Latency Attribution:
How can we measure and differentiate latencies within the SDK layer versus lower-level factors (e.g., network delays) that may contribute to overall high latencies observed at the SDK entry point?

Goal is to disambiguate SDK-level delays from external factors to better understand and optimize performance.

[NaveenSai1605]

Hello @azure-sdk-for-cpp

Could please provide any update?

Thank you!

[LarryOsterman]

Without symbols for libcurl it will be difficult to diagnose the problem - the SendBuffer call is a fairly thin wrapper around curl_easy_send - it loops sending the buffer until all the data is consumed.

Possible reasons for spending CPU time in this function:

• curl_easy_send returned a very low sentBytesPerRequest which causes the function to loop over very small buffers,
• the time is blocked in curl_easy_send and the SendBuffer call is being blamed for a delay in curl_easy_send.

Unfortunately, by default there aren't enter/exit trace points in the Azure SDK which would allow latency attribution.

[ashu-tripathi-rubrik]

@LarryOsterman I am from Rubrik Engineering and had looked at the issue at customer system. This part:

the time is blocked in curl_easy_send and the SendBuffer call is being blamed for a delay in curl_easy_send.

I think the description of what we are looking for could've been crisper... It is NOT that we are blaming curl_easy_send for "delay", rather the ask here is purely on the CPU usage of SDK here.

Azure network support team had looked at the overall e2e delay and pinpointed that the delay is happening because the client side (running the SDK code), is not able to ACK the incoming packets from server side as all the CPUs on the client are busy. Those missed ACKs then result in retransmissions from the server side, and e2e delays ballon. The busyness of the CPUs was then tracked down to the I/O threads inside the SDK, using up CPU. The thread stack of all such running I/O threads on the CPU was captured. they were all found to be attempting to send data to the server (SendBuffer() call) (see attached file thread_stack_bt_upload_sendbuffer.txt) for a full stack, if that helps.

So, to summarize: THIS issue should be purely about "CPU usage of the SDK stack", not about "e2e delay".

Does that help?

[LarryOsterman]

I'm at a loss to understand why we would be consuming excessive CPU time in the call to curl_easy_send, since we are simply blocked in synchronous call to curl_easy_send.

If curl_easy_send returns EAGAIN, the transport calls either WSAPoll or poll, but that blocks for 1 second while waiting for the socket to be ready.

azure-sdk-for-cpp/sdk/core/azure-core/src/http/curl/curl.cpp

Line 124 in ba9c199

int pollSocketUntilEventOrTimeout(

That should block the thread, avoiding excessive CPU consumption. It's possible that is not correctly blocking though.

[ashu-tripathi-rubrik]

@LarryOsterman Indeed, this is strange. Interesting point about 1 second wait if EAGAIN is returned. Any chance there is some sort of a race here that instead of that wait, the loop goes right back to poll again? maybe it is a different error code returned (Linux folks have known to be taking liberty with changing specific error codes in patches and other code refactors etc).

[ashu-tripathi-rubrik]

Yeah the code is fairly simple, if error && EINTR, wait another second. Otherwise, return on success OR failure.

consuming excessive CPU time in the call to curl_easy_send

Hmmm... another possibility is that it is NOT the poll, rather somehow the send is looping between pollSocketUntilEventOrTimeout() and its caller, we only see curl_easy_send() on the stack as the caller is all user level quick code, the syscall poll() is the one where the tight loop spends any time (even if very small) going up into kernel and back, and so it shows up in the thread stack.

Two possible subcases here:

1. poll() is indeed returning error for some socket condition (as noted earlier, TCP level retransmissions are indeed being seen here, although i am unsure what/how would that translate to poll error), which gets back to the caller. Presumably, there is some handling in the caller to handle that error return by either failing the send, re-creating the socket, or retrying. And somehow that handling has an issue that it keeps looping rapidly.

2. poll() is, actually, returning success. But somehow the amount of data being sent per socket write is very small and so we keep rapidly looping between send (which would just enqueue the data not really spend any time) and then poll. Not sure if there is some sort of logic in the code to decide how much data to send per poll, or is it always a fixed amount of data (assuming application has a bunch of data queued up into the buffer).

I know, a bit of hand wave here, looking for ideas.

[agabhin]

Hi team,

One possible reason for spinning I could think of is if curl_easy_send returns CURLE_OK but sends 0 bytes. In that case, this function will spin until it is able to send something. While usually, it must send CURLE_AGAIN it may send CURLE_OK but sends 0 bytes in some cases (SSL sockets - only ssl data was sent but no actual data). If that were to happen, it will def cause cpu spin. Can you please look at it from this angle?

CURLcode CurlConnection::SendBuffer(
    uint8_t const* buffer,
    size_t bufferSize,
    Context const& context)
{
  for (size_t sentBytesTotal = 0; sentBytesTotal < bufferSize;)
  {
    // check cancelation for each chunk of data.
    // Next loop is expected to be called at most 2 times:
    // The first time we call `curl_easy_send()`, if it return CURLE_AGAIN it would call
    // `pollSocketUntilEventOrTimeout` to wait for socket to be ready to write.
    // `pollSocketUntilEventOrTimeout` will then handle cancelation token.
    // If socket is not ready before the timeout, Exception is thrown.
    // When socket is ready, it calls curl_easy_send() again (second loop iteration). It is not
    // expected to return CURLE_AGAIN (since socket is ready), so, a chuck of data will be uploaded
    // and result will be CURLE_OK which breaks the loop. Also, getting other than CURLE_OK or
    // CURLE_AGAIN throws.
    context.ThrowIfCancelled();
    for (CURLcode sendResult = CURLE_AGAIN; sendResult == CURLE_AGAIN;)
    {
      size_t sentBytesPerRequest = 0;
      sendResult = curl_easy_send(
          m_handle, buffer + sentBytesTotal, bufferSize - sentBytesTotal, &sentBytesPerRequest);

      switch (sendResult)
      {
        case CURLE_OK: {
          sentBytesTotal += sentBytesPerRequest;
          break;
        }
        case CURLE_AGAIN: {
          // start polling operation with 1 min timeout
          auto pollUntilSocketIsReady = pollSocketUntilEventOrTimeout(
              context, m_curlSocket, PollSocketDirection::Write, 60000L);

          if (pollUntilSocketIsReady == 0)
          {
            throw TransportException("Timeout waiting for socket to upload.");
          }
          else if (pollUntilSocketIsReady < 0)
          { // negative value, error while polling
            throw TransportException("Error while polling for socket ready write");
          }

          // Ready to continue download.
          break;
        }
        default: {
          return sendResult;
        }
      }
    };
  }
#if defined(AZ_PLATFORM_WINDOWS)
  WinSocketSetBuffSize(m_curlSocket);
#endif
  return CURLE_OK;
}

This hypothesis is also supported by the stacktrace of spinning thread we see:

#0  0x00007f337b0a05f3 in __libc_sigaction () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007f337dc78a79 in ?? () from /lib/x86_64-linux-gnu/libcurl.so.4
:#2  0x00007f337dc81fb2 in curl_easy_send () from /lib/x86_64-linux-gnu/libcurl.so.4
#3  0x0000561e6ac98d55 in Azure::Core::Http::CurlConnection::SendBuffer(unsigned char const*, unsigned long, Azure::Core::Context const&) ()
#4  0x0000561e6ac9900a in Azure::Core::Http::CurlSession::UploadBody(Azure::Core::Context const&) ()
#5  0x0000561e6ac98470 in Azure::Core::Http::CurlSession::Perform(Azure::Core::Context const&) ()
#6  0x0000561e6ac97656 in Azure::Core::Http::CurlTransport::Send(Azure::Core::Http::Request&, Azure::Core::Context const&) ()
...```

[ashu-tripathi-rubrik]

Intriguing possibility indeed @agabhin , my possibility #2 was around this point

2. poll() is, actually, returning success. But somehow the amount of data being sent per socket write is very small

But yeah "0 bytes sent" would do that even better and quicker!

Thoughts @LarryOsterman ?

[LarryOsterman]

I would completely buy a 0 bytes sent being the cause of this problem. However if it is the cause, it might be interesting to understand why the TCP pipeline has been flow controlled (0 bytes sent will happen if the kernel can no longer accept any more bytes of data, which implies that the TCP connection has been flow controlled by the service).

It would certainly be possible to add a short (10ms or so) sleep if we receive a 0 byte send, and that might be an interesting experiment to run here.

[ashu-tripathi-rubrik]

0 bytes sent will happen if the kernel can no longer accept any more bytes of data, which implies that the TCP connection has been flow controlled by the service

Indeed. I think when TCP's send buffer is full, this might happen.

might be interesting to understand why the TCP pipeline has been flow controlled

As reported, we did see a bunch of retransmissions from the server side, which typically indicates packet loss somewhere in the network, but could also be because the client is "too busy" to process those packets and ack them, and therefore retransmissions. My understanding is that the packets coming from the server would also contain the ACK for the client side transmissions (the send()s) so as those packet losses happen, TCP (on the client side), would eventually exhausts its send window (ie: amount of unACKed data it has outstanding), and stop the application from sending more data. It seems plausible.

It would be really interesting if the reason for those retransmissions is not dropped packets, rather "client VM too busy". Because if so, this can become a "self sustaining loop". ie: A short burst of time where the client is too busy, a few packets are lost, send buffers get full, libcurl starts spinning on CPU, thereby making sure that client VM gets even busier, a loopty-loop ensues and the system tips over.... Wild, i know.. :-) But not entirely out of the realm of possibility!!

It would certainly be possible to add a short (10ms or so) sleep if we receive a 0 byte send, and that might be an interesting experiment to run here.

Sounds good. As of now, the code is not even specifically checking for this today. How do you propose we proceed next?

[ashu-tripathi-rubrik]

@LarryOsterman While you are thinking about this, wanted to see how this grabs you:

add a short (10ms or so) sleep

Network congestions, when they do develop, typically takes a little more time then that to settle back. The RTT between client/server is probably of the order of 100 msec in most cases, but i reckon you might have a better idea about that. But in general, when "retrying with a delay", the exponential backoff approach is the standard way, and seems to be time tested.

Assuming a starting delay value of 100 msec and "max" of 1 seconds. Psuedo code with exponential backoff:

delay = 100 msec:
for (CURLcode sendResult = CURLE_AGAIN; sendResult == CURLE_AGAIN;) {
sendResult = curl_easy_send(..., &sentBytesPerRequest);
if (sentBytesPerRequest == 0) {
sleep(delay);
delay = max(2*delay, 1000);
}
...
}

Just an idea. Not sure if it is too complex, but hope you would consider it. Looking forward to working with you on this.

[ashu-tripathi-rubrik]

And noting here for the record, had a offline email discussion with @NaveenSai1605 about making sure that all the data about network/storage stats, tcpdump packet captures and other things that the customer, Rubrik, Azure cloud storage support team, Azure networking support teams have gathered, with associated analysis (with nice charts and what have you, there was fair amount of effort on this before we got here), be added to this ticket for record keeping and reference. Thank you @NaveenSai1605 for that.