# HG changeset patch # User Alain Mazy # Date 1700496108 -3600 # Node ID b83192e7ad10db33330ac200b6cbd297aa6739cc # Parent d40ac28b97021c91d98b4ece9e9dfa931f8e51bc Now displaying timings when reading from/writing to disk in the verbose logs diff -r d40ac28b9702 -r b83192e7ad10 NEWS --- a/NEWS Fri Nov 17 13:56:13 2023 +0100 +++ b/NEWS Mon Nov 20 17:01:48 2023 +0100 @@ -12,6 +12,7 @@ multiple users request the same file at the same time. - The StorageCache is now also storing transcoded instances that have been requested by /file?transcode=... that is now used by the DICOMweb plugin. This speeds up retrieval of transcoded frames through WADO-RS. + - Now displaying timings when reading from/writing to disk in the verbose logs. * Housekeeper plugin: - Update to rebuild the cache of the DICOMweb plugin when updating to DICOMweb 1.15. - New trigger configuration: "DicomWebCacheChange" diff -r d40ac28b9702 -r b83192e7ad10 OrthancFramework/Sources/FileStorage/FilesystemStorage.cpp --- a/OrthancFramework/Sources/FileStorage/FilesystemStorage.cpp Fri Nov 17 13:56:13 2023 +0100 +++ b/OrthancFramework/Sources/FileStorage/FilesystemStorage.cpp Mon Nov 20 17:01:48 2023 +0100 @@ -122,16 +122,9 @@ size_t size, FileContentType type) { - if (size > (1024 * 1024)) - { - LOG(INFO) << "Creating attachment \"" << uuid << "\" of \"" << GetDescriptionInternal(type) - << "\" type (size: " << (size / (1024 * 1024) + 1) << "MB)"; - } - else - { - LOG(INFO) << "Creating attachment \"" << uuid << "\" of \"" << GetDescriptionInternal(type) - << "\" type (size: " << (size / 1024 + 1) << "KB)"; - } + Toolbox::ElapsedTimer timer; + LOG(INFO) << "Creating attachment \"" << uuid << "\" of \"" << GetDescriptionInternal(type) + << "\" type"; boost::filesystem::path path; @@ -160,18 +153,22 @@ } SystemToolbox::WriteFile(content, size, path.string(), fsyncOnWrite_); + LOG(INFO) << "Created attachment \"" << uuid << "\" (" << timer.GetHumanTransferSpeed(true, size) << ")"; } IMemoryBuffer* FilesystemStorage::Read(const std::string& uuid, FileContentType type) { + Toolbox::ElapsedTimer timer; LOG(INFO) << "Reading attachment \"" << uuid << "\" of \"" << GetDescriptionInternal(type) << "\" content type"; std::string content; SystemToolbox::ReadFile(content, GetPath(uuid).string()); + LOG(INFO) << "Read attachment \"" << uuid << "\" (" << timer.GetHumanTransferSpeed(true, content.size()) << ")"; + return StringMemoryBuffer::CreateFromSwap(content); } @@ -181,6 +178,7 @@ uint64_t start /* inclusive */, uint64_t end /* exclusive */) { + Toolbox::ElapsedTimer timer; LOG(INFO) << "Reading attachment \"" << uuid << "\" of \"" << GetDescriptionInternal(type) << "\" content type (range from " << start << " to " << end << ")"; @@ -188,6 +186,7 @@ SystemToolbox::ReadFileRange( content, GetPath(uuid).string(), start, end, true /* throw if overflow */); + LOG(INFO) << "Read range of attachment \"" << uuid << "\" (" << timer.GetHumanTransferSpeed(true, content.size()) << ")"; return StringMemoryBuffer::CreateFromSwap(content); } diff -r d40ac28b9702 -r b83192e7ad10 OrthancFramework/Sources/FileStorage/MemoryStorageArea.cpp --- a/OrthancFramework/Sources/FileStorage/MemoryStorageArea.cpp Fri Nov 17 13:56:13 2023 +0100 +++ b/OrthancFramework/Sources/FileStorage/MemoryStorageArea.cpp Mon Nov 20 17:01:48 2023 +0100 @@ -27,6 +27,7 @@ #include "../Logging.h" #include "../OrthancException.h" #include "../StringMemoryBuffer.h" +#include "../Toolbox.h" namespace Orthanc { @@ -47,7 +48,7 @@ FileContentType type) { LOG(INFO) << "Creating attachment \"" << uuid << "\" of \"" << static_cast(type) - << "\" type (size: " << (size / (1024 * 1024) + 1) << "MB)"; + << "\" type (size: " << Toolbox::GetHumanFileSize(size) << ")"; Mutex::ScopedLock lock(mutex_); diff -r d40ac28b9702 -r b83192e7ad10 OrthancFramework/Sources/Toolbox.cpp --- a/OrthancFramework/Sources/Toolbox.cpp Fri Nov 17 13:56:13 2023 +0100 +++ b/OrthancFramework/Sources/Toolbox.cpp Mon Nov 20 17:01:48 2023 +0100 @@ -2514,6 +2514,45 @@ } } + Toolbox::ElapsedTimer::ElapsedTimer() + { + Restart(); + } + + void Toolbox::ElapsedTimer::Restart() + { + start_ = boost::posix_time::microsec_clock::universal_time(); + } + + uint64_t Toolbox::ElapsedTimer::GetElapsedMilliseconds() + { + return GetElapsedNanoseconds() / 1000000; + } + + uint64_t Toolbox::ElapsedTimer::GetElapsedMicroseconds() + { + return GetElapsedNanoseconds() / 1000; + } + + uint64_t Toolbox::ElapsedTimer::GetElapsedNanoseconds() + { + boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time(); + boost::posix_time::time_duration diff = now - start_; + return static_cast(diff.total_nanoseconds()); + } + + std::string Toolbox::ElapsedTimer::GetHumanElapsedDuration() + { + return Toolbox::GetHumanDuration(GetElapsedNanoseconds()); + } + + // in "full" mode, returns " 26.45MB in 2.25s = 94.04Mbps" + // else, returns "94.04Mbps" + std::string Toolbox::ElapsedTimer::GetHumanTransferSpeed(bool full, uint64_t sizeInBytes) + { + return Toolbox::GetHumanTransferSpeed(full, sizeInBytes, GetElapsedNanoseconds()); + } + Toolbox::ElapsedTimeLogger::ElapsedTimeLogger(const std::string& message) : message_(message), logged_(false) @@ -2531,17 +2570,111 @@ void Toolbox::ElapsedTimeLogger::Restart() { - start_ = boost::posix_time::microsec_clock::universal_time(); + timer_.Restart(); } void Toolbox::ElapsedTimeLogger::StopAndLog() { - boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time(); - boost::posix_time::time_duration diff = now - start_; - LOG(WARNING) << "ELAPSED TIMER: " << message_ << " (" << diff.total_microseconds() << " us)"; + LOG(WARNING) << "ELAPSED TIMER: " << message_ << " (" << timer_.GetElapsedMicroseconds() << " us)"; logged_ = true; } + std::string Toolbox::GetHumanFileSize(uint64_t sizeInBytes) + { + if (sizeInBytes < 1024) + { + std::ostringstream oss; + oss << sizeInBytes << "bytes"; + return oss.str(); + } + else + { + static const char* suffixes[] = {"KB", "MB", "GB", "TB"}; + static const int suffixesCount = sizeof(suffixes) / sizeof(suffixes[0]); + + int i = 0; + double size = static_cast(sizeInBytes)/1024.0; + + while (size >= 1024.0 && i < suffixesCount - 1) + { + size /= 1024.0; + i++; + } + + std::ostringstream oss; + oss << std::fixed << std::setprecision(2) << size << suffixes[i]; + return oss.str(); + } + } + + std::string Toolbox::GetHumanDuration(uint64_t durationInNanoseconds) + { + if (durationInNanoseconds < 1024) + { + std::ostringstream oss; + oss << durationInNanoseconds << "ns"; + return oss.str(); + } + else + { + static const char* suffixes[] = {"ns", "us", "ms", "s"}; + static const int suffixesCount = sizeof(suffixes) / sizeof(suffixes[0]); + + int i = 0; + double duration = static_cast(durationInNanoseconds); + + while (duration >= 1000.0 && i < suffixesCount - 1) + { + duration /= 1000.0; + i++; + } + + std::ostringstream oss; + oss << std::fixed << std::setprecision(2) << duration << suffixes[i]; + return oss.str(); + } + } + + std::string Toolbox::GetHumanTransferSpeed(bool full, uint64_t sizeInBytes, uint64_t durationInNanoseconds) + { + // in "full" mode, returns " 26.45MB in 2.25s = 94.04Mbps" + // else, return "94.04Mbps" + + if (full) + { + std::ostringstream oss; + oss << Toolbox::GetHumanFileSize(sizeInBytes) << " in " << Toolbox::GetHumanDuration(durationInNanoseconds) << " = " << GetHumanTransferSpeed(false, sizeInBytes, durationInNanoseconds); + return oss.str(); + } + + double throughputInBps = 8.0 * 1000000000.0 * static_cast(sizeInBytes) / static_cast(durationInNanoseconds); + + if (throughputInBps < 1000.0) + { + std::ostringstream oss; + oss << throughputInBps << "bps"; + return oss.str(); + } + else + { + throughputInBps /= 1000.0; + static const char* suffixes[] = {"kbps", "Mbps", "Gbps"}; + static const int suffixesCount = sizeof(suffixes) / sizeof(suffixes[0]); + + int i = 0; + + while (throughputInBps >= 1000.0 && i < suffixesCount - 1) + { + throughputInBps /= 1000.0; + i++; + } + + std::ostringstream oss; + oss << std::fixed << std::setprecision(2) << throughputInBps << suffixes[i]; + return oss.str(); + } + } + } diff -r d40ac28b9702 -r b83192e7ad10 OrthancFramework/Sources/Toolbox.h --- a/OrthancFramework/Sources/Toolbox.h Fri Nov 17 13:56:13 2023 +0100 +++ b/OrthancFramework/Sources/Toolbox.h Mon Nov 20 17:01:48 2023 +0100 @@ -376,14 +376,30 @@ static void RemoveSurroundingQuotes(std::string& value); + class ORTHANC_PUBLIC ElapsedTimer + { + boost::posix_time::ptime start_; + public: + explicit ElapsedTimer(); + + uint64_t GetElapsedMilliseconds(); + uint64_t GetElapsedMicroseconds(); + uint64_t GetElapsedNanoseconds(); + + std::string GetHumanElapsedDuration(); + std::string GetHumanTransferSpeed(bool full, uint64_t sizeInBytes); + + void Restart(); + }; + // This is a helper class to measure and log time spend e.g in a method. // This should be used only during debugging and should likely not ever used in a release. // By default, you should use it as a RAII but you may force Restart/StopAndLog manually if needed. class ORTHANC_PUBLIC ElapsedTimeLogger { private: - const std::string message_; - boost::posix_time::ptime start_; + ElapsedTimer timer_; + const std::string message_; bool logged_; public: @@ -394,6 +410,12 @@ void StopAndLog(); }; + static std::string GetHumanFileSize(uint64_t sizeInBytes); + + static std::string GetHumanDuration(uint64_t durationInNanoseconds); + + static std::string GetHumanTransferSpeed(bool full, uint64_t sizeInBytes, uint64_t durationInNanoseconds); + }; } diff -r d40ac28b9702 -r b83192e7ad10 OrthancFramework/UnitTestsSources/ToolboxTests.cpp --- a/OrthancFramework/UnitTestsSources/ToolboxTests.cpp Fri Nov 17 13:56:13 2023 +0100 +++ b/OrthancFramework/UnitTestsSources/ToolboxTests.cpp Mon Nov 20 17:01:48 2023 +0100 @@ -374,4 +374,36 @@ ASSERT_EQ("http://test.org:8042", Toolbox::JoinUri("http://test.org:8042", "")); ASSERT_EQ("http://test.org:8042/", Toolbox::JoinUri("http://test.org:8042/", "")); +} + +TEST(Toolbox, GetHumanFileSize) +{ + ASSERT_EQ("234bytes", Toolbox::GetHumanFileSize(234)); + ASSERT_EQ("2.29KB", Toolbox::GetHumanFileSize(2345)); + ASSERT_EQ("22.91KB", Toolbox::GetHumanFileSize(23456)); + ASSERT_EQ("229.07KB", Toolbox::GetHumanFileSize(234567)); + ASSERT_EQ("2.24MB", Toolbox::GetHumanFileSize(2345678)); + ASSERT_EQ("22.37MB", Toolbox::GetHumanFileSize(23456789)); + ASSERT_EQ("223.70MB", Toolbox::GetHumanFileSize(234567890)); + ASSERT_EQ("2.18GB", Toolbox::GetHumanFileSize(2345678901)); + ASSERT_EQ("21.33TB", Toolbox::GetHumanFileSize(23456789012345)); +} + +TEST(Toolbox, GetHumanDuration) +{ + ASSERT_EQ("234ns", Toolbox::GetHumanDuration(234)); + ASSERT_EQ("2.35us", Toolbox::GetHumanDuration(2345)); + ASSERT_EQ("23.46us", Toolbox::GetHumanDuration(23456)); + ASSERT_EQ("234.57us", Toolbox::GetHumanDuration(234567)); + ASSERT_EQ("2.35ms", Toolbox::GetHumanDuration(2345678)); + ASSERT_EQ("2.35s", Toolbox::GetHumanDuration(2345678901)); + ASSERT_EQ("23456.79s", Toolbox::GetHumanDuration(23456789012345)); +} + +TEST(Toolbox, GetHumanTransferSpeed) +{ + ASSERT_EQ("8.00Mbps", Toolbox::GetHumanTransferSpeed(false, 1000, 1000000)); + ASSERT_EQ("8.59Gbps", Toolbox::GetHumanTransferSpeed(false, 1024*1024*1024, 1000000000)); + ASSERT_EQ("1.00GB in 1.00s = 8.59Gbps", Toolbox::GetHumanTransferSpeed(true, 1024*1024*1024, 1000000000)); + ASSERT_EQ("976.56KB in 1.00s = 8.00Mbps", Toolbox::GetHumanTransferSpeed(true, 1000*1000, 1000000000)); } \ No newline at end of file diff -r d40ac28b9702 -r b83192e7ad10 OrthancServer/Sources/OrthancRestApi/OrthancRestApi.cpp --- a/OrthancServer/Sources/OrthancRestApi/OrthancRestApi.cpp Fri Nov 17 13:56:13 2023 +0100 +++ b/OrthancServer/Sources/OrthancRestApi/OrthancRestApi.cpp Mon Nov 20 17:01:48 2023 +0100 @@ -160,7 +160,7 @@ ServerContext& context = OrthancRestApi::GetContext(call); - CLOG(INFO, HTTP) << "Receiving a DICOM file of " << call.GetBodySize() << " bytes through HTTP"; + CLOG(INFO, HTTP) << "Receiving a DICOM file of " << Toolbox::GetHumanFileSize(static_cast(call.GetBodySize())) << " through HTTP"; if (call.GetBodySize() == 0) { diff -r d40ac28b9702 -r b83192e7ad10 OrthancServer/Sources/ServerIndex.cpp --- a/OrthancServer/Sources/ServerIndex.cpp Fri Nov 17 13:56:13 2023 +0100 +++ b/OrthancServer/Sources/ServerIndex.cpp Mon Nov 20 17:01:48 2023 +0100 @@ -36,8 +36,6 @@ #include "ServerToolbox.h" -static const uint64_t MEGA_BYTES = 1024 * 1024; - namespace Orthanc { class ServerIndex::TransactionContext : public StatelessDatabaseOperations::ITransactionContext @@ -402,7 +400,7 @@ } else { - LOG(WARNING) << "At most " << (size / MEGA_BYTES) << "MB will be used for the storage area"; + LOG(WARNING) << "At most " << Toolbox::GetHumanFileSize(size) << " will be used for the storage area"; } } diff -r d40ac28b9702 -r b83192e7ad10 OrthancServer/Sources/ServerJobs/ArchiveJob.cpp --- a/OrthancServer/Sources/ServerJobs/ArchiveJob.cpp Fri Nov 17 13:56:13 2023 +0100 +++ b/OrthancServer/Sources/ServerJobs/ArchiveJob.cpp Mon Nov 20 17:01:48 2023 +0100 @@ -71,7 +71,7 @@ countInstances >= 65535 - FILES_MARGIN); LOG(INFO) << "Creating a ZIP file with " << countInstances << " files of size " - << (uncompressedSize / MEGA_BYTES) << "MB using the " + << Toolbox::GetHumanFileSize(uncompressedSize) << " using the " << (isZip64 ? "ZIP64" : "ZIP32") << " file format"; return isZip64;