From cfef5cacda94622438c1ec094854a500fe91f4c4 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Wed, 24 Jul 2024 20:10:41 +0200 Subject: [PATCH 1/4] Log download durations (cherry picked from commit caf4e98f0c0a0a7178538ee8ef7b199d2a655aac) --- src/libstore/filetransfer.cc | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/libstore/filetransfer.cc b/src/libstore/filetransfer.cc index 219b60c44..386587682 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -70,7 +70,10 @@ struct curlFileTransfer : public FileTransfer curl_off_t writtenToSink = 0; + std::chrono::steady_clock::time_point startTime = std::chrono::steady_clock::now(); + inline static const std::set successfulStatuses {200, 201, 204, 206, 304, 0 /* other protocol */}; + /* Get the HTTP status code, or 0 for other protocols. */ long getHTTPStatus() { @@ -372,10 +375,14 @@ struct curlFileTransfer : public FileTransfer void finish(CURLcode code) { + auto finishTime = std::chrono::steady_clock::now(); + auto httpStatus = getHTTPStatus(); - debug("finished %s of '%s'; curl status = %d, HTTP status = %d, body = %d bytes", - request.verb(), request.uri, code, httpStatus, result.bodySize); + debug("finished %s of '%s'; curl status = %d, HTTP status = %d, body = %d bytes, duration = %.2f s", + request.verb(), request.uri, code, httpStatus, result.bodySize, + std::chrono::duration_cast(finishTime - startTime).count() / 1000.0f + ); appendCurrentUrl(); From a57ded2403eb54b6705b1a5d5e03dff318996040 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Wed, 24 Jul 2024 20:10:45 +0200 Subject: [PATCH 2/4] Add 'download-buffer-size' setting We are piping curl downloads into `unpackTarfileToSink()`, but the latter is typically slower than the former if you're on a fast connection. So the download could appear unnecessarily slow. (There is even a risk that if the Git import is *really* slow for whatever reason, the TCP connection could time out.) So let's make the download buffer bigger by default - 64 MiB is big enough for the Nixpkgs tarball. Perhaps in the future, we could have an unlimited buffer that spills data to disk beyond a certain threshold, but that's probably overkill. (cherry picked from commit 8ffea0a018874e60584eabeb620ec3495873c30d) --- src/libstore/filetransfer.cc | 2 +- src/libstore/filetransfer.hh | 6 ++++++ 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/src/libstore/filetransfer.cc b/src/libstore/filetransfer.cc index 386587682..9641c252e 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -852,7 +852,7 @@ void FileTransfer::download( buffer). We don't wait forever to prevent stalling the download thread. (Hopefully sleeping will throttle the sender.) */ - if (state->data.size() > 1024 * 1024) { + if (state->data.size() > fileTransferSettings.downloadBufferSize) { debug("download buffer is full; going to sleep"); state.wait_for(state->request, std::chrono::seconds(10)); } diff --git a/src/libstore/filetransfer.hh b/src/libstore/filetransfer.hh index 1c271cbec..221a2b0ea 100644 --- a/src/libstore/filetransfer.hh +++ b/src/libstore/filetransfer.hh @@ -45,6 +45,12 @@ struct FileTransferSettings : Config Setting tries{this, 5, "download-attempts", "How often Nix will attempt to download a file before giving up."}; + + Setting downloadBufferSize{this, 64 * 1024 * 1024, "download-buffer-size", + R"( + The size of Nix's internal download buffer during `curl` transfers. If data is + not processed quickly enough to exceed the size of this buffer, downloads may stall. + )"}; }; extern FileTransferSettings fileTransferSettings; From 331bcdb8310df08bd43548f67005ad6c7b6a2b39 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Wed, 24 Jul 2024 20:14:31 +0200 Subject: [PATCH 3/4] Warn if the download buffer is full (cherry picked from commit f6a9a71b38b25d6c9fb0b9a7fbf0eccf99fa5520) --- src/libstore/filetransfer.cc | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/libstore/filetransfer.cc b/src/libstore/filetransfer.cc index 9641c252e..bc1f86acf 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -854,6 +854,8 @@ void FileTransfer::download( sender.) */ if (state->data.size() > fileTransferSettings.downloadBufferSize) { debug("download buffer is full; going to sleep"); + static bool haveWarned = false; + warnOnce(haveWarned, "download buffer is full; consider increasing the 'download-buffer-size' setting"); state.wait_for(state->request, std::chrono::seconds(10)); } From 8a80f8a6ac9c9e779dd9038b4c0b3aab0ddf9955 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Wed, 24 Jul 2024 20:22:26 +0200 Subject: [PATCH 4/4] Show when we're unpacking an archive into the Git cache This happens in parallel with the download (which starts later), so you only see this message when the download has finished but the import hasn't. (cherry picked from commit 01839b525c5e80d7f67f2808f7f7fb478ddf1ba0) --- src/libfetchers/github.cc | 5 +++++ src/libfetchers/tarball.cc | 5 +++++ 2 files changed, 10 insertions(+) diff --git a/src/libfetchers/github.cc b/src/libfetchers/github.cc index 985f2e479..07d7e15fe 100644 --- a/src/libfetchers/github.cc +++ b/src/libfetchers/github.cc @@ -248,10 +248,15 @@ struct GitArchiveInputScheme : InputScheme getFileTransfer()->download(std::move(req), sink); }); + auto act = std::make_unique(*logger, lvlInfo, actUnknown, + fmt("unpacking '%s' into the Git cache", input.to_string())); + TarArchive archive { *source }; auto parseSink = getTarballCache()->getFileSystemObjectSink(); auto lastModified = unpackTarfileToSink(archive, *parseSink); + act.reset(); + TarballInfo tarballInfo { .treeHash = parseSink->sync(), .lastModified = lastModified diff --git a/src/libfetchers/tarball.cc b/src/libfetchers/tarball.cc index 2d05eb41d..3acf96e20 100644 --- a/src/libfetchers/tarball.cc +++ b/src/libfetchers/tarball.cc @@ -155,6 +155,9 @@ DownloadTarballResult downloadTarball( // TODO: fall back to cached value if download fails. + auto act = std::make_unique(*logger, lvlInfo, actUnknown, + fmt("unpacking '%s' into the Git cache", url)); + AutoDelete cleanupTemp; /* Note: if the download is cached, `importTarball()` will receive @@ -179,6 +182,8 @@ DownloadTarballResult downloadTarball( auto parseSink = getTarballCache()->getFileSystemObjectSink(); auto lastModified = unpackTarfileToSink(archive, *parseSink); + act.reset(); + auto res(_res->lock()); Attrs infoAttrs;