getinfo: add CURLINFO_ADDED_TIME_Tbagder/time-added

The relative time from the creation of the multi handle until the easy
handle reached the DO state.

initial take for debug and discussion purposes

The name shall be improved/set once we agree on the exact time it is set.

11 files changed, 53 insertions, 17 deletions

diff --git a/include/curl/curl.h b/include/curl/curl.h
index c599b4d3f..f8c1ab772 100644
--- a/include/curl/curl.h
+++ b/include/curl/curl.h
@@ -2909,6 +2909,7 @@ typedef enum {
   CURLINFO_REFERER          = CURLINFO_STRING + 60,
   CURLINFO_CAINFO           = CURLINFO_STRING + 61,
   CURLINFO_CAPATH           = CURLINFO_STRING + 62,
+  CURLINFO_ADDED_TIME_T     = CURLINFO_OFF_T + 63, /* debug only for now */
   CURLINFO_LASTONE          = 62
 } CURLINFO;
 
diff --git a/lib/getinfo.c b/lib/getinfo.c
index 826ffd0b0..c5effec84 100644
--- a/lib/getinfo.c
+++ b/lib/getinfo.c
@@ -391,7 +391,12 @@ static CURLcode getinfo_offt(struct Curl_easy *data, CURLINFO info,
     *param_offt = (data->progress.flags & PGRS_UL_SIZE_KNOWN)?
       data->progress.size_ul:-1;
     break;
-   case CURLINFO_TOTAL_TIME_T:
+#ifdef CURLDEBUG
+  case CURLINFO_ADDED_TIME_T:
+    *param_offt = data->progress.t_added;
+    break;
+#endif
+  case CURLINFO_TOTAL_TIME_T:
     *param_offt = data->progress.timespent;
     break;
   case CURLINFO_NAMELOOKUP_TIME_T:
diff --git a/lib/multi.c b/lib/multi.c
index b6187cd20..e63d18572 100644
--- a/lib/multi.c
+++ b/lib/multi.c
@@ -127,13 +127,30 @@ static const char * const statename[]={
 /* function pointer called once when switching TO a state */
 typedef void (*init_multistate_func)(struct Curl_easy *data);
 
-/* called in DID state, before PERFORMING state */
-static void before_perform(struct Curl_easy *data)
+/* called before DO state */
+static void before_DO(struct Curl_easy *data)
+{
+#ifdef CURLDEBUG
+  Curl_pgrsTime(data, TIMER_ADDED);
+#endif
+}
+
+/* called before DID state */
+static void before_DID(struct Curl_easy *data)
 {
   data->req.chunk = FALSE;
   Curl_pgrsTime(data, TIMER_PRETRANSFER);
 }
 
+/* before_CONNECT() gets called each time the handle switches to CONNECT
+   which means this gets called once for each subsequent redirect etc */
+static void before_CONNECT(struct Curl_easy *data)
+{
+  data->state.fread_func = data->set.fread_func_set;
+  data->state.in = data->set.in_set;
+}
+
+
 static void init_completed(struct Curl_easy *data)
 {
   /* this is a completed transfer */
@@ -155,16 +172,16 @@ static void mstate(struct Curl_easy *data, CURLMstate state
   static const init_multistate_func finit[MSTATE_LAST] = {
     NULL,              /* INIT */
     NULL,              /* PENDING */
-    Curl_init_CONNECT, /* CONNECT */
+    before_CONNECT,    /* CONNECT */
     NULL,              /* RESOLVING */
     NULL,              /* CONNECTING */
     NULL,              /* TUNNELING */
     NULL,              /* PROTOCONNECT */
     NULL,              /* PROTOCONNECTING */
-    NULL,              /* DO */
+    before_DO,         /* DO */
     NULL,              /* DOING */
     NULL,              /* DOING_MORE */
-    before_perform,    /* DID */
+    before_DID,        /* DID */
     NULL,              /* PERFORMING */
     NULL,              /* RATELIMITING */
     NULL,              /* DONE */
@@ -574,6 +591,10 @@ CURLMcode curl_multi_add_handle(struct Curl_multi *multi,
   /* increase the alive-counter */
   multi->num_alive++;
 
+#ifdef CURLDEBUG
+  multi->t_created = Curl_now();
+#endif
+
   CONNCACHE_LOCK(data);
   /* The closure handle only ever has default timeouts set. To improve the
      state somewhat we clone the timeouts from each added handle so that the
@@ -2126,7 +2147,7 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi,
       }
       break;
 
-    case MSTATE_DO:
+     case MSTATE_DO:
       if(data->set.fprereq) {
         int prereq_rc;
 
diff --git a/lib/multihandle.h b/lib/multihandle.h
index 7dd6a0a75..143aa88da 100644
--- a/lib/multihandle.h
+++ b/lib/multihandle.h
@@ -149,6 +149,9 @@ struct Curl_multi {
   struct curltime timer_lastcall; /* the fixed time for the timeout for the
                                     previous callback */
   unsigned int max_concurrent_streams;
+#ifdef CURLDEBUG
+  struct curltime t_created;
+#endif
 
 #ifdef USE_WINSOCK
   WSAEVENT wsa_event; /* winsock event used for waits */
diff --git a/lib/progress.c b/lib/progress.c
index acebec481..d35eb217c 100644
--- a/lib/progress.c
+++ b/lib/progress.c
@@ -181,6 +181,14 @@ struct curltime Curl_pgrsTime(struct Curl_easy *data, timerid timer)
   case TIMER_NONE:
     /* mistake filter */
     break;
+#ifdef CURLDEBUG
+  case TIMER_ADDED: {
+    /* relative time from the creation of the multi handle */
+    struct Curl_multi *m = data->multi_easy ? data->multi_easy : data->multi;
+    data->progress.t_added = Curl_timediff_us(now, m->t_created);
+    break;
+  }
+#endif
   case TIMER_STARTOP:
     /* This is set at the start of a transfer */
     data->progress.t_startop = now;
diff --git a/lib/progress.h b/lib/progress.h
index 5719b18e2..eedf8b765 100644
--- a/lib/progress.h
+++ b/lib/progress.h
@@ -39,6 +39,9 @@ typedef enum {
   TIMER_POSTRANSFER,
   TIMER_STARTACCEPT,
   TIMER_REDIRECT,
+#ifdef CURLDEBUG
+  TIMER_ADDED,
+#endif
   TIMER_LAST /* must be last */
 } timerid;
 
diff --git a/lib/transfer.c b/lib/transfer.c
index 75e002547..78717a0c4 100644
--- a/lib/transfer.c
+++ b/lib/transfer.c
@@ -1278,14 +1278,6 @@ int Curl_single_getsock(struct Curl_easy *data,
   return bitmap;
 }
 
-/* Curl_init_CONNECT() gets called each time the handle switches to CONNECT
-   which means this gets called once for each subsequent redirect etc */
-void Curl_init_CONNECT(struct Curl_easy *data)
-{
-  data->state.fread_func = data->set.fread_func_set;
-  data->state.in = data->set.in_set;
-}
-
 /*
  * Curl_pretransfer() is called immediately before a transfer starts, and only
  * once for one transfer no matter if it has redirects or do multi-pass
diff --git a/lib/transfer.h b/lib/transfer.h
index 536ac249b..573ba0336 100644
--- a/lib/transfer.h
+++ b/lib/transfer.h
@@ -29,8 +29,6 @@ char *Curl_checkheaders(const struct Curl_easy *data,
                         const char *thisheader,
                         const size_t thislen);
 
-void Curl_init_CONNECT(struct Curl_easy *data);
-
 CURLcode Curl_pretransfer(struct Curl_easy *data);
 CURLcode Curl_posttransfer(struct Curl_easy *data);
 
diff --git a/lib/urldata.h b/lib/urldata.h
index 87e4b052a..d192c2798 100644
--- a/lib/urldata.h
+++ b/lib/urldata.h
@@ -1164,6 +1164,9 @@ struct Progress {
   timediff_t t_pretransfer;
   timediff_t t_starttransfer;
   timediff_t t_redirect;
+#ifdef CURLDEBUG
+  timediff_t t_added;
+#endif
 
   struct curltime start;
   struct curltime t_startsingle;
diff --git a/src/tool_writeout.c b/src/tool_writeout.c
index 5246db2cf..cc362ab01 100644
--- a/src/tool_writeout.c
+++ b/src/tool_writeout.c
@@ -111,6 +111,7 @@ static const struct writeoutvar variables[] = {
    writeLong},
   {"stderr", VAR_STDERR, CURLINFO_NONE, NULL},
   {"stdout", VAR_STDOUT, CURLINFO_NONE, NULL},
+  {"time_added", VAR_ADDED_TIME, CURLINFO_ADDED_TIME_T, writeTime},
   {"time_appconnect", VAR_APPCONNECT_TIME, CURLINFO_APPCONNECT_TIME_T,
    writeTime},
   {"time_connect", VAR_CONNECT_TIME, CURLINFO_CONNECT_TIME_T, writeTime},
diff --git a/src/tool_writeout.h b/src/tool_writeout.h
index 0c07f222b..558035e54 100644
--- a/src/tool_writeout.h
+++ b/src/tool_writeout.h
@@ -28,6 +28,7 @@
 
 typedef enum {
   VAR_NONE,       /* must be the first */
+  VAR_ADDED_TIME,
   VAR_APPCONNECT_TIME,
   VAR_CERT,
   VAR_CONNECT_TIME,