A Perl script to calculate the delta time between timestamps at the start of a line
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
|
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 |
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
|
#! /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
# Version 1.1 April 25, 2018
# replaced <> with < and > so text displays correctly on web page
#
# noah@noahdavids.org
#
use strict;
my ($first, $diff);
my ($currentTimestamp, $lastTimestamp);
$first=1;
while ($_ = <stdin>)
{
$_ =~ /^([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
|
Send comments and suggestions