Bash Time Difference

Question

I have a log file and I need to make some calculations between two jobs to find time difference.

In my log file I am supposed to calculate time between the jobs incoming request and candidate list sent for which took 2 seconds in the log below as an example;

2019-08-23 00:05:27 42303: incoming request: 1dd5.073f.5d5f0397 (156074 bytes)
2019-08-23 00:05:27 42303: store file: /papillon1/vrf/rq/1dd5.073f.5d5f0397.rq, len: 156074
2019-08-23 00:05:27 42303: registering process 42605 left to finish it's work
2019-08-23 00:05:27 42605: making search request for: 1dd5.073f.5d5f0397
2019-08-23 00:05:27 42605: 1dd5.073f.5d5f0397 is request for search by fingers
2019-08-23 00:05:27 42605: portions: 156
2019-08-23 00:05:27 42605: request pattern version 8
2019-08-23 00:05:27 42605: fingers mask: 1111111111; quality mask: 3011031110
2019-08-23 00:05:27 42605: saving request file: /papillon1/vrf/rqm/1dd5.073f.5d5f0397.rqm~
2019-08-23 00:05:27 42605: renaming request file: /papillon1/vrf/rqm/1dd5.073f.5d5f0397.rqm~ -
> /papillon1/vrf/rqm/1dd5.073f.5d5f0397.rqm
2019-08-23 00:05:27 42605: request file saved /papillon1/vrf/rqm/1dd5.073f.5d5f0397.rqm
2019-08-23 00:05:27 42605: request is in queue: 1dd5.073f.5d5f0397
2019-08-23 00:05:27 42605: request 1dd5.073f.5d5f0397 registering time: 663 msec
2019-08-23 00:05:28 42303: waiting for 42605 to be finished
2019-08-23 00:05:28 42303: 42605 finished; waiting time: 0 ms
2019-08-23 00:05:29 43188: candidate list for 1dd5.073f.5d5f0397; 2 records
2019-08-23 00:05:29 43188: candidate list file size: 381
2019-08-23 00:05:29 43188: candidate list sent for: 1dd5.073f.5d5f0397

so I created a script that reads all the maps in the log file and make calculations between 2 jobs for that map. In the log above 1dd5.073f.5d5f0397 is one map as an example.

Also here is my full script;

#!/bin/bash

for i in $(grep 'incoming request:' a8.svrf.ear | sed 's/^.*: //' | awk -F'[ ]' '{print $1}')
do
    var0=$i

    TIME1=$(grep 'incoming request:' a8.svrf.ear | awk -F'[ ]' '{print $2}')

    TIME2=$(grep 'candidate list sent for:' a8.svrf.ear | grep "$var0" | awk -F'[ ]' '{print $2}')

    SEC1=$(date +%s -d "${TIME1}")

    SEC2=$(date +%s -d "${TIME2}")

    DIFFSEC=$(expr "${SEC2}" - "${SEC1}")

    echo Map "${var0}" >> /home/st/anil/test.txt

    echo Start "${TIME1}" >> /home/st/anil/test.txt
    echo Finish "${TIME2}" >> /home/st/anil/test.txt

    echo Took "${DIFFSEC}" seconds >> /home/st/anil/test.txt

    echo Took $(date +%H:%M:%S -ud @"${DIFFSEC}") >>/home/st/anil/test.txt

    echo =========================================================================


done

In my code I basically tried to get all maps with a for loop and for each map I tried to get time for 2 jobs and find the time difference but my output is something unexpected ;

=========================================================================
...
34\n11:33:42\n11:33:42\n11:33:47’
expr: non-integer argument
date: invalid date ‘@’
=========================================================================
date: invalid date ‘00:01:37\n00:05:27\n00:09:49\n00:11:18\n00:12:02\n00:12:28\n00:12:52\n00:13:24\n00:15:10\n00:16:
...

Also in the output txt file I face something like this for every map;

Map 1dd5.0721.5d5f02b1
Start 00:01:37
00:05:27
00:09:49
00:11:18
00:12:02
00:12:28
00:12:52
00:13:24
00:15:10
00:16:05
00:22:36
00:23:14
00:23:44
00:24:15
00:25:26
00:26:07
00:27:04
00:27:34
...
Finish 
Took  seconds
Took
=========================================================================

I would be glad if you guys show my mistake. Thank you

Answer 1

#!/usr/bin/perl

use strict;

use Date::Parse;
use Date::Format;

# hash arrays to keep the start and ending times for each request id.
my %start = ();
my %end = ();

# the @order array is used to preserve the order that we saw request ids,
# so we can print them out in the same order.
my @order;

while(<>) {
  # skip lines we're not interested in
  next unless (m/incoming request:|candidate list sent for:/);
  chomp;  # strip trailing linefeed

  # split input line into array @F on white-space separated fields.
  my @F = split;
  # and get the timestamp of the log entry
  my $timestamp = join(" ", @F[0..1]);

  if (m/incoming request:/) {
    my $reqid = $F[5];
    if (!defined($start{$reqid})) { push @order, $reqid };

    $start{$reqid} = $timestamp;

  } elsif (m/candidate list sent for:/) {
    my $reqid = $F[7];
    $end{$reqid} = $timestamp;
  };

};

foreach my $reqid (@order) {
    my $seconds = str2time($end{$reqid}) - str2time($start{$reqid});
    my $hms = time2str("%H:%M:%S", $seconds, "0");
    my $s = time2str("%H:%M:%S", str2time($start{$reqid}));
    my $e = time2str("%H:%M:%S", str2time($end{$reqid}));

    print <<__EOF__
Map $reqid
Start $s
Finish $e
Took $seconds seconds
Took $hms
=========================================================================

__EOF__
}

Save this as, e.g. anil.pl and make it executable with chmod +x anil.pl.

Output from the sample input is:

$ ./anil.pl a8.svrf.ear 
Map 1dd5.073f.5d5f0397
Start 00:05:27
Finish 00:05:29
Took 2 seconds
Took 00:00:02
=========================================================================

---

The same algorithm can be implemented in bash, but (IMO) it's a lot harder to read and understand, and bash array variables are a pain to work with because of how they need to be quoted. And it will run a lot slower:

For example:

#!/bin/bash

declare -A start end
declare -a order

while read -r -a F ; do

  [ "${F[3]} ${F[4]}" != "incoming request:" ] \
    && [ "${F[3]} ${F[6]}" != "candidate for:" ] \
    && continue

  ts="${F[0]} ${F[1]}"

  if [ "${F[3]}" = "incoming" ] ; then
    reqid="${F[5]}"
    [ -v start[$reqid] ] || order+=( "$reqid" )
    start["$reqid"]="$ts"

  elif [ "${F[3]}" = "candidate" ] ; then
    reqid="${F[7]}"
    end["$reqid"]="$ts"
  fi

done <(cat "$@")

for reqid in "${order[@]}"; do
  start=$(date -d "${start[$reqid]}" +%s)
  end=$(date -d "${end[$reqid]}" +%s)
  seconds=$(( $end - $start ))
  hms=$(TZ=UTC date -d "@$seconds" "+%H:%M:%S")
  s=$(date -d "${start[$reqid]}" "+%H:%M:%S")
  e=$(date -d "${end[$reqid]}" "+%H:%M:%S")

cat <<__EOF__
Map $reqid
Start $s
Finish $e
Took $seconds seconds
Took $hms
=========================================================================

__EOF__

done

Note: this requires bash v4.3 or newer for the -v test operator to check if a variable exists.

Answer 2

I cannot reproduce your error. I made changes to parameterize your output file because I don't have your /home/st... as noted:

#!/bin/bash

for i in $(grep 'incoming request:' a8.svrf.ear | sed 's/^.*: //' | awk -F'[ ]' '{print $1}')
do
    var0=$i

    TIME1=$(grep 'incoming request:' a8.svrf.ear | awk -F'[ ]' '{print $2}')

    TIME2=$(grep 'candidate list sent for:' a8.svrf.ear | grep "$var0" | awk -F'[ ]' '{print $2}')

    SEC1=$(date +%s -d "${TIME1}")

    SEC2=$(date +%s -d "${TIME2}")

    DIFFSEC=$(expr "${SEC2}" - "${SEC1}")

        OUT=/home/st/anil/test.txt
        OUT=t1
        rm -f $OUT
    # echo Map "${var0}" >> /home/st/anil/test.txt
    echo Map "${var0}" >> $OUT

    # echo Start "${TIME1}" >> /home/st/anil/test.txt
    echo Start "${TIME1}" >> $OUT
    # echo Finish "${TIME2}" >> /home/st/anil/test.txt
    echo Finish "${TIME2}" >> $OUT

    # echo Took "${DIFFSEC}" seconds >> /home/st/anil/test.txt
    echo Took "${DIFFSEC}" seconds >> $OUT

    # echo Took $(date +%H:%M:%S -ud @"${DIFFSEC}") >>/home/st/anil/test.txt
    echo Took $(date +%H:%M:%S -ud @"${DIFFSEC}") >> $OUT

    echo =========================================================================


done

The output file t1 contains:

Map 1dd5.073f.5d5f0397
Start 00:05:27
Finish 00:05:29
Took 2 seconds
Took 00:00:02

This was on a system like:

OS, ker|rel, machine: Linux, 3.16.0-7-amd64, x86_64
Distribution        : Debian 8.11 (jessie) 
bash GNU bash 4.3.30
date (GNU coreutils) 8.23

To set your file, just interchange the 2 OUT assignments.

Good luck ... cheers, drl