A Perl script to calculate the delta time between timestamps at the start of a line

Blue Bar separator

I have many times needed to calculate the difference between the timestamps in a log file. Typically because I am looking for a jump in the log message times in an attempt to understand a performance issue.

In the past I have loaded the file into a spread sheet and then used the functions in the spread sheet to calculate the difference. Not difficult but I finally got tired of all the extra steps and came up with this simple Perl script to do it for me.

The sample data looks like this.

10:28:11.179849 execve("/usr/sbin/sshd", ["/usr/sbin/sshd", "-p", "12481",                                 
10:28:11.180616 brk(NULL)         = 0x561be9fe0000 <0.000024>
10:28:11.180745 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such fi
10:28:11.180861 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANO
10:28:11.180966 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such fi
10:28:11.181094 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000038
10:28:11.181219 fstat(3, {st_dev=makedev(8, 2), st_ino=44567611, st_mode=S
10:28:11.181350 mmap(NULL, 102768, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f8b9
10:28:11.181441 close(3)          = 0 <0.000024>
10:28:11.181534 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such fi
Example data file

The above output is from the following strace command in line 1 with the with the process ID removed and the lines truncated in line 2. Obviously the length of truncation (including no truncation) is dependent on the log messages and what you need to help make sense of them and present any findings. The line length makes no difference to the script.

1. # strace -Tttvxfs 1024 -o /tmp/strace.out /usr/sbin/sshd -p 12481 -dddd                                 
2. # cat /tmp/strace.out  | grep ^7964 | cut -c 7-80 > foo
Commands to generate the data file.

The script takes no aruments and uses standard in and out. The line it writes is the delta time followed by the time in seconds followed by the original line. The first line is given a delta time of 0. I pipe the output through sort, doing a numeric sort on just the first column (-nk1) and then take the last 10 lines which will give me the 10 lines with the largest delta time. Once I have these lines I can go back to the original log file and see what came right before and that will give me my perforamce hit (if I am lucky).

# cat foo | delta_time_stamp.pl | sort -nk1 | tail -10
0.004230 	 37741.525235 	 10:29:01.525235 read(6, "\x00\x00\x00\x1c", 4) = 4 <0.000054>
0.004752 	 37741.476075 	 10:29:01.476075 read(6, "\x00\x00\x00\x1f", 4) = 4 <0.000030>
0.005140 	 37738.323805 	 10:28:58.323805 write(2, "debug3: mm_answer_sign: hostkey proof signature 
0.015590 	 37738.287194 	 10:28:58.287194 read(4, "ADD061CC5BE1EA060CC3217CA11E26772BD088898D2882CB4
0.036733 	 37741.449795 	 10:29:01.449795 <... poll resumed> ) = 1 ([{fd=6, revents=POLLIN}]) <0.036
0.045310 	 37738.200757 	 10:28:58.200757 futex(0x7f844aa020a8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 
0.050958 	 37691.267450 	 10:28:11.267450 futex(0x7f8b9959d0a8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 
3.084389 	 37741.411521 	 10:29:01.411521 <... poll resumed> ) = 1 ([{fd=6, revents=POLLIN}]) <3.084
3.549315 	 37745.074983 	 10:29:05.074983 <... poll resumed> ) = 1 ([{fd=6, revents=POLLIN}]) <3.549
46.824926 	 37738.120466 	 10:28:58.120466 accept(3, {sa_family=AF_INET, sin_port=htons(35524), sin_a
Sample execution

delta_time_stamp.pl

 
#! /usr/bin/perl                                                               
#
# delta_time_stamp - reads from standard in writes to stanadrd out.
# first column must be a time stamp in the form HH:MM:SS.ssssss
#
# Version 1.0 May 6, 2016
#
# noah@noahdavids.org
#

use strict;

my ($first, $diff);
my ($currentTimestamp, $lastTimestamp);

$first=1;
while ($_ = ) 
   {
   $_ =~ /^([0-9][0-9]):([0-9][0-9]):([0-9][0-9].[1234567890]*)/;
   $currentTimestamp = ((($1 * 60) + $2) * 60) + $3;
   if ($first) {
      $lastTimestamp = $currentTimestamp;
      $first = 0; }
   $diff = $currentTimestamp - $lastTimestamp;
   printf ("%6f \t %6f \t %s", $diff, $currentTimestamp, $_);
   $lastTimestamp = $currentTimestamp;
   } 
#
# delta_time_stamp.pl ends here



Blue Bar separator
This page was last modified on 16-05-15
mailbox Send comments and suggestions
to noah@noahdavids.org