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

diff --git a/docs/cmdline-opts/write-out.md b/docs/cmdline-opts/write-out.md
index 3f8af2b5e3e19e16327a5bccf2772c80e3286ff4..f11c28086442aca8de7633ecfec1ef345f774561 100644 (file)
--- 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 e6d67195056d97c3af223fb1ef70f990c6815206..d40bb3a3a8c9355bf6893dc0958d2e64db4fd174 100644 (file)
--- 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 d3a1b9ac9afad119f5a8d9dbcf8371a467060202..91fae30fdf7707845456ab9e0c4d266b7d2b25ba 100644 (file)
--- 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 4e89d981067825ed9d26dec793fcfc9810d7eada..ca6fc97714115034b55f206f749abf8b7ef4fbf8 100644 (file)
--- 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 ba45d137488ae0415032fe8b7029bd93257199ec..5c33ebb158b602fdde31c9092e50e51cff75a6d0 100644 (file)
--- 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 7b3ca7bd02726a2367ccd642fa2ac1784011f040..ace80e518dfa6ee7dbe90b2bd6cc413170a9443d 100644 (file)
--- 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 98997973850349888aea4ca6e40f319cc965f54e..18a47812f3b0bcc3116bb4796ecb2f09f5e11512 100644 (file)
--- a/tests/data/test970
+++ b/tests/data/test970
@@ -59,7 +59,7 @@ Accept: */*
 \r
 </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>

diff --git a/tests/data/test972 b/tests/data/test972
index 01bd2ed5fe7f87eb5be5565e312d325e89523353..d375adbe38d86e7b6109b25d2348357864860cfa 100644 (file)
--- a/tests/data/test972
+++ b/tests/data/test972
@@ -60,7 +60,7 @@ Accept: */*
 \r
 </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>

diff --git a/tests/http/test_16_info.py b/tests/http/test_16_info.py
index 06ab9503cf4e768f5d69aff7d4a23edde242d102..6b63ec875a0251a2d52d3256ee50a9d8ab6a78bc 100644 (file)
--- 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}'