From 136504195ae63c79f01e8f5de058d305d7f21ffd Mon Sep 17 00:00:00 2001 From: Alex Snast Date: Mon, 15 Jul 2024 11:52:50 +0300 Subject: [PATCH] getinfo: add CURLINFO_POSTTRANSFER_TIME_T Returns the time, in microseconds, from the start until the last byte is sent by libcurl (i.e. the request is sent off). Closes #14189 --- .github/workflows/linux.yml | 1 + docs/cmdline-opts/write-out.md | 4 ++ docs/libcurl/curl_easy_getinfo.md | 17 +++-- .../opts/CURLINFO_POSTTRANSFER_TIME_T.md | 69 +++++++++++++++++++ docs/libcurl/opts/Makefile.inc | 1 + docs/libcurl/symbols-in-versions | 1 + include/curl/curl.h | 3 +- lib/getinfo.c | 5 ++ lib/progress.c | 2 +- lib/request.c | 1 + lib/urldata.h | 1 + src/tool_writeout.c | 2 + src/tool_writeout.h | 1 + tests/data/test1541 | 1 + tests/data/test970 | 2 +- tests/data/test972 | 2 +- tests/libtest/lib1541.c | 1 + tests/libtest/lib500.c | 18 +++++ 18 files changed, 123 insertions(+), 9 deletions(-) create mode 100644 docs/libcurl/opts/CURLINFO_POSTTRANSFER_TIME_T.md diff --git a/.github/workflows/linux.yml b/.github/workflows/linux.yml index 367abddc68..d378d9294a 100644 --- a/.github/workflows/linux.yml +++ b/.github/workflows/linux.yml @@ -169,6 +169,7 @@ jobs: - name: hyper install_steps: rust hyper valgrind configure: LDFLAGS="-Wl,-rpath,$HOME/hyper/target/debug" --with-openssl --with-hyper=$HOME/hyper --enable-debug --enable-websockets + tflags: '!500' singleuse: --unit - name: rustls diff --git a/docs/cmdline-opts/write-out.md b/docs/cmdline-opts/write-out.md index acfb59dcc5..3f8af2b5e3 100644 --- a/docs/cmdline-opts/write-out.md +++ b/docs/cmdline-opts/write-out.md @@ -221,6 +221,10 @@ remote host (or proxy) was completed. The time, in seconds, it took from the start until the name resolving was completed. +## `time_posttransfer` +The time it took from the start until the last byte is sent by libcurl. +In microseconds. (Added in 8.10.0) + ## `time_pretransfer` The time, in seconds, it took from the start until the file transfer was just about to begin. This includes all pre-transfer commands and negotiations that diff --git a/docs/libcurl/curl_easy_getinfo.md b/docs/libcurl/curl_easy_getinfo.md index ce328d6c56..7157cd2113 100644 --- a/docs/libcurl/curl_easy_getinfo.md +++ b/docs/libcurl/curl_easy_getinfo.md @@ -180,6 +180,11 @@ See CURLINFO_NUM_CONNECTS(3) The errno from the last failure to connect. See CURLINFO_OS_ERRNO(3) +## CURLINFO_POSTTRANSFER_TIME_T + +The time it took from the start until the last byte is sent by libcurl. +In microseconds. (Added in 8.10.0) See CURLINFO_POSTTRANSFER_TIME_T(3) + ## CURLINFO_PRETRANSFER_TIME The time it took from the start until the file transfer is just about to @@ -375,15 +380,17 @@ An overview of the time values available from curl_easy_getinfo(3) |--|--|--CONNECT |--|--|--|--APPCONNECT |--|--|--|--|--PRETRANSFER - |--|--|--|--|--|--STARTTRANSFER - |--|--|--|--|--|--|--TOTAL - |--|--|--|--|--|--|--REDIRECT + |--|--|--|--|--|--POSTTRANSFER + |--|--|--|--|--|--|--STARTTRANSFER + |--|--|--|--|--|--|--|--TOTAL + |--|--|--|--|--|--|--|--REDIRECT CURLINFO_QUEUE_TIME_T(3), CURLINFO_NAMELOOKUP_TIME_T(3), CURLINFO_CONNECT_TIME_T(3), CURLINFO_APPCONNECT_TIME_T(3), - CURLINFO_PRETRANSFER_TIME_T(3), CURLINFO_STARTTRANSFER_TIME_T(3), - CURLINFO_TOTAL_TIME_T(3), CURLINFO_REDIRECT_TIME_T(3) + CURLINFO_PRETRANSFER_TIME_T(3), CURLINFO_POSTTRANSFER_TIME_T(3), + CURLINFO_STARTTRANSFER_TIME_T(3), CURLINFO_TOTAL_TIME_T(3), + CURLINFO_REDIRECT_TIME_T(3) # %PROTOCOLS% diff --git a/docs/libcurl/opts/CURLINFO_POSTTRANSFER_TIME_T.md b/docs/libcurl/opts/CURLINFO_POSTTRANSFER_TIME_T.md new file mode 100644 index 0000000000..5d81a59a6c --- /dev/null +++ b/docs/libcurl/opts/CURLINFO_POSTTRANSFER_TIME_T.md @@ -0,0 +1,69 @@ +--- +c: Copyright (C) Daniel Stenberg, , et al. +SPDX-License-Identifier: curl +Title: CURLINFO_POSTTRANSFER_TIME_T +Section: 3 +Source: libcurl +See-also: + - CURLINFO_PRETRANSFER_TIME_T (3) + - CURLOPT_TIMEOUT (3) + - curl_easy_getinfo (3) + - curl_easy_setopt (3) +Protocol: + - All +Added-in: 8.10.0 +--- + +# NAME + +CURLINFO_POSTTRANSFER_TIME_T - get the time until the last byte is sent + +# SYNOPSIS + +~~~c +#include + +CURLcode curl_easy_getinfo(CURL *handle, CURLINFO_POSTTRANSFER_TIME_T, + curl_off_t *timep); +~~~ + +# DESCRIPTION + +Pass a pointer to a curl_off_t to receive the time, in microseconds, +it took from the start until the last byte is sent by libcurl. + +When a redirect is followed, the time from each request is added together. + +See also the TIMES overview in the curl_easy_getinfo(3) man page. + +# %PROTOCOLS% + +# EXAMPLE + +~~~c +int main(void) +{ + CURL *curl = curl_easy_init(); + if(curl) { + CURLcode res; + curl_easy_setopt(curl, CURLOPT_URL, "https://example.com"); + res = curl_easy_perform(curl); + if(CURLE_OK == res) { + curl_off_t posttransfer; + res = curl_easy_getinfo(curl, CURLINFO_POSTTRANSFER_TIME_T, &posttransfer); + if(CURLE_OK == res) { + printf("Request sent after: %" CURL_FORMAT_CURL_OFF_T ".%06ld us", posttransfer / 1000000, + (long)(posttransfer % 1000000)); + } + } + /* always cleanup */ + curl_easy_cleanup(curl); + } +} +~~~ + +# %AVAILABILITY% + +# RETURN VALUE + +Returns CURLE_OK if the option is supported, and CURLE_UNKNOWN_OPTION if not. diff --git a/docs/libcurl/opts/Makefile.inc b/docs/libcurl/opts/Makefile.inc index f09c5863d3..edabe37a75 100644 --- a/docs/libcurl/opts/Makefile.inc +++ b/docs/libcurl/opts/Makefile.inc @@ -58,6 +58,7 @@ man_MANS = \ CURLINFO_OS_ERRNO.3 \ CURLINFO_PRETRANSFER_TIME.3 \ CURLINFO_PRETRANSFER_TIME_T.3 \ + CURLINFO_POSTTRANSFER_TIME_T.3 \ CURLINFO_PRIMARY_IP.3 \ CURLINFO_PRIMARY_PORT.3 \ CURLINFO_PRIVATE.3 \ diff --git a/docs/libcurl/symbols-in-versions b/docs/libcurl/symbols-in-versions index ebf2cee293..69246c013d 100644 --- a/docs/libcurl/symbols-in-versions +++ b/docs/libcurl/symbols-in-versions @@ -462,6 +462,7 @@ CURLINFO_OFF_T 7.55.0 CURLINFO_OS_ERRNO 7.12.2 CURLINFO_PRETRANSFER_TIME 7.4.1 CURLINFO_PRETRANSFER_TIME_T 7.61.0 +CURLINFO_POSTTRANSFER_TIME_T 8.10.0 CURLINFO_PRIMARY_IP 7.19.0 CURLINFO_PRIMARY_PORT 7.21.0 CURLINFO_PRIVATE 7.10.3 diff --git a/include/curl/curl.h b/include/curl/curl.h index 67c816cfb5..e37394174a 100644 --- a/include/curl/curl.h +++ b/include/curl/curl.h @@ -2953,7 +2953,8 @@ typedef enum { CURLINFO_CONN_ID = CURLINFO_OFF_T + 64, CURLINFO_QUEUE_TIME_T = CURLINFO_OFF_T + 65, CURLINFO_USED_PROXY = CURLINFO_LONG + 66, - CURLINFO_LASTONE = 66 + CURLINFO_POSTTRANSFER_TIME_T = CURLINFO_OFF_T + 67, + CURLINFO_LASTONE = 67 } CURLINFO; /* CURLINFO_RESPONSE_CODE is the new name for the option previously known as diff --git a/lib/getinfo.c b/lib/getinfo.c index 03bf85ae65..c05d3c9d37 100644 --- a/lib/getinfo.c +++ b/lib/getinfo.c @@ -53,6 +53,7 @@ CURLcode Curl_initinfo(struct Curl_easy *data) pro->t_connect = 0; pro->t_appconnect = 0; pro->t_pretransfer = 0; + pro->t_posttransfer = 0; pro->t_starttransfer = 0; pro->timespent = 0; pro->t_redirect = 0; @@ -368,6 +369,7 @@ static CURLcode getinfo_offt(struct Curl_easy *data, CURLINFO info, case CURLINFO_CONNECT_TIME_T: case CURLINFO_APPCONNECT_TIME_T: case CURLINFO_PRETRANSFER_TIME_T: + case CURLINFO_POSTTRANSFER_TIME_T: case CURLINFO_STARTTRANSFER_TIME_T: case CURLINFO_REDIRECT_TIME_T: case CURLINFO_SPEED_DOWNLOAD_T: @@ -418,6 +420,9 @@ static CURLcode getinfo_offt(struct Curl_easy *data, CURLINFO info, case CURLINFO_PRETRANSFER_TIME_T: *param_offt = data->progress.t_pretransfer; break; + case CURLINFO_POSTTRANSFER_TIME_T: + *param_offt = data->progress.t_posttransfer; + break; case CURLINFO_STARTTRANSFER_TIME_T: *param_offt = data->progress.t_starttransfer; break; diff --git a/lib/progress.c b/lib/progress.c index 67f4ba9c30..52fecf2d6f 100644 --- a/lib/progress.c +++ b/lib/progress.c @@ -217,7 +217,7 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer, break; } case TIMER_POSTRANSFER: - /* this is the normal end-of-transfer thing */ + delta = &data->progress.t_posttransfer; break; case TIMER_REDIRECT: data->progress.t_redirect = Curl_timediff_us(timestamp, diff --git a/lib/request.c b/lib/request.c index c42f2e6677..a38be46833 100644 --- a/lib/request.c +++ b/lib/request.c @@ -258,6 +258,7 @@ CURLcode Curl_req_set_upload_done(struct Curl_easy *data) data->req.upload_done = TRUE; data->req.keepon &= ~(KEEP_SEND|KEEP_SEND_TIMED); /* we are done sending */ + Curl_pgrsTime(data, TIMER_POSTRANSFER); Curl_creader_done(data, data->req.upload_aborted); if(data->req.upload_aborted) { diff --git a/lib/urldata.h b/lib/urldata.h index 096665440c..d16e00dfe5 100644 --- a/lib/urldata.h +++ b/lib/urldata.h @@ -1091,6 +1091,7 @@ struct Progress { timediff_t t_connect; timediff_t t_appconnect; timediff_t t_pretransfer; + timediff_t t_posttransfer; timediff_t t_starttransfer; timediff_t t_redirect; diff --git a/src/tool_writeout.c b/src/tool_writeout.c index 20945cf480..7892b68a8b 100644 --- a/src/tool_writeout.c +++ b/src/tool_writeout.c @@ -119,6 +119,8 @@ static const struct writeoutvar variables[] = { {"time_connect", VAR_CONNECT_TIME, CURLINFO_CONNECT_TIME_T, writeTime}, {"time_namelookup", VAR_NAMELOOKUP_TIME, CURLINFO_NAMELOOKUP_TIME_T, writeTime}, + {"time_posttransfer", VAR_POSTTRANSFER_TIME, CURLINFO_POSTTRANSFER_TIME_T, + writeTime}, {"time_pretransfer", VAR_PRETRANSFER_TIME, CURLINFO_PRETRANSFER_TIME_T, writeTime}, {"time_redirect", VAR_REDIRECT_TIME, CURLINFO_REDIRECT_TIME_T, writeTime}, diff --git a/src/tool_writeout.h b/src/tool_writeout.h index 36b218cc44..77ceaff1c4 100644 --- a/src/tool_writeout.h +++ b/src/tool_writeout.h @@ -77,6 +77,7 @@ typedef enum { VAR_NUM_RETRY, VAR_ONERROR, VAR_PRETRANSFER_TIME, + VAR_POSTTRANSFER_TIME, VAR_PRIMARY_IP, VAR_PRIMARY_PORT, VAR_PROXY_SSL_VERIFY_RESULT, diff --git a/tests/data/test1541 b/tests/data/test1541 index 5094c3513c..9b29f43534 100644 --- a/tests/data/test1541 +++ b/tests/data/test1541 @@ -36,6 +36,7 @@ Transfer-Encoding: chunked datad474 CURLINFO_CONNECT_TIME_T on done is OK CURLINFO_PRETRANSFER_TIME_T on done is OK +CURLINFO_POSTTRANSFER_TIME_T on done is OK CURLINFO_STARTTRANSFER_TIME_T on done is OK CURLINFO_APPCONNECT_TIME_T on done is OK CURLINFO_SPEED_DOWNLOAD_T on done is OK diff --git a/tests/data/test970 b/tests/data/test970 index bf1235da58..9899797385 100644 --- a/tests/data/test970 +++ b/tests/data/test970 @@ -59,7 +59,7 @@ Accept: */* -{"certs":"","conn_id":0,"content_type":"text/html","errormsg":null,"exitcode":0,"filename_effective":"%LOGDIR/out%TESTNUMBER","ftp_entry_path":null,"http_code":200,"http_connect":0,"http_version":"1.1","local_ip":"127.0.0.1","local_port":13,"method":"GET","num_certs":0,"num_connects":1,"num_headers":9,"num_redirects":0,"num_retries":0,"proxy_ssl_verify_result":0,"proxy_used":0,"redirect_url":null,"referer":null,"remote_ip":"%HOSTIP","remote_port":%HTTPPORT,"response_code":200,"scheme":"http","size_download":445,"size_header":4019,"size_request":4019,"size_upload":0,"speed_download":13,"speed_upload":13,"ssl_verify_result":0,"time_appconnect":0.000013,"time_connect":0.000013,"time_namelookup":0.000013,"time_pretransfer":0.000013,"time_redirect":0.000013,"time_starttransfer":0.000013,"time_total":0.000013,"url":"http://%HOSTIP:%HTTPPORT/%TESTNUMBER","url.fragment":null,"url.host":"127.0.0.1","url.options":null,"url.password":null,"url.path":"/%TESTNUMBER","url.port":"%HTTPPORT","url.query":null,"url.scheme":"http","url.user":null,"url.zoneid":null,"url_effective":"http://%HOSTIP:%HTTPPORT/%TESTNUMBER","urle.fragment":null,"urle.host":"127.0.0.1","urle.options":null,"urle.password":null,"urle.path":"/%TESTNUMBER","urle.port":"%HTTPPORT","urle.query":null,"urle.scheme":"http","urle.user":null,"urle.zoneid":null,"urlnum":0,"xfer_id":0,"curl_version":"curl-unit-test-fake-version"} +{"certs":"","conn_id":0,"content_type":"text/html","errormsg":null,"exitcode":0,"filename_effective":"%LOGDIR/out%TESTNUMBER","ftp_entry_path":null,"http_code":200,"http_connect":0,"http_version":"1.1","local_ip":"127.0.0.1","local_port":13,"method":"GET","num_certs":0,"num_connects":1,"num_headers":9,"num_redirects":0,"num_retries":0,"proxy_ssl_verify_result":0,"proxy_used":0,"redirect_url":null,"referer":null,"remote_ip":"%HOSTIP","remote_port":%HTTPPORT,"response_code":200,"scheme":"http","size_download":445,"size_header":4019,"size_request":4019,"size_upload":0,"speed_download":13,"speed_upload":13,"ssl_verify_result":0,"time_appconnect":0.000013,"time_connect":0.000013,"time_namelookup":0.000013,"time_posttransfer":0.000013,"time_pretransfer":0.000013,"time_redirect":0.000013,"time_starttransfer":0.000013,"time_total":0.000013,"url":"http://%HOSTIP:%HTTPPORT/%TESTNUMBER","url.fragment":null,"url.host":"127.0.0.1","url.options":null,"url.password":null,"url.path":"/%TESTNUMBER","url.port":"%HTTPPORT","url.query":null,"url.scheme":"http","url.user":null,"url.zoneid":null,"url_effective":"http://%HOSTIP:%HTTPPORT/%TESTNUMBER","urle.fragment":null,"urle.host":"127.0.0.1","urle.options":null,"urle.password":null,"urle.path":"/%TESTNUMBER","urle.port":"%HTTPPORT","urle.query":null,"urle.scheme":"http","urle.user":null,"urle.zoneid":null,"urlnum":0,"xfer_id":0,"curl_version":"curl-unit-test-fake-version"} diff --git a/tests/data/test972 b/tests/data/test972 index c6def29867..01bd2ed5fe 100644 --- a/tests/data/test972 +++ b/tests/data/test972 @@ -60,7 +60,7 @@ Accept: */* -{"certs":"","conn_id":0,"content_type":"text/html","errormsg":null,"exitcode":0,"filename_effective":"%LOGDIR/out%TESTNUMBER","ftp_entry_path":null,"http_code":200,"http_connect":0,"http_version":"1.1","local_ip":"127.0.0.1","local_port":13,"method":"GET","num_certs":0,"num_connects":1,"num_headers":9,"num_redirects":0,"num_retries":0,"proxy_ssl_verify_result":0,"proxy_used":0,"redirect_url":null,"referer":null,"remote_ip":"%HOSTIP","remote_port":%HTTPPORT,"response_code":200,"scheme":"http","size_download":445,"size_header":4019,"size_request":4019,"size_upload":0,"speed_download":13,"speed_upload":13,"ssl_verify_result":0,"time_appconnect":0.000013,"time_connect":0.000013,"time_namelookup":0.000013,"time_pretransfer":0.000013,"time_redirect":0.000013,"time_starttransfer":0.000013,"time_total":0.000013,"url":"http://%HOSTIP:%HTTPPORT/%TESTNUMBER","url.fragment":null,"url.host":"127.0.0.1","url.options":null,"url.password":null,"url.path":"/%TESTNUMBER","url.port":"%HTTPPORT","url.query":null,"url.scheme":"http","url.user":null,"url.zoneid":null,"url_effective":"http://%HOSTIP:%HTTPPORT/%TESTNUMBER","urle.fragment":null,"urle.host":"127.0.0.1","urle.options":null,"urle.password":null,"urle.path":"/%TESTNUMBER","urle.port":"%HTTPPORT","urle.query":null,"urle.scheme":"http","urle.user":null,"urle.zoneid":null,"urlnum":0,"xfer_id":0,"curl_version":"curl-unit-test-fake-version"} +{"certs":"","conn_id":0,"content_type":"text/html","errormsg":null,"exitcode":0,"filename_effective":"%LOGDIR/out%TESTNUMBER","ftp_entry_path":null,"http_code":200,"http_connect":0,"http_version":"1.1","local_ip":"127.0.0.1","local_port":13,"method":"GET","num_certs":0,"num_connects":1,"num_headers":9,"num_redirects":0,"num_retries":0,"proxy_ssl_verify_result":0,"proxy_used":0,"redirect_url":null,"referer":null,"remote_ip":"%HOSTIP","remote_port":%HTTPPORT,"response_code":200,"scheme":"http","size_download":445,"size_header":4019,"size_request":4019,"size_upload":0,"speed_download":13,"speed_upload":13,"ssl_verify_result":0,"time_appconnect":0.000013,"time_connect":0.000013,"time_namelookup":0.000013,"time_posttransfer":0.000013,"time_pretransfer":0.000013,"time_redirect":0.000013,"time_starttransfer":0.000013,"time_total":0.000013,"url":"http://%HOSTIP:%HTTPPORT/%TESTNUMBER","url.fragment":null,"url.host":"127.0.0.1","url.options":null,"url.password":null,"url.path":"/%TESTNUMBER","url.port":"%HTTPPORT","url.query":null,"url.scheme":"http","url.user":null,"url.zoneid":null,"url_effective":"http://%HOSTIP:%HTTPPORT/%TESTNUMBER","urle.fragment":null,"urle.host":"127.0.0.1","urle.options":null,"urle.password":null,"urle.path":"/%TESTNUMBER","urle.port":"%HTTPPORT","urle.query":null,"urle.scheme":"http","urle.user":null,"urle.zoneid":null,"urlnum":0,"xfer_id":0,"curl_version":"curl-unit-test-fake-version"} diff --git a/tests/libtest/lib1541.c b/tests/libtest/lib1541.c index f326211d46..640a2f1690 100644 --- a/tests/libtest/lib1541.c +++ b/tests/libtest/lib1541.c @@ -137,6 +137,7 @@ CURLcode test(char *URL) check_time(curls, KN(CURLINFO_CONNECT_TIME_T), "done"); check_time(curls, KN(CURLINFO_PRETRANSFER_TIME_T), "done"); + check_time(curls, KN(CURLINFO_POSTTRANSFER_TIME_T), "done"); check_time(curls, KN(CURLINFO_STARTTRANSFER_TIME_T), "done"); /* no SSL, must be 0 */ check_time0(curls, KN(CURLINFO_APPCONNECT_TIME_T), "done"); diff --git a/tests/libtest/lib500.c b/tests/libtest/lib500.c index b117862903..8b27aef04a 100644 --- a/tests/libtest/lib500.c +++ b/tests/libtest/lib500.c @@ -101,6 +101,7 @@ CURLcode test(char *URL) curl_off_t time_namelookup; curl_off_t time_connect; curl_off_t time_pretransfer; + curl_off_t time_posttransfer; curl_off_t time_starttransfer; curl_off_t time_total; fprintf(moo, "IP %s\n", ipstr); @@ -108,6 +109,8 @@ CURLcode test(char *URL) curl_easy_getinfo(curl, CURLINFO_CONNECT_TIME_T, &time_connect); curl_easy_getinfo(curl, CURLINFO_PRETRANSFER_TIME_T, &time_pretransfer); + curl_easy_getinfo(curl, CURLINFO_POSTTRANSFER_TIME_T, + &time_posttransfer); curl_easy_getinfo(curl, CURLINFO_STARTTRANSFER_TIME_T, &time_starttransfer); curl_easy_getinfo(curl, CURLINFO_TOTAL_TIME_T, &time_total); @@ -128,6 +131,14 @@ CURLcode test(char *URL) (time_pretransfer / 1000000), (long)(time_pretransfer % 1000000)); } + if(time_pretransfer > time_posttransfer) { + fprintf(moo, "pretransfer vs posttransfer: %" CURL_FORMAT_CURL_OFF_T + ".%06ld %" CURL_FORMAT_CURL_OFF_T ".%06ld\n", + (time_pretransfer / 1000000), + (long)(time_pretransfer % 1000000), + (time_posttransfer / 1000000), + (long)(time_posttransfer % 1000000)); + } if(time_pretransfer > time_starttransfer) { fprintf(moo, "pretransfer vs starttransfer: %" CURL_FORMAT_CURL_OFF_T ".%06ld %" CURL_FORMAT_CURL_OFF_T ".%06ld\n", @@ -143,6 +154,13 @@ CURLcode test(char *URL) (long)(time_starttransfer % 1000000), (time_total / 1000000), (long)(time_total % 1000000)); } + if(time_posttransfer > time_total) { + fprintf(moo, "posttransfer vs total: %" CURL_FORMAT_CURL_OFF_T + ".%06ld %" CURL_FORMAT_CURL_OFF_T ".%06ld\n", + (time_posttransfer / 1000000), + (long)(time_posttransfer % 1000000), + (time_total / 1000000), (long)(time_total % 1000000)); + } fclose(moo); } -- 2.47.3