From: Bill Erickson <berickxx@gmail.com>
Date: Mon, 23 Feb 2015 22:23:14 +0000 (-0500)
Subject: LP#1425135 Log message duration w/ millisecond granularity
X-Git-Url: https://old-git.evergreen-ils.org/?a=commitdiff_plain;h=cffea8a217a1bc0b8de1714e291a098eefda4e75;p=working%2FSIPServer.git

LP#1425135 Log message duration w/ millisecond granularity

Log message processing duration with finer granularity.  This is
especially useful for diagnosing SIP speed issues for automated
materials handling, where small changes in speed can have a big impact.

New message logs at DEBUG level.

Signed-off-by: Bill Erickson <berickxx@gmail.com>
Signed-off-by: Galen Charlton <gmc@esilibrary.com>
---

diff --git a/SIPServer.pm b/SIPServer.pm
index 9e598b6..30ed53d 100755
--- a/SIPServer.pm
+++ b/SIPServer.pm
@@ -685,12 +685,16 @@ sub sip_protocol_loop {
         alarm 0; # Don't timeout while we are processing
         $input =~ s/[\r\n]+$//sm;    # Strip off any trailing line ends
 
+        my $start = time;
         my $status = Sip::MsgType::handle($input, $self, $expect);
         if ($status eq REQUEST_ACS_RESEND) {
             alarm $timeout;
             next;
         }
 
+        my $duration = sprintf("%0.3f", time - $start);
+        syslog('LOG_DEBUG', "SIP processing duration $duration : $input");
+
         if (!$status) {
             syslog("LOG_ERR", "raw_transport: failed to handle %s", substr($input,0,2));
             die "sip_protocol_loop: failed Sip::MsgType::handle('$input', $self, '$expect')";