← Commit list

fbcf10ab84

Stefan Eissing
Stefan Eissing
2026-06-07
SUCCESS Duration: 241s

Subject

progress: fx CURLINFO time reporting

Binary

No binary (build failed)

Architecture & Compiler Flags

Architecture: x86_64-linux-gnu Compiler: gcc (Ubuntu 11.4.0-1ubuntu1~22.04.3) 11.4.0

—

Build Log

(log yok)

Commit Diff GitHub →

lib/multi.c +61 -49lib/progress.c +38 -5lib/progress.h +2 -0lib/request.c +2 -1lib/sendf.c +2 -1tests/http/testenv/curl.py +2 -17tests/libtest/lib500.c +1 -4tests/unit/unit1399.c +51 -32
lib/multi.c+61 -49
@@ -106,20 +106,56 @@ static const struct curltime *multi_now(struct Curl_multi *multi)
return &multi->now;
}
-/* function pointer called once when switching TO a state */
-typedef void (*init_multistate_func)(struct Curl_easy *data);
+/* function pointer called once when entering a state */
+typedef void (*mstate_enter_func)(struct Curl_easy *data,
+ CURLMstate from_state);
-/* called in DID state, before PERFORMING state */
-static void before_perform(struct Curl_easy *data)
+static void mstate_enter_connect(struct Curl_easy *data,
+ CURLMstate from_state)
{
+ (void)from_state;
+ Curl_init_CONNECT(data);
+}
+
+static void mstate_enter_did(struct Curl_easy *data,
+ CURLMstate from_state)
+{
+ (void)from_state;
data->req.chunk = FALSE;
Curl_pgrsTime(data, TIMER_PRETRANSFER);
+ if(!CURL_REQ_WANT_SEND(data))
+ Curl_pgrsTime(data, TIMER_POSTRANSFER);
+}
+
+static void mstate_enter_done(struct Curl_easy *data,
+ CURLMstate from_state)
+{
+ (void)from_state;
+ CURLM_NTFY(data, CURLMNOTIFY_EASY_DONE);
}
-static void init_completed(struct Curl_easy *data)
+static void mstate_enter_completed(struct Curl_easy *data,
+ CURLMstate from_state)
{
- /* this is a completed transfer */
+ /* we sometimes directly jump to COMPLETED, trigger things
+ * we then missed. */
+ if(from_state < MSTATE_DID) {
+ Curl_pgrsTime(data, TIMER_PRETRANSFER);
+ Curl_pgrsTime(data, TIMER_POSTRANSFER);
+ Curl_pgrsTime(data, TIMER_STARTTRANSFER);
+ }
+ Curl_pgrsCompleted(data);
+ if(from_state < MSTATE_DONE)
+ CURLM_NTFY(data, CURLMNOTIFY_EASY_DONE);
+ /* changing to COMPLETED means it is in process and needs to go */
+ DEBUGASSERT(Curl_uint32_bset_contains(&data->multi->process, data->mid));
+ Curl_uint32_bset_remove(&data->multi->process, data->mid);
+ Curl_uint32_bset_remove(&data->multi->pending, data->mid); /* to be sure */
+ if(Curl_uint32_bset_empty(&data->multi->process)) {
+ /* free the transfer buffer when we have no more active transfers */
+ multi_xfer_bufs_free(data->multi);
+ }
/* Important: reset the conn pointer so that we do not point to memory
that could be freed anytime */
Curl_detach_connection(data);
@@ -134,23 +170,23 @@ static void mstate(struct Curl_easy *data, CURLMstate state
)
{
CURLMstate oldstate = data->mstate;
- static const init_multistate_func finit[MSTATE_LAST] = {
- NULL, /* INIT */
- NULL, /* PENDING */
- NULL, /* SETUP */
- Curl_init_CONNECT, /* CONNECT */
- NULL, /* CONNECTING */
- NULL, /* PROTOCONNECT */
- NULL, /* PROTOCONNECTING */
- NULL, /* DO */
- NULL, /* DOING */
- NULL, /* DOING_MORE */
- before_perform, /* DID */
- NULL, /* PERFORMING */
- NULL, /* RATELIMITING */
- NULL, /* DONE */
- init_completed, /* COMPLETED */
- NULL /* MSGSENT */
+ static const mstate_enter_func state_enter[MSTATE_LAST] = {
+ NULL, /* INIT */
+ NULL, /* PENDING */
+ NULL, /* SETUP */
+ mstate_enter_connect, /* CONNECT */
+ NULL, /* CONNECTING */
+ NULL, /* PROTOCONNECT */
+ NULL, /* PROTOCONNECTING */
+ NULL, /* DO */
+ NULL, /* DOING */
+ NULL, /* DOING_MORE */
+ mstate_enter_did, /* DID */
+ NULL, /* PERFORMING */
+ NULL, /* RATELIMITING */
+ mstate_enter_done, /* DONE */
+ mstate_enter_completed, /* COMPLETED */
+ NULL /* MSGSENT */
};
if(oldstate == state)
@@ -166,32 +202,8 @@ static void mstate(struct Curl_easy *data, CURLMstate state
/* really switching state */
data->mstate = state;
- switch(state) {
- case MSTATE_DONE:
- CURLM_NTFY(data, CURLMNOTIFY_EASY_DONE);
- break;
- case MSTATE_COMPLETED:
- /* we sometimes directly jump to COMPLETED, trigger also a notification
- * in that case. */
- if(oldstate < MSTATE_DONE)
- CURLM_NTFY(data, CURLMNOTIFY_EASY_DONE);
- /* changing to COMPLETED means it is in process and needs to go */
- DEBUGASSERT(Curl_uint32_bset_contains(&data->multi->process, data->mid));
- Curl_uint32_bset_remove(&data->multi->process, data->mid);
- Curl_uint32_bset_remove(&data->multi->pending, data->mid); /* to be sure */
-
- if(Curl_uint32_bset_empty(&data->multi->process)) {
- /* free the transfer buffer when we have no more active transfers */
- multi_xfer_bufs_free(data->multi);
- }
- break;
- default:
- break;
- }
-
- /* if this state has an init-function, run it */
- if(finit[state])
- finit[state](data);
+ if(state_enter[state])
+ state_enter[state](data, oldstate);
}
#ifndef DEBUGBUILD
lib/progress.c+38 -5
@@ -240,6 +240,30 @@ void Curl_pgrsSendPause(struct Curl_easy *data, bool enable)
}
}
+#ifdef CURLVERBOSE
+static const char * const pgrs_timer_names[] = {
+ "PGRS-NONE",
+ "PGRS-STARTOP",
+ "PGRS-STARTSINGLE",
+ "PGRS-POSTQUEUE",
+ "PGRS-NAMELOOKUP",
+ "PGRS-CONNECT",
+ "PGRS-APPCONNECT",
+ "PGRS-PRETRANSFER",
+ "PGRS-STARTTRANSFER",
+ "PGRS-POSTRANSFER",
+ "PGRS-STARTACCEPT",
+ "PGRS-REDIRECT",
+};
+
+static const char *pgrs_timer_name(timerid timer)
+{
+ if((size_t)timer < CURL_ARRAYSIZE(pgrs_timer_names))
+ return pgrs_timer_names[(size_t)timer];
+ return "?";
+}
+
+#endif /* CURLVERBOSE */
/*
* Curl_pgrsTimeWas(). Store the timestamp time at the given label.
*/
@@ -285,7 +309,6 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer,
delta = &data->progress.t_pretransfer;
break;
case TIMER_STARTTRANSFER:
- delta = &data->progress.t_starttransfer;
/* prevent updating t_starttransfer unless:
* 1. this is the first time we are setting t_starttransfer
* 2. a redirect has occurred since the last time t_starttransfer was set
@@ -293,12 +316,12 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer,
* changing the t_starttransfer time.
*/
if(data->progress.is_t_startransfer_set) {
+ CURL_TRC_M(data, "[%s] ignored", pgrs_timer_name(timer));
return;
}
- else {
- data->progress.is_t_startransfer_set = TRUE;
- break;
- }
+ data->progress.is_t_startransfer_set = TRUE;
+ delta = &data->progress.t_starttransfer;
+ break;
case TIMER_POSTRANSFER:
delta = &data->progress.t_posttransfer;
break;
@@ -314,7 +337,11 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer,
if(us < 1)
us = 1; /* make sure at least one microsecond passed */
*delta += us;
+ CURL_TRC_M(data, "[%s] added %" FMT_TIMEDIFF_T "ns",
+ pgrs_timer_name(timer), us);
}
+ else
+ CURL_TRC_M(data, "[%s] set", pgrs_timer_name(timer));
}
/*
@@ -703,3 +730,9 @@ void Curl_pgrsUpdate_nometer(struct Curl_easy *data)
{
(void)progress_calc(data, Curl_pgrs_now(data));
}
+
+void Curl_pgrsCompleted(struct Curl_easy *data)
+{
+ struct Progress * const p = &data->progress;
+ p->timespent = curlx_ptimediff_us(Curl_pgrs_now(data), &p->start);
+}
lib/progress.h+2 -0
@@ -83,4 +83,6 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer,
void Curl_pgrsEarlyData(struct Curl_easy *data, curl_off_t sent);
+void Curl_pgrsCompleted(struct Curl_easy *data);
+
#endif /* HEADER_CURL_PROGRESS_H */
lib/request.c+2 -1
@@ -271,7 +271,8 @@ static CURLcode req_set_upload_done(struct Curl_easy *data)
data->req.upload_done = TRUE;
CURL_REQ_CLEAR_SEND(data);
- Curl_pgrsTime(data, TIMER_POSTRANSFER);
+ if(data->mstate >= MSTATE_DID)
+ Curl_pgrsTime(data, TIMER_POSTRANSFER);
Curl_creader_done(data, data->req.upload_aborted);
if(data->req.upload_aborted) {
lib/sendf.c+2 -1
@@ -183,7 +183,8 @@ static CURLcode cw_download_write(struct Curl_easy *data,
bool is_connect = !!(type & CLIENTWRITE_CONNECT);
if(!ctx->started_response &&
- !(type & (CLIENTWRITE_INFO | CLIENTWRITE_CONNECT))) {
+ !(type & CLIENTWRITE_CONNECT) &&
+ (!(type & CLIENTWRITE_INFO) || data->req.upload_done)) {
Curl_pgrsTime(data, TIMER_STARTTRANSFER);
ctx->started_response = TRUE;
}
tests/http/testenv/curl.py+2 -17
@@ -540,23 +540,8 @@ class ExecResult:
ref_tl += ['time_namelookup', 'time_connect']
if url.startswith('https:'):
ref_tl += ['time_appconnect']
- # what kind of transfer was it?
- if s['size_upload'] == 0 and s['size_download'] > 0:
- # this is a download
- dl_tl = ['time_pretransfer']
- if s['size_request'] > 0:
- dl_tl = ['time_posttransfer'] + dl_tl
- ref_tl += dl_tl
- # the first byte of the response may arrive before we
- # track the other times when the client is slow (CI).
- somewhere_keys.extend(['time_starttransfer'])
- elif s['size_upload'] > 0 and s['size_download'] == 0:
- # this is an upload
- ul_tl = ['time_pretransfer', 'time_posttransfer']
- ref_tl += ul_tl
- else:
- # could be a 0-length upload or 0-length download, not sure
- exact_match = False
+ ref_tl += ['time_pretransfer', 'time_posttransfer']
+ somewhere_keys.extend(['time_starttransfer'])
# always there at the end
ref_tl += ['time_total']
tests/libtest/lib500.c+1 -4
@@ -127,10 +127,7 @@ static CURLcode test_lib500(const char *URL)
(time_pretransfer / 1000000),
(long)(time_pretransfer % 1000000));
}
- if(time_posttransfer > time_pretransfer) {
- /* counter-intuitive: on a GET request, all bytes are sent *before*
- * PRETRANSFER happens. Thus POSTTRANSFER has to be smaller.
- * The reverse would be true for a POST/PUT. */
+ if(time_pretransfer > time_posttransfer) {
curl_mfprintf(moo, "pretransfer vs posttransfer: %"
CURL_FORMAT_CURL_OFF_T
".%06ld %" CURL_FORMAT_CURL_OFF_T ".%06ld\n",
tests/unit/unit1399.c+51 -32
@@ -25,6 +25,25 @@
#include "urldata.h"
#include "progress.h"
+static CURLcode t1399_setup(struct Curl_easy **easy)
+{
+ CURLcode result = CURLE_OK;
+
+ global_init(CURL_GLOBAL_ALL);
+ *easy = curl_easy_init();
+ if(!*easy) {
+ curl_global_cleanup();
+ return CURLE_OUT_OF_MEMORY;
+ }
+ return result;
+}
+
+static void t1399_stop(struct Curl_easy *easy)
+{
+ curl_easy_cleanup(easy);
+ curl_global_cleanup();
+}
+
/*
* Invoke Curl_pgrsTime for TIMER_STARTSINGLE to trigger the behavior that
* manages is_t_startransfer_set, but fake the t_startsingle time for purposes
@@ -72,45 +91,45 @@ static void expect_timer_seconds(struct Curl_easy *data, int seconds)
* be 3 seconds. */
static CURLcode test_unit1399(const char *arg)
{
- UNITTEST_BEGIN_SIMPLE
-
- struct Curl_easy data;
+ struct Curl_easy *data;
struct curltime now = curlx_now();
- data.multi = NULL;
- data.progress.now = now;
- data.progress.t_nslookup = 0;
- data.progress.t_connect = 0;
- data.progress.t_appconnect = 0;
- data.progress.t_pretransfer = 0;
- data.progress.t_starttransfer = 0;
- data.progress.t_redirect = 0;
- data.progress.start.tv_sec = now.tv_sec - 2;
- data.progress.start.tv_usec = now.tv_usec;
- fake_t_startsingle_time(&data, now, -2);
-
- Curl_pgrsTime(&data, TIMER_NAMELOOKUP);
- Curl_pgrsTime(&data, TIMER_CONNECT);
- Curl_pgrsTime(&data, TIMER_APPCONNECT);
- Curl_pgrsTime(&data, TIMER_PRETRANSFER);
- Curl_pgrsTime(&data, TIMER_STARTTRANSFER);
-
- expect_timer_seconds(&data, 2);
+ UNITTEST_BEGIN(t1399_setup(&data))
+
+ data->multi = NULL;
+ data->progress.now = now;
+ data->progress.t_nslookup = 0;
+ data->progress.t_connect = 0;
+ data->progress.t_appconnect = 0;
+ data->progress.t_pretransfer = 0;
+ data->progress.t_starttransfer = 0;
+ data->progress.t_redirect = 0;
+ data->progress.start.tv_sec = now.tv_sec - 2;
+ data->progress.start.tv_usec = now.tv_usec;
+ fake_t_startsingle_time(data, now, -2);
+
+ Curl_pgrsTime(data, TIMER_NAMELOOKUP);
+ Curl_pgrsTime(data, TIMER_CONNECT);
+ Curl_pgrsTime(data, TIMER_APPCONNECT);
+ Curl_pgrsTime(data, TIMER_PRETRANSFER);
+ Curl_pgrsTime(data, TIMER_STARTTRANSFER);
+
+ expect_timer_seconds(data, 2);
/* now simulate the redirect */
- data.progress.t_redirect = data.progress.t_starttransfer + 1;
- fake_t_startsingle_time(&data, now, -1);
+ data->progress.t_redirect = data->progress.t_starttransfer + 1;
+ fake_t_startsingle_time(data, now, -1);
- Curl_pgrsTime(&data, TIMER_NAMELOOKUP);
- Curl_pgrsTime(&data, TIMER_CONNECT);
- Curl_pgrsTime(&data, TIMER_APPCONNECT);
- Curl_pgrsTime(&data, TIMER_PRETRANSFER);
+ Curl_pgrsTime(data, TIMER_NAMELOOKUP);
+ Curl_pgrsTime(data, TIMER_CONNECT);
+ Curl_pgrsTime(data, TIMER_APPCONNECT);
+ Curl_pgrsTime(data, TIMER_PRETRANSFER);
/* ensure t_starttransfer is only set on the first invocation by attempting
* to set it twice */
- Curl_pgrsTime(&data, TIMER_STARTTRANSFER);
- Curl_pgrsTime(&data, TIMER_STARTTRANSFER);
+ Curl_pgrsTime(data, TIMER_STARTTRANSFER);
+ Curl_pgrsTime(data, TIMER_STARTTRANSFER);
- expect_timer_seconds(&data, 3);
+ expect_timer_seconds(data, 3);
- UNITTEST_END_SIMPLE
+ UNITTEST_END(t1399_stop(data))
}