Log message handline 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.

Signed-off-by: Bill Erickson <berickxx@gmail.com>

diff --git a/SIPServer.pm b/SIPServer.pm
index 9e598b6..6418007 100755 (executable)
--- 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_INFO', "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')";