luo980/curl
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

getinfo: fix CURLINFO_QUEUE_TIME_T and add 'time_queue' var

Browse Source 
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
This commit is contained in:
Stefan Eissing 2024-11-07 14:43:23 +01:00 committed by Daniel Stenberg
parent 40c264db61
commit b06b35154f
No known key found for this signature in database
GPG Key ID: 5CC908FDB71E12C2
9 changed files with 25 additions and 9 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
docs/cmdline-opts/write-out.md
View File

@ -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

1
lib/getinfo.c
View File

@ -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:

12
lib/progress.c
View File

@ -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) {

1
lib/urldata.h
View File

@ -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 */

1
src/tool_writeout.c
View File

@ -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},

1
src/tool_writeout.h
View File

@ -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,

2
tests/data/test970
View File

@ -59,7 +59,7 @@ Accept: */*
</protocol>
<stdout nonewline="yes">
{"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"}
</stdout>
</verify>
</testcase>

2
tests/data/test972
View File

@ -60,7 +60,7 @@ Accept: */*
</protocol>
<stdout mode="text">
{"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"}
</stdout>
</verify>
</testcase>

8
tests/http/test_16_info.py
View File

@ -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}'