From b06b35154f76b5db343c7919f0340933c5f2ec48 Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Thu, 7 Nov 2024 14:43:23 +0100 Subject: [PATCH] getinfo: fix CURLINFO_QUEUE_TIME_T and add 'time_queue' var Let CURLINFO_QUEUE_TIME_T count only the time a transfer spends queued, including possible redirect requests. Add var 'time_queue' for reporting the time in write outs. Add test for verifying correct reporting. Closes #15512 --- docs/cmdline-opts/write-out.md | 6 ++++++ lib/getinfo.c | 1 + lib/progress.c | 12 ++++++------ lib/urldata.h | 1 + src/tool_writeout.c | 1 + src/tool_writeout.h | 1 + tests/data/test970 | 2 +- tests/data/test972 | 2 +- tests/http/test_16_info.py | 8 +++++++- 9 files changed, 25 insertions(+), 9 deletions(-) diff --git a/docs/cmdline-opts/write-out.md b/docs/cmdline-opts/write-out.md index 3f8af2b5e3..f11c280864 100644 --- a/docs/cmdline-opts/write-out.md +++ b/docs/cmdline-opts/write-out.md @@ -230,6 +230,12 @@ 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 are specific to the particular protocol(s) involved. +## `time_queue` +The time, in seconds, the transfer was queued during its run. This adds +the queue time for each redirect step that may have happened. Transfers +may be queued for significant amounts of time when connection or parallel +limits are in place. (Added in 8.12.0) + ## `time_redirect` The time, in seconds, it took for all redirection steps including name lookup, connect, pretransfer and transfer before the final transaction was diff --git a/lib/getinfo.c b/lib/getinfo.c index e6d6719505..d40bb3a3a8 100644 --- a/lib/getinfo.c +++ b/lib/getinfo.c @@ -379,6 +379,7 @@ static CURLcode getinfo_offt(struct Curl_easy *data, CURLINFO info, case CURLINFO_APPCONNECT_TIME_T: case CURLINFO_PRETRANSFER_TIME_T: case CURLINFO_POSTTRANSFER_TIME_T: + case CURLINFO_QUEUE_TIME_T: case CURLINFO_STARTTRANSFER_TIME_T: case CURLINFO_REDIRECT_TIME_T: case CURLINFO_SPEED_DOWNLOAD_T: diff --git a/lib/progress.c b/lib/progress.c index d3a1b9ac9a..91fae30fdf 100644 --- a/lib/progress.c +++ b/lib/progress.c @@ -170,6 +170,8 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer, case TIMER_STARTOP: /* This is set at the start of a transfer */ data->progress.t_startop = timestamp; + data->progress.t_startqueue = timestamp; + data->progress.t_postqueue = 0; break; case TIMER_STARTSINGLE: /* This is set at the start of each single transfer */ @@ -177,12 +179,9 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer, data->progress.is_t_startransfer_set = FALSE; break; case TIMER_POSTQUEUE: - /* Set when the transfer starts (after potentially having been brought - back from the waiting queue). It needs to count from t_startop and not - t_startsingle since the latter is reset when a connection is brought - back from the pending queue. */ - data->progress.t_postqueue = - Curl_timediff_us(timestamp, data->progress.t_startop); + /* Queue time is accumulative from all involved redirects */ + data->progress.t_postqueue += + Curl_timediff_us(timestamp, data->progress.t_startqueue); break; case TIMER_STARTACCEPT: data->progress.t_acceptdata = timestamp; @@ -220,6 +219,7 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer, case TIMER_REDIRECT: data->progress.t_redirect = Curl_timediff_us(timestamp, data->progress.start); + data->progress.t_startqueue = timestamp; break; } if(delta) { diff --git a/lib/urldata.h b/lib/urldata.h index 4e89d98106..ca6fc97714 100644 --- a/lib/urldata.h +++ b/lib/urldata.h @@ -1047,6 +1047,7 @@ struct Progress { struct curltime start; struct curltime t_startsingle; struct curltime t_startop; + struct curltime t_startqueue; struct curltime t_acceptdata; #define CURR_TIME (5 + 1) /* 6 entries for 5 seconds */ diff --git a/src/tool_writeout.c b/src/tool_writeout.c index ba45d13748..5c33ebb158 100644 --- a/src/tool_writeout.c +++ b/src/tool_writeout.c @@ -122,6 +122,7 @@ static const struct writeoutvar variables[] = { writeTime}, {"time_pretransfer", VAR_PRETRANSFER_TIME, CURLINFO_PRETRANSFER_TIME_T, writeTime}, + {"time_queue", VAR_QUEUE_TIME, CURLINFO_QUEUE_TIME_T, writeTime}, {"time_redirect", VAR_REDIRECT_TIME, CURLINFO_REDIRECT_TIME_T, writeTime}, {"time_starttransfer", VAR_STARTTRANSFER_TIME, CURLINFO_STARTTRANSFER_TIME_T, writeTime}, diff --git a/src/tool_writeout.h b/src/tool_writeout.h index 7b3ca7bd02..ace80e518d 100644 --- a/src/tool_writeout.h +++ b/src/tool_writeout.h @@ -82,6 +82,7 @@ typedef enum { VAR_PRIMARY_PORT, VAR_PROXY_SSL_VERIFY_RESULT, VAR_PROXY_USED, + VAR_QUEUE_TIME, VAR_REDIRECT_COUNT, VAR_REDIRECT_TIME, VAR_REDIRECT_URL, diff --git a/tests/data/test970 b/tests/data/test970 index 9899797385..18a47812f3 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_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"} +{"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_queue":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 01bd2ed5fe..d375adbe38 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_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"} +{"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_queue":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/http/test_16_info.py b/tests/http/test_16_info.py index 06ab9503cf..6b63ec875a 100644 --- a/tests/http/test_16_info.py +++ b/tests/http/test_16_info.py @@ -144,7 +144,7 @@ class TestInfo: 'time_pretransfer', 'time_starttransfer', 'time_total' } # stat keys where we expect a positive value - pos_keys = {'time_pretransfer', 'time_starttransfer', 'time_total'} + pos_keys = {'time_pretransfer', 'time_starttransfer', 'time_total', 'time_queue'} if s['num_connects'] > 0: pos_keys.add('time_connect') if url.startswith('https:'): @@ -167,3 +167,9 @@ class TestInfo: # assert that transfer start is before total assert s['time_starttransfer'] <= s['time_total'], f'"time_starttransfer" '\ f'greater than "time_total", {s}' + if s['num_redirects'] > 0: + assert s['time_queue'] < s['time_starttransfer'], f'"time_queue" '\ + f'greater/equal than "time_starttransfer", {s}' + else: + assert s['time_queue'] <= s['time_starttransfer'], f'"time_queue" '\ + f'greater than "time_starttransfer", {s}' -- 2.47.3