From d8bbc2dd00eddd2c36a6a718f7e21e6e7d4f26e5 Mon Sep 17 00:00:00 2001 From: "Richard W.M. Jones" Date: Tue, 25 Jul 2023 21:45:31 +0100 Subject: [PATCH] curl: Add -D curl.times=1 to collect time statistics (cherry picked from commit 68dddbeb584fb9385915846d259563f74338ffe8) --- plugins/curl/Makefile.am | 1 + plugins/curl/curl.c | 3 + plugins/curl/curldefs.h | 13 +++ plugins/curl/nbdkit-curl-plugin.pod | 21 +++++ plugins/curl/pool.c | 2 + plugins/curl/times.c | 130 ++++++++++++++++++++++++++++ 6 files changed, 170 insertions(+) create mode 100644 plugins/curl/times.c diff --git a/plugins/curl/Makefile.am b/plugins/curl/Makefile.am index 82c09582..f5f1cc1a 100644 --- a/plugins/curl/Makefile.am +++ b/plugins/curl/Makefile.am @@ -42,6 +42,7 @@ nbdkit_curl_plugin_la_SOURCES = \ curl.c \ pool.c \ scripts.c \ + times.c \ $(top_srcdir)/include/nbdkit-plugin.h \ $(NULL) diff --git a/plugins/curl/curl.c b/plugins/curl/curl.c index 3557fd53..0d1fcfee 100644 --- a/plugins/curl/curl.c +++ b/plugins/curl/curl.c @@ -119,6 +119,7 @@ curl_unload (void) curl_slist_free_all (resolves); scripts_unload (); unload_pool (); + display_times (); curl_global_cleanup (); } @@ -639,6 +640,7 @@ curl_pread (void *handle, void *buf, uint32_t count, uint64_t offset) display_curl_error (ch, r, "pread: curl_easy_perform"); return -1; } + update_times (ch->c); /* Could use curl_easy_getinfo here to obtain further information * about the connection. @@ -683,6 +685,7 @@ curl_pwrite (void *handle, const void *buf, uint32_t count, uint64_t offset) display_curl_error (ch, r, "pwrite: curl_easy_perform"); return -1; } + update_times (ch->c); /* Could use curl_easy_getinfo here to obtain further information * about the connection. diff --git a/plugins/curl/curldefs.h b/plugins/curl/curldefs.h index 4506f3e1..dd9791aa 100644 --- a/plugins/curl/curldefs.h +++ b/plugins/curl/curldefs.h @@ -44,6 +44,15 @@ #if CURL_AT_LEAST_VERSION (7, 55, 0) #define HAVE_CURLINFO_CONTENT_LENGTH_DOWNLOAD_T #endif +#if CURL_AT_LEAST_VERSION (7, 61, 0) +#define HAVE_CURLINFO_NAMELOOKUP_TIME_T +#define HAVE_CURLINFO_CONNECT_TIME_T +#define HAVE_CURLINFO_APPCONNECT_TIME_T +#define HAVE_CURLINFO_PRETRANSFER_TIME_T +#define HAVE_CURLINFO_STARTTRANSFER_TIME_T +#define HAVE_CURLINFO_TOTAL_TIME_T +#define HAVE_CURLINFO_REDIRECT_TIME_T +#endif #endif extern const char *url; @@ -131,6 +140,10 @@ extern void put_handle (struct curl_handle *ch); extern int do_scripts (struct curl_handle *ch); extern void scripts_unload (void); +/* times.c */ +extern void update_times (CURL *c); /* called after every curl_easy_perform */ +extern void display_times (void); + /* Translate CURLcode to nbdkit_error. */ #define display_curl_error(ch, r, fs, ...) \ do { \ diff --git a/plugins/curl/nbdkit-curl-plugin.pod b/plugins/curl/nbdkit-curl-plugin.pod index a7315047..0fd688ed 100644 --- a/plugins/curl/nbdkit-curl-plugin.pod +++ b/plugins/curl/nbdkit-curl-plugin.pod @@ -543,6 +543,27 @@ This prints out the headers and cookies generated by the C and C options, which can be useful when debugging these scripts. +=item B<-D curl.times=1> + +This prints out additional information about the total time taken to +do name resolution, connect to the remote server, etc. The +information is printed in the debug output before nbdkit exits. The +output will look like: + + nbdkit: debug: times (-D curl.times=1): + nbdkit: debug: name resolution : 0.128442 s + nbdkit: debug: connection : 4.945213 s + nbdkit: debug: SSL negotiation : 4.291362 s + nbdkit: debug: pretransfer : 0.104137 s + nbdkit: debug: first byte received : 56.115269 s + nbdkit: debug: data transfer : 222.633831 s + nbdkit: debug: redirection time : 0.000000 s + +The cumulative time taken to perform each step is shown (summed across +all HTTP connections). The redirection time is the total time taken +doing HTTP redirections. For further information see +L. + =item B<-D curl.verbose=1> This enables very verbose curl debugging. See L. diff --git a/plugins/curl/pool.c b/plugins/curl/pool.c index f91cdf57..10f9011d 100644 --- a/plugins/curl/pool.c +++ b/plugins/curl/pool.c @@ -475,6 +475,7 @@ get_content_length_accept_range (struct curl_handle *ch) display_curl_error (ch, r, "problem doing HEAD request to fetch size of URL [%s]", url); + update_times (ch->c); /* Get the HTTP status code, if available. */ r = curl_easy_getinfo (ch->c, CURLINFO_RESPONSE_CODE, &code); @@ -569,6 +570,7 @@ try_fallback_GET_method (struct curl_handle *ch) curl_easy_setopt (ch->c, CURLOPT_WRITEFUNCTION, error_cb); curl_easy_setopt (ch->c, CURLOPT_WRITEDATA, ch); r = curl_easy_perform (ch->c); + update_times (ch->c); /* We expect CURLE_WRITE_ERROR here, but CURLE_OK is possible too * (eg if the remote has zero length). Other errors might happen diff --git a/plugins/curl/times.c b/plugins/curl/times.c new file mode 100644 index 00000000..8cc4cf27 --- /dev/null +++ b/plugins/curl/times.c @@ -0,0 +1,130 @@ +/* nbdkit + * Copyright Red Hat + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions are + * met: + * + * * Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * + * * Redistributions in binary form must reproduce the above copyright + * notice, this list of conditions and the following disclaimer in the + * documentation and/or other materials provided with the distribution. + * + * * Neither the name of Red Hat nor the names of its contributors may be + * used to endorse or promote products derived from this software without + * specific prior written permission. + * + * THIS SOFTWARE IS PROVIDED BY RED HAT AND CONTRIBUTORS ''AS IS'' AND + * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, + * THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A + * PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL RED HAT OR + * CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, + * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT + * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF + * USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND + * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, + * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT + * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF + * SUCH DAMAGE. + */ + +#include + +#include +#include +#include +#include +#include + +#include + +#include + +#include "array-size.h" + +#include "curldefs.h" + +/* Use '-D curl.times=1' to set. */ +NBDKIT_DLL_PUBLIC int curl_debug_times = 0; + +/* The cumulative times. */ +static struct { + bool cumulative; + const char *name; + CURLINFO info; + curl_off_t t; +} times[] = { +#ifdef HAVE_CURLINFO_NAMELOOKUP_TIME_T + { true, "name resolution", CURLINFO_NAMELOOKUP_TIME_T }, +#endif +#ifdef HAVE_CURLINFO_CONNECT_TIME_T + { true, "connection", CURLINFO_CONNECT_TIME_T }, +#endif +#ifdef HAVE_CURLINFO_APPCONNECT_TIME_T + { true, "SSL negotiation", CURLINFO_APPCONNECT_TIME_T }, +#endif +#ifdef HAVE_CURLINFO_PRETRANSFER_TIME_T + { true, "pretransfer", CURLINFO_PRETRANSFER_TIME_T }, +#endif +#ifdef HAVE_CURLINFO_STARTTRANSFER_TIME_T + { true, "first byte received", CURLINFO_STARTTRANSFER_TIME_T }, +#endif +#ifdef HAVE_CURLINFO_TOTAL_TIME_T + { true, "data transfer", CURLINFO_TOTAL_TIME_T }, +#endif +#ifdef HAVE_CURLINFO_REDIRECT_TIME_T + { false, "redirection time", CURLINFO_REDIRECT_TIME_T }, +#endif +}; + +/* This is called after every curl_easy_perform. If -D curl.times=1 + * then we update the time counters. Refer to curl_easy_getinfo(3) + * section "TIMES". + */ +void +update_times (CURL *c) +{ + size_t i; + CURLcode r; + curl_off_t t; + + if (!curl_debug_times) return; + + for (i = 0; i < ARRAY_SIZE (times); ++i) { + r = curl_easy_getinfo (c, times[i].info, &t); + if (r != CURLE_OK) { + nbdkit_debug ("curl_easy_getinfo: error getting time '%s': %s", + times[i].name, curl_easy_strerror (r)); + continue; + } + if (curl_debug_verbose) + nbdkit_debug ("time '%s': %" PRIi64, times[i].name, (int64_t) t); + times[i].t += t; + } +} + +/* Called when the plugin is unloaded. */ +void +display_times (void) +{ + size_t i; + int64_t prev_t = 0, t, v; + + if (!curl_debug_times) return; + + nbdkit_debug ("times (-D curl.times=1):"); + for (i = 0; i < ARRAY_SIZE (times); ++i) { + t = times[i].t; /* in microseconds */ + if (times[i].cumulative) + v = t - prev_t; + else + v = t; + prev_t = t; + + nbdkit_debug ("%-30s: %3" PRIi64 ".%06" PRIi64 " s", + times[i].name, + v / 1000000, v % 1000000); + } +} -- 2.39.3