Mercurial > hg > orthanc

changeset 5430:b83192e7ad10

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
Now displaying timings when reading from/writing to disk in the verbose logs
author Alain Mazy <am@osimis.io>
date Mon, 20 Nov 2023 17:01:48 +0100
parents d40ac28b9702
children 4be5f117aa0d
files NEWS OrthancFramework/Sources/FileStorage/FilesystemStorage.cpp OrthancFramework/Sources/FileStorage/MemoryStorageArea.cpp OrthancFramework/Sources/Toolbox.cpp OrthancFramework/Sources/Toolbox.h OrthancFramework/UnitTestsSources/ToolboxTests.cpp OrthancServer/Sources/OrthancRestApi/OrthancRestApi.cpp OrthancServer/Sources/ServerIndex.cpp OrthancServer/Sources/ServerJobs/ArchiveJob.cpp
diffstat 9 files changed, 208 insertions(+), 22 deletions(-) [+]
line wrap: on
line diff
--- 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"
--- 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);
   }
 
--- 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<int>(type)
-              << "\" type (size: " << (size / (1024 * 1024) + 1) << "MB)";
+              << "\" type (size: " << Toolbox::GetHumanFileSize(size) << ")";
 
     Mutex::ScopedLock lock(mutex_);
 
--- 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<uint64_t>(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<double>(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<double>(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<double>(sizeInBytes) / static_cast<double>(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();
+    }
+  }
+
 
 }
 
--- 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);
+
   };
 }
 
--- 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
--- 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<uint64_t>(call.GetBodySize())) << " through HTTP";
 
     if (call.GetBodySize() == 0)
     {
--- 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";
       }
     }
 
--- 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;