time_starttransfer reported wrong timestamp

[JazJas]

I did this

According to the man page below, the server response time can be: time_starttransfer - time_starttransfer

time_starttransfer:　The time, in seconds, it took from the start until the first byte was just about to be transferred. This includes time_pretransfer and also the time the server needed to calculate the result.

However, curl (all versions) actually set the time_starttransfer incorrectly.

I used curl to send a large text file (134M) as a payload of a POST request to a HTTP server using the following syntax:
curl -s -w "%{time_pretransfer}\n%{time_starttransfer}\n" -o /dev/null --data-binary @file.txt --header @$headers_file $server_url --insecure

At the same time, tcpdump was used to capture all network packets.

When the curl command finished, I got:

time_pretransfer: 0.017484
time_starttransfer: 1.018670

However, when analyzing the captured packets, Time 0.017484 is roughly the point when the client sent the first packet of the request (ie Packet 4) and Time 1.018670 is when the client started sending the large post payload (ie Packet 6).
An in fact, the entire POST request is sent over the wire completely at Time 1.156250 (ie Packet 175), and the first packet of the response from the server is at Time 3.041776 (Packet 184).

    1   0.000000 192.168.46.132 → 192.168.70.34 TCP 80 59664 → 80 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM TSval=3381780598 TSecr=0 WS=128
    2   0.017261 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [SYN, ACK] Seq=0 Ack=1 Win=64240 Len=0 MSS=1460
    3   0.017298 192.168.46.132 → 192.168.70.34 TCP 60 59664 → 80 [ACK] Seq=1 Ack=1 Win=64240 Len=0
    4   0.017377 192.168.46.132 → 192.168.70.34 TCP 848 POST / HTTP/1.1  [TCP segment of a reassembled PDU]
    5   0.017506 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=789 Win=64240 Len=0
    6   1.018656 192.168.46.132 → 192.168.70.34 HTTP 7360 POST / HTTP/1.1  (application/x-www-form-urlencoded)Continuation
    7   1.018717 192.168.46.132 → 192.168.70.34 HTTP 7360 Continuation
    8   1.018914 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=2249 Win=64240 Len=0
    9   1.018914 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=3709 Win=64240 Len=0
   10   1.018914 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=5169 Win=64240 Len=0
   11   1.018915 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=6629 Win=64240 Len=0
   12   1.018915 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=8089 Win=64240 Len=0
   13   1.018915 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=9549 Win=64240 Len=0
   14   1.018934 192.168.46.132 → 192.168.70.34 HTTP 2980 Continuation
   15   1.018978 192.168.46.132 → 192.168.70.34 HTTP 2980 Continuation
   16   1.019120 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=11009 Win=64240 Len=0
   17   1.019121 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=12469 Win=64240 Len=0
...
...
  173   1.096653 192.168.70.34 → 192.168.46.132 TCP 66 [TCP ZeroWindow] 80 → 59664 [ACK] Seq=1 Ack=193509 Win=0 Len=0
  174   1.156231 192.168.70.34 → 192.168.46.132 TCP 66 [TCP Window Update] 80 → 59664 [ACK] Seq=1 Ack=193509 Win=4380 Len=0
  175   1.156250 192.168.46.132 → 192.168.70.34 HTTP 4440 [TCP Window Full] Continuation
  176   1.156344 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=194969 Win=2920 Len=0
  177   1.156344 192.168.70.34 → 192.168.46.132 TCP 66 80 → 59664 [ACK] Seq=1 Ack=196429 Win=1460 Len=0
  178   1.156416 192.168.70.34 → 192.168.46.132 TCP 66 [TCP ZeroWindow] 80 → 59664 [ACK] Seq=1 Ack=197889 Win=0 Len=0
  179   1.364067 192.168.46.132 → 192.168.70.34 TCP 60 [TCP Keep-Alive] 59664 → 80 [ACK] Seq=197888 Ack=1 Win=64240 Len=0
  180   1.804074 192.168.46.132 → 192.168.70.34 TCP 60 [TCP Keep-Alive] 59664 → 80 [ACK] Seq=197888 Ack=1 Win=64240 Len=0
  181   1.804404 192.168.70.34 → 192.168.46.132 TCP 66 [TCP ZeroWindow] 80 → 59664 [ACK] Seq=1 Ack=197889 Win=0 Len=0
  182   2.635608 192.168.46.132 → 192.168.70.34 TCP 60 [TCP Keep-Alive] 59664 → 80 [ACK] Seq=197888 Ack=1 Win=64240 Len=0
  183   2.635759 192.168.70.34 → 192.168.46.132 TCP 66 [TCP ZeroWindow] 80 → 59664 [ACK] Seq=1 Ack=197889 Win=0 Len=0
  184   3.041776 192.168.70.34 → 192.168.46.132 TCP 181 [TCP ZeroWindow] HTTP/1.0 200 OK  [TCP segment of a reassembled PDU]
  185   3.041810 192.168.46.132 → 192.168.70.34 TCP 60 59664 → 80 [ACK] Seq=197889 Ack=122 Win=64119 Len=0
  186   3.345284 192.168.70.34 → 192.168.46.132 TCP 2540 [TCP ZeroWindow] 80 → 59664 [PSH, ACK] Seq=122 Ack=197889 Win=0 Len=2480 [TCP segment of a reassembled PDU]
  187   3.345363 192.168.46.132 → 192.168.70.34 TCP 60 59664 → 80 [ACK] Seq=197889 Ack=2602 Win=62780 Len=0
  188   3.345602 192.168.70.34 → 192.168.46.132 TCP 5020 [TCP ZeroWindow] 80 → 59664 [PSH, ACK] Seq=2602 Ack=197889 Win=0 Len=4960 [TCP segment of a reassembled PDU]
  189   3.345631 192.168.46.132 → 192.168.70.34 TCP 60 59664 → 80 [ACK] Seq=197889 Ack=7562 Win=61320 Len=0

I expected the following

First, the time_starttransfer is expected to be the timestamp of Packet 184. and the description of it should be made clear to something like: The time, in seconds, it took from the start until the first byte was just about to be transferred from the server. This includes time_pretransfer and also the time the server needed to calculate the result.

Second, the description of time_pretransfer needs to be made clearer. More details are given below:

According to my test results above, it looks like time_pretransfer is the time when the file transfer is just about to begin by a client. If this is indeed the intended result, then time_starttransfer should include time_pretransfer, the time the server needed to calculate the result, and the time the client needed to send the entire request. However, this will give users no idea how to calculate the server response time as the time the client needed to send the entire request is unknown.

Therefore:
If time_pretransfer is the time when the file transfer is just about to begin by a client:

1. make the description of time_pretransfer clear
2. introduce a new variable to track the time the client needs to send an entire request, and
3. update the description of time_starttransfer to be something like: The time, in seconds, it took from the start until the first byte was just about to be transferred from the server. This includes time_pretransfer, time to complete sending a request, and also the time the server needed to calculate the result.

If time_pretransfer is the time when the client complete sending the entire request:

1. make the description of time_pretransfer clear.
2. re-implement time_pretransfer so that it will return the correct timestamp.

curl/libcurl version

curl 8.2.1 (x86_64-pc-linux-gnu) libcurl/8.2.1 OpenSSL/3.0.9 zlib/1.2.13
Release-Date: 2023-07-26
Protocols: dict file ftp ftps gopher gophers http https imap imaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HSTS HTTPS-proxy IPv6 Largefile libz NTLM NTLM_WB SSL threadsafe TLS-SRP UnixSockets

operating system

Linux kali 6.1.0-kali9-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.27-1kali1 (2023-05-12) x86_64 GNU/Linux

[bagder]

The libcurl docs for the time stamp is the canonical one. It describes this timer like this:

the time, in microseconds, it took from the start until the first byte is received by libcurl.

Does that not match what you see?

[JazJas]

Thank you for your update.

Unfortunately, my answer is: No, it does not match what I saw for the case where the post request had a large payload.

If time_starttransfer is indeed the time took from the start until the first byte of a server response is received, then it should report the timestamp of Packet 184 other than Packet 6.

[bagder]

Try #11670 !

[JazJas]

Thank you so much for your prompt actions.

However, after patching, the time_starttransfer is still incorrectly set to the time when the first byte of the POST payload is sent to the server.

In addition, the time_pretransfer should be set to the time when the last byte of the POST payload has been sent to the server so that the difference between time_starttransfer and time_pretransfer could be approximately used to determine the server response time.

[bagder]

the time_starttransfer is still incorrectly set to the time when the first byte of the POST payload is sent to the server.

Are you sure you're running the version with the #11670 patch? I don't see how it stores any timestamp for that moment. Curl_pgrsTime(data, TIMER_STARTTRANSFER); is now only called in a single place for an ordinary HTTP transfer:

curl/lib/transfer.c

Line 482 in 8a86ccf

Curl_pgrsTime(data, TIMER_STARTTRANSFER);

Any chance you can set a break-point to see how your TIMER_STARTTRANSFER is set to get that wrong?

In addition, the time_pretransfer should

If so, that's a separate issue and I rather we keep that separate. One thing at a time.

[JazJas]

Thank you for your update. I am so sorry for my previous incorrect test result.

I confirm that the time logged in TIMER_STARTTRANSFER is close to expected according to the analysis of packets captured by tcpdump.

I am closing this issue.

I will raise a separate issue for time_pretransfer.