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

Are you sure that the script you are running is exactly as shown, in particular that `"${TIME1}"` and `"${TIME2}"` are quoted? otherwise errors such as this might occur if one of your `grep`s matches none or more than one line. (If they **are** properly quoted and grep matches more than one line, it will still be an error of course, though probably an "invalid date"). — steeldriver, Aug 25 '19 at 17:31
the script I run is exactly the same. I run my script witch bash -x and it seems that my script tries to set more than one variable one after another such as ++ grep 'candidate list sent for:' a8.svrf.ear ++ grep 1dd5.076c.5d5f049d ++ awk '-F[ ]' '{print $2}' + TIME2=00:09:50 ++ date +%s -d '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 — Anıl Aşık, Aug 25 '19 at 17:49
Please [edit] the `bash -x` output into your question so that its formatting is preserved — steeldriver, Aug 25 '19 at 18:16
Right. So following your recent edit you are getting what I would expect for properly quoted strings when there is more than one match for at least one of your `grep`s. You need to re-think the whole approach so as to guarantee that `date -d` receives a single valid date string. — steeldriver, Aug 25 '19 at 18:35
I dont understand I am already using `date -d` and I tested my greps as a single command on shell and all of them gave me what I need — Anıl Aşık, Aug 25 '19 at 18:47
see [Why is using a shell loop to process text considered bad practice?](https://unix.stackexchange.com/questions/169716/why-is-using-a-shell-loop-to-process-text-considered-bad-practice). This would be better, easier to do in awk (or, better yet, perl as perl has good, ready-to-use date-parsing modules). It would also be **much** faster as it wouldn't need to scan the input file multiple times. I'll add an example of how to do it in perl below. — cas, Aug 26 '19 at 00:53

cas · Answer 1 · 2019-08-26T02:03:06.303

#!/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.

score 0 · Answer 2 · answered Aug 25 '19 at 16:45

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

thanks for the reply but when I givesome parameters to my variables I also dont get any error. I can share the original log file if you dont mind — Anıl Aşık, Aug 25 '19 at 17:52
I CAN reproduce your error if I make TWO copies of your input file. That leads me to believe that you have more than one set of interesting lines in the data file, as steeldriver notes ... cheers, drl — drl, Aug 25 '19 at 17:58
also my output txt file is something like this for every map ; `... 11:33:30 11:33:34 11:33:42 11:33:42 11:33:47 Finish 00:12:54 Took seconds Took Map 1dd5.07a4.5d5f0574 Start 00:01:37 00:05:27 00:09:49 00:11:18 00:12:02 00:12:28 00:12:52 ... ` — Anıl Aşık, Aug 25 '19 at 18:01

Bash Time Difference

2 Answers2