Mercurial > hg > orthanc

changeset 6099:554b081d8df4

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
In verbose logs, added the elapsed time spent in each HTTP call.
author Alain Mazy <am@orthanc.team>
date Thu, 10 Apr 2025 12:14:17 +0200
parents a25c7c58c356
children 7eaee38747ab
files NEWS OrthancFramework/Sources/HttpServer/HttpServer.cpp OrthancFramework/Sources/Toolbox.cpp OrthancFramework/Sources/Toolbox.h
diffstat 4 files changed, 43 insertions(+), 15 deletions(-) [+]
line wrap: on
line diff
--- a/NEWS	Wed Apr 09 10:10:51 2025 +0200
+++ b/NEWS	Thu Apr 10 12:14:17 2025 +0200
@@ -1,6 +1,12 @@
 Pending changes in the mainline
 ===============================
 
+Maintenance
+-----------
+
+* In verbose logs, added the elapsed time spent in each HTTP call.
+
+
 
 Version 1.12.7 (2025-04-07)
 ===========================
--- a/OrthancFramework/Sources/HttpServer/HttpServer.cpp	Wed Apr 09 10:10:51 2025 +0200
+++ b/OrthancFramework/Sources/HttpServer/HttpServer.cpp	Thu Apr 10 12:14:17 2025 +0200
@@ -1257,10 +1257,12 @@
     
     HttpMethod filterMethod;
 
-    
+    std::unique_ptr<Toolbox::ApiElapsedTimeLogger> apiLogTimer; // to log the time spent in the API call
+
     if (ExtractMethod(method, request, headers, argumentsGET))
     {
-      CLOG(INFO, HTTP) << EnumerationToString(method) << " " << Toolbox::FlattenUri(uri);
+      apiLogTimer.reset(new Toolbox::ApiElapsedTimeLogger(std::string(EnumerationToString(method)) + " " + Toolbox::FlattenUri(uri)));
+      
       filterMethod = method;
     }
 #if ORTHANC_ENABLE_PUGIXML == 1
@@ -1268,8 +1270,7 @@
              !strcmp(request->request_method, "PROPFIND") ||
              !strcmp(request->request_method, "HEAD"))
     {
-      CLOG(INFO, HTTP) << "Incoming read-only WebDAV request: "
-                       << request->request_method << " " << requestUri;
+      apiLogTimer.reset(new Toolbox::ApiElapsedTimeLogger(std::string("Incoming read-only WebDAV request: ") + request->request_method + " " + requestUri));
       filterMethod = HttpMethod_Get;
       isWebDav = true;
     }
@@ -1278,8 +1279,7 @@
              !strcmp(request->request_method, "UNLOCK") ||
              !strcmp(request->request_method, "MKCOL"))
     {
-      CLOG(INFO, HTTP) << "Incoming read-write WebDAV request: "
-                       << request->request_method << " " << requestUri;
+      apiLogTimer.reset(new Toolbox::ApiElapsedTimeLogger(std::string("Incoming read-write WebDAV request: ") + request->request_method + " " + requestUri));
       filterMethod = HttpMethod_Put;
       isWebDav = true;
     }
--- a/OrthancFramework/Sources/Toolbox.cpp	Wed Apr 09 10:10:51 2025 +0200
+++ b/OrthancFramework/Sources/Toolbox.cpp	Thu Apr 10 12:14:17 2025 +0200
@@ -2576,14 +2576,14 @@
     return Toolbox::GetHumanTransferSpeed(full, sizeInBytes, GetElapsedNanoseconds());
   }
 
-  Toolbox::ElapsedTimeLogger::ElapsedTimeLogger(const std::string& message)
+  Toolbox::DebugElapsedTimeLogger::DebugElapsedTimeLogger(const std::string& message)
   : message_(message),
     logged_(false)
   {
     Restart();
   }
 
-  Toolbox::ElapsedTimeLogger::~ElapsedTimeLogger()
+  Toolbox::DebugElapsedTimeLogger::~DebugElapsedTimeLogger()
   {
     if (!logged_)
     {
@@ -2591,17 +2591,29 @@
     }
   }
 
-  void Toolbox::ElapsedTimeLogger::Restart()
+  void Toolbox::DebugElapsedTimeLogger::Restart()
   {
     timer_.Restart();
   }
 
-  void Toolbox::ElapsedTimeLogger::StopAndLog()
+  void Toolbox::DebugElapsedTimeLogger::StopAndLog()
   {
     LOG(WARNING) << "ELAPSED TIMER: " << message_ << " (" << timer_.GetElapsedMicroseconds() << " us)";
     logged_ = true;
   }
 
+  Toolbox::ApiElapsedTimeLogger::ApiElapsedTimeLogger(const std::string& message) :
+    message_(message)
+  {
+    timer_.Restart();
+    CLOG(INFO, HTTP) << message_;
+  }
+  
+  Toolbox::ApiElapsedTimeLogger::~ApiElapsedTimeLogger()
+  {
+    CLOG(INFO, HTTP) << message_ << " (elapsed: " << timer_.GetElapsedMicroseconds() << " us)";
+  }
+
   std::string Toolbox::GetHumanFileSize(uint64_t sizeInBytes)
   {
     if (sizeInBytes < 1024)
--- a/OrthancFramework/Sources/Toolbox.h	Wed Apr 09 10:10:51 2025 +0200
+++ b/OrthancFramework/Sources/Toolbox.h	Thu Apr 10 12:14:17 2025 +0200
@@ -394,23 +394,33 @@
     };
 
     // 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.
+    // This should be used only during debugging and should likely not ever be 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
+    class ORTHANC_PUBLIC DebugElapsedTimeLogger
     {
-    private:
       ElapsedTimer      timer_;
       const std::string message_;
       bool logged_;
 
     public:
-      explicit ElapsedTimeLogger(const std::string& message);
-      ~ElapsedTimeLogger();  
+      explicit DebugElapsedTimeLogger(const std::string& message);
+      ~DebugElapsedTimeLogger();  
 
       void Restart();
       void StopAndLog();
     };
 
+    // This variant logs the same message when entering the method and when exiting (with the elapsed time).
+    // Logs goes to verbose-http.
+    class ORTHANC_PUBLIC ApiElapsedTimeLogger
+    {
+      ElapsedTimer      timer_;
+      const std::string message_;
+    public:
+      explicit ApiElapsedTimeLogger(const std::string& message);
+      ~ApiElapsedTimeLogger();
+    };
+
     static std::string GetHumanFileSize(uint64_t sizeInBytes);
 
     static std::string GetHumanDuration(uint64_t durationInNanoseconds);