From 7698e53b0ba8263643c2bf7f1f95ddee94b2a681 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 a54ebdcf3..64fcbabe0 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 78046450aba39d539a5838e3c31649c4b6c22056 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 64fcbabe0..ccae7e45b 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -857,7 +857,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 c3e907af7d58607d134ff667ddd316b65e8f5efe 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 ccae7e45b..18eb64573 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -859,6 +859,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 dd0412d1b49a86e4f3de45bf72415d8d75f5fd57 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 ddb41e63f..a17a6ea54 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 aa8ff652f..9e9038deb 100644 --- a/src/libfetchers/tarball.cc +++ b/src/libfetchers/tarball.cc @@ -145,6 +145,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 @@ -169,6 +172,8 @@ DownloadTarballResult downloadTarball( auto parseSink = getTarballCache()->getFileSystemObjectSink(); auto lastModified = unpackTarfileToSink(archive, *parseSink); + act.reset(); + auto res(_res->lock()); Attrs infoAttrs;