#Time marker falls back after 5450.91sec log time

[dschiedsch]

Joulescope model

JS220

UI version

1.2.1

What OS are you seeing the problem on?

Windows 10

What happened?

While logging with 50Hz i encountered that the timestamp in my logs falls back
after 5450.91sec
or after line 272527

here is the log starting from line 272523
5450.83,0.00843953,4.84234,0.0408671,498.404,2409.76
5450.85,0.00844139,4.84235,0.0408762,498.404,2409.76
5450.87,0.00844158,4.84234,0.040877,498.404,2409.76
5450.89,0.00844035,4.84239,0.0408715,498.404,2409.76
5450.91,0.00843744,4.84236,0.0408571,498.404,2409.77
3303.44,0.0084382,4.84234,0.0408606,498.404,2409.77
3303.46,0.00843958,4.84235,0.0408674,498.405,2409.77
3303.48,0.00843948,4.84233,0.0408667,498.405,2409.77
3303.50,0.00844342,4.84235,0.040886,498.405,2409.77
3303.52,0.00844488,4.84241,0.0408936,498.405,2409.77

What was expected?

log time should increase continously

How to reproduce?

50Hz logging rate after 5450sec of logging

Extra information

No response

[mliberty1]

I will set up a test to see if I can duplicate this. Does this happen in a repeatable manner on your computer?

[mliberty1]

I just collected a capture for 18096 seconds, and it looks good:

Here is the analyzer.py source code:

#!/usr/bin/env python3
# Copyright 2024 Jetperch LLC
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

import argparse
import matplotlib.pyplot as plt
import numpy as np
import os


def get_parser():
    p = argparse.ArgumentParser(
        description='Analyze Joulescope statistics capture for "jumps".')
    p.add_argument('--plot',
                   action='store_true',
                   help='display a plot of the time.')
    p.add_argument('path',
                   help='The path to the CSV statistics file.')
    return p


def run(args=None):
    parser = get_parser()
    args = parser.parse_args(args=args)
    d = np.loadtxt(args.path, delimiter=',')
    t = d[:, 0]
    dt = np.diff(t)
    p = np.median(dt[:100])
    k = np.where(np.logical_or(dt <= 0, dt > (p * 2.1)))[0]

    if len(k):
        for i in k:
            print(f'{i} {dt[i]}')
    else:
        print('All good!')
        
    if args.plot:
        f = plt.figure(figsize=[6.0, 8.0], layout='tight')
        ax1 = f.add_subplot(2, 1, 1)
        ax1.set_title('Time')
        ax1.set_xlabel('Sample')
        ax1.set_ylabel('Time (s)')
        ax1.grid(True)
        ax1.plot(t)
        
        ax2 = f.add_subplot(2, 1, 2, sharex=ax1)
        ax2.set_title('Time Delta')
        ax2.set_xlabel('Sample')
        ax2.set_ylabel('Δt (s)')
        ax2.grid(True)
        ax2.plot(dt)
        
        plt.show()


if __name__ == '__main__':
    run()

which I ran with:

python .\analyze.py 50hz_01.csv --plot

I will try again with an overnight statistics recording.

Are you able to duplicate this issue on your computer? If so, can you use Help → Report issue in the Joulescope UI to report this issue? The logs may have some hints.

[dschiedsch]

Hi I will try to rerun the capture and see if I can recreate it

[mliberty1]

The overnight run was good too:

I do see that the time sync algorithm made a pretty major time correction about 9600 seconds in. It then undid this correction at 11000 seconds in. A more normal correction occurred at 43000 seconds in. I need to investigate what happened here. We do expect up ±20 ppm (±1.7 seconds / day) of drift that needs to be corrected. However, correcting one way and then back is not desirable, but this could also have been the PC's NTP time correction...

I will set up another capture to run over the weekend.

[mliberty1]

I ran multiple 50 Hz statistics captures last night, and I caught one issue:

I also edited the script in the previous post to correctly process this failed case.

The logs show an uneventful night from when I started CSV statistics logging to when I ended it:

INFO:2024-11-22 16:56:19,638:statistics_record.py:43:joulescope_ui.widgets.statistics_record.statistics_record.obj:JLS record registry/JS220-000415/events/statistics/!data to C:\Users\mliberty\Documents\joulescope\20241122_215619-JS220-000415.csv
INFO:2024-11-22 16:56:19,638:paths.py:122:joulescope_ui.paths:mru_save C:\Users\mliberty\Documents\joulescope\20241122_215619-JS220-000415.csv
INFO:2024-11-22 16:56:19,638:pubsub.py:1092:joulescope_ui.pubsub:register(unique_id=StatisticsRecord:0000000b, obj=<joulescope_ui.widgets.statistics_record.statistics_record.StatisticsRecord object at 0x000001C3159D3A50>) start
INFO:2024-11-22 16:56:19,638:pubsub.py:905:joulescope_ui.pubsub:Missing metadata for registry/app/children
INFO:2024-11-22 16:56:19,638:pubsub.py:1143:joulescope_ui.pubsub:register(unique_id=StatisticsRecord:0000000b) done 
INFO:2024-11-22 21:58:18,141:main.py:458:joulescope_ui.main:on_action_key_press: (16777216, <KeyboardModifier.NoModifier: 0>)
INFO:2024-11-23 07:45:37,604:statistics_record.py:131:joulescope_ui.widgets.statistics_record.statistics_record.cls:stop
INFO:2024-11-23 07:45:37,604:statistics_record.py:107:joulescope_ui.widgets.statistics_record.statistics_record.obj:stop

The biggest lead here is the time alignment algorithm. It's possible that the new time alignment algorithm in UI 1.2.1 with FW 1.3.0 and FPGA 1.3.0 is to blame. However, I have an older, still unsolved report from September with strange timestamps in a JLS file. It could be that this is simply a relatively rare event.

We will investigate. Given the difficulty in duplicating this issue, any fix will likely take some time.