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=174c0c24535d754b7df0ca56a217eaca0c3608a0;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 ac983c5..7573ffe 100644
--- a/SIPServer.pm
+++ b/SIPServer.pm
@@ -278,9 +278,13 @@ sub sip_protocol_loop {
     while ( $input = Sip::read_SIP_packet(*STDIN) ) {
         $input =~ s/[\r\n]+$//sm;    # Strip off any trailing line ends
 
+        my $start = time;
         my $status = Sip::MsgType::handle($input, $self, $expect);
         next if $status eq REQUEST_ACS_RESEND;
 
+        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')";