Hello Daniel & Mezon,

I have came across the same timing issue. That is, a wrong STARTTRANSFER time when POSTing data bigger than 1024 bytes (1024 is the value of TINY_INITIAL_POST_SIZE defined in lib/http.h). Mezon is right, it's using the 100-continue response to set the STARTTRANSFER time, instead of the time of the first byte of actual data received.

I have attached a nodejs script to reproduce the issue:

~~~~~~
# Set up dummy server
$ nodejs index.js 8000

# Curl command that throws the STARTTRANSFER value to stdout
# data.txt should be a file with > 1024 bytes of data.
$ curl -v --data @data.txt --write-out ">>> Pre transfer time: %{time_pretransfer}\n>>> Start Transfer Time: %{time_starttransfer}\n>>> Total time: %{time_total}\n\n" http://127.0.0.1:8000/
~~~~~~

I have also attached a patch with a possible solution, a review would be really appreciated.

Hope that helps.
Thanks,
Lucas Manuel Rodriguez.

Attachment: bug_1213.diff (2.3 kB; text/x-patch) index.js (683 Bytes; application/javascript)

---
** [bugs:#1213] Wrong STARTTRANSFER timer for POST requests getting response code 100**
**Status:** open
**Labels:** POST CURLINFO_STARTTRANSFER_TIME 
**Created:** Sat Apr 06, 2013 07:17 PM UTC by Mezon
**Last Updated:** Thu Aug 28, 2014 05:13 AM UTC
**Owner:** Daniel Stenberg
curl 7.28.1 (i686-pc-linux-gnu) libcurl/7.28.1 OpenSSL/0.9.8o zlib/1.2.3.4
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smtp smtps telnet tftp 
Features: IPv6 Largefile NTLM NTLM_WB SSL libz 
There is an error in timing accounting at least for STARTTRANSFER timer during POST requests.
Timer works fine with GET requests, but while using POST the time for CURLINFO_STARTTRANSFER_TIME is wrong. While using POST CURLINFO_STARTTRANSFER_TIME minus CURLINFO_PRETRANSFER_TIME is near to zero every time.
Proof of concept:
I've prepared CGI script that sleeps 3 seconds on start, before it returns any data.
While making curl GET request to the script, (CURLINFO_STARTTRANSFER_TIME - CURLINFO_PRETRANSFER_TIME) is ok [~ 3 seconds]. Trying the same thing with POST request, cause the 3 seconds appears in CURLINFO_TOTAL_TIME instead of CURLINFO_STARTTRANSFER_TIME. So with POST it looks like the transfer took 3 seconds instead of waiting for server reply.
IMHO the problem is in ./lib/transfer.c in readwrite_upload() function, where Curl_pgrsTime(data, TIMER_STARTTRANSFER) is called in wrong place. Unfortunately I'm not sure where to replace it to fix the bug. I think it should go somewhere in Curl_readwrite() function, for example here:
~~~~~~
/* We go ahead and do a read if we have a readable socket or if
     the stream was rewound (in which case we have data in a
     buffer) */
if((k->keepon & KEEP_RECV) &&
     ((select_res & CURL_CSELECT_IN) || conn->bits.stream_was_rewound)) {
    result = readwrite_data(data, conn, k, &didwhat, done);
    if(result || *done)
      return result;
  }
  else {
      Curl_pgrsTime(data, TIMER_STARTTRANSFER); // <-- here
  }
~~~~~~
I'm not sure if any other timers are affected.
Best regards,
Mezon
---
Sent from sourceforge.net because curl-tracker@cool.haxx.se is subscribed to https://sourceforge.net/p/curl/bugs/
To unsubscribe from further messages, a project admin can change settings at https://sourceforge.net/p/curl/admin/bugs/options.  Or, if this is a mailing list, you can unsubscribe from the mailing list.