From c9beb93d83b08a320f7cfbbc3519a1dfcdb77071 Mon Sep 17 00:00:00 2001 From: Yaroslav Halchenko Date: Wed, 15 May 2024 13:35:18 -0400 Subject: [PATCH] BF: tools/dtime to handle log line having non-increment timestamp Apparently can happen, likely due to multithreading and different threads doing their own timestamping. Interestingly Python seems to not handle negative time delta "intuitively": (Pdb) p t datetime.datetime(2024, 5, 14, 19, 39, 12, 800000) (Pdb) p prevt datetime.datetime(2024, 5, 14, 19, 39, 12, 801000) (Pdb) p t - prevt datetime.timedelta(days=-1, seconds=86399, microseconds=999000) *(Pdb) p prevt -t datetime.timedelta(microseconds=1000) but since python 2.7 there is "total_seconds" which is behaving as desired and anyways we need those, so we can just use and thus operate correctly also whenever crossing some days boundary (hopefully never). --- tools/dtime | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/tools/dtime b/tools/dtime index 206df02341..91130d3b25 100755 --- a/tools/dtime +++ b/tools/dtime @@ -15,6 +15,7 @@ reg = re.compile('^\d{4}-\d{2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2},\d{1,3}') prevt = None maxl = 0 prevl = None +warned_negative = False if len(sys.argv) <= 1: in_ = sys.stdin @@ -30,7 +31,14 @@ for l in in_: t = datetime.strptime(l[:end], '%Y-%m-%d %H:%M:%S,%f') if prevt is not None: dt = t - prevt - ms = dt.microseconds // 1000 + dt.seconds*1000 + secs = dt.total_seconds() + # negative dt has very weird form of -1 day + huge number of seconds + if secs < 0: + if not warned_negative: + sys.stderr.write(f"Negative delta of {secs} seconds detected. Might be due to threading etc\n") + warned_negative = True + + ms = secs * 1000 dtstr = ("%5d" % ms if ms else ' 0') maxl = max(maxl, len(dtstr))