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 (file)
--- 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')";