IIO timestamp get skewed when suspending (st_lsm6dsx)

IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

Hi,

I don't know if it's normal behavior or maybe just a problem related to 
the buffered reads in st_lsm6dsx.

But when we have the buffered reads enabled and suspending for x amount 
of time. The iio timestamps is, x amount of time is delayed. As seen here:

https://gist.github.com/sknsean/60e20c2fa3a3c6d69ef128c703ed43fc

 From your own software (but I'm able to reproduce with libiio/iio_readdev)

First col is system time,
Second timestamp is the iio timestamp

Could a solution, be to call st_lsm6dsx_reset_hw_ts() in 
st_lsm6dsx_resume() ?

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 4130 bytes --]

> Hi,

Hi Sean,

> 
> I don't know if it's normal behavior or maybe just a problem related to the
> buffered reads in st_lsm6dsx.
> 
> But when we have the buffered reads enabled and suspending for x amount of
> time. The iio timestamps is, x amount of time is delayed. As seen here:
> 
> https://gist.github.com/sknsean/60e20c2fa3a3c6d69ef128c703ed43fc
> 
> From your own software (but I'm able to reproduce with libiio/iio_readdev)
> 
> First col is system time,
> Second timestamp is the iio timestamp
> 
> Could a solution, be to call st_lsm6dsx_reset_hw_ts() in st_lsm6dsx_resume()
> ?

yes, I think so. Could you please try to patch below? Thanks.

Regards,
Lorenzo

> 
> /Sean

From f4ea9019d3b6fb1ad80747cf378bf1fbdebd3dd8 Mon Sep 17 00:00:00 2001
Message-Id: <f4ea9019d3b6fb1ad80747cf378bf1fbdebd3dd8.1590699935.git.lorenzo@kernel.org>
From: Lorenzo Bianconi <lorenzo@kernel.org>
Date: Thu, 28 May 2020 23:05:16 +0200
Subject: [PATCH] iio: imu: st_lsm6dsx: reset hw ts after resume

Signed-off-by: Lorenzo Bianconi <lorenzo@kernel.org>
---
 drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h       |  3 +--
 .../iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c    | 23 ++++++++++++-------
 drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c  |  2 +-
 3 files changed, 17 insertions(+), 11 deletions(-)

diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h
index b56df409ed0f..529970195b39 100644
--- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h
+++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h
@@ -436,8 +436,7 @@ int st_lsm6dsx_update_watermark(struct st_lsm6dsx_sensor *sensor,
 				u16 watermark);
 int st_lsm6dsx_update_fifo(struct st_lsm6dsx_sensor *sensor, bool enable);
 int st_lsm6dsx_flush_fifo(struct st_lsm6dsx_hw *hw);
-int st_lsm6dsx_set_fifo_mode(struct st_lsm6dsx_hw *hw,
-			     enum st_lsm6dsx_fifo_mode fifo_mode);
+int st_lsm6dsx_resume_fifo(struct st_lsm6dsx_hw *hw);
 int st_lsm6dsx_read_fifo(struct st_lsm6dsx_hw *hw);
 int st_lsm6dsx_read_tagged_fifo(struct st_lsm6dsx_hw *hw);
 int st_lsm6dsx_check_odr(struct st_lsm6dsx_sensor *sensor, u32 odr, u8 *val);
diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
index afd00daeefb2..7de10bd636ea 100644
--- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
+++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
@@ -184,8 +184,8 @@ static int st_lsm6dsx_update_decimators(struct st_lsm6dsx_hw *hw)
 	return err;
 }
 
-int st_lsm6dsx_set_fifo_mode(struct st_lsm6dsx_hw *hw,
-			     enum st_lsm6dsx_fifo_mode fifo_mode)
+static int st_lsm6dsx_set_fifo_mode(struct st_lsm6dsx_hw *hw,
+				    enum st_lsm6dsx_fifo_mode fifo_mode)
 {
 	unsigned int data;
 
@@ -302,6 +302,18 @@ static int st_lsm6dsx_reset_hw_ts(struct st_lsm6dsx_hw *hw)
 	return 0;
 }
 
+int st_lsm6dsx_resume_fifo(struct st_lsm6dsx_hw *hw)
+{
+	int err;
+
+	/* reset hw ts counter */
+	err = st_lsm6dsx_reset_hw_ts(hw);
+	if (err < 0)
+		return err;
+
+	return st_lsm6dsx_set_fifo_mode(hw, ST_LSM6DSX_FIFO_CONT);
+}
+
 /*
  * Set max bulk read to ST_LSM6DSX_MAX_WORD_LEN/ST_LSM6DSX_MAX_TAGGED_WORD_LEN
  * in order to avoid a kmalloc for each bus access
@@ -675,12 +687,7 @@ int st_lsm6dsx_update_fifo(struct st_lsm6dsx_sensor *sensor, bool enable)
 		goto out;
 
 	if (fifo_mask) {
-		/* reset hw ts counter */
-		err = st_lsm6dsx_reset_hw_ts(hw);
-		if (err < 0)
-			goto out;
-
-		err = st_lsm6dsx_set_fifo_mode(hw, ST_LSM6DSX_FIFO_CONT);
+		err = st_lsm6dsx_resume_fifo(hw);
 		if (err < 0)
 			goto out;
 	}
diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
index 0b776cb91928..b3a08e3e2359 100644
--- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
+++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
@@ -2458,7 +2458,7 @@ static int __maybe_unused st_lsm6dsx_resume(struct device *dev)
 	}
 
 	if (hw->fifo_mask)
-		err = st_lsm6dsx_set_fifo_mode(hw, ST_LSM6DSX_FIFO_CONT);
+		err = st_lsm6dsx_resume_fifo(hw);
 
 	return err;
 }
-- 
2.26.2


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

>>
>> Could a solution, be to call st_lsm6dsx_reset_hw_ts() in st_lsm6dsx_resume()
>> ?
> 
> yes, I think so. Could you please try to patch below? Thanks.
> 

Hi Lorenzo,

I have tried your patch, and the timestamp seems to behave like before.

https://gist.github.com/sknsean/959d3421f66cb49144e7841a8a08a2be
Sorry NTP have been connected for a while :)

I will enable some more debug to trace what is happening.

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 735 bytes --]

On May 29, Sean Nyekjaer wrote:
> 
> > > 
> > > Could a solution, be to call st_lsm6dsx_reset_hw_ts() in st_lsm6dsx_resume()
> > > ?
> > 
> > yes, I think so. Could you please try to patch below? Thanks.
> > 
> 
> Hi Lorenzo,
> 
> I have tried your patch, and the timestamp seems to behave like before.
> 
> https://gist.github.com/sknsean/959d3421f66cb49144e7841a8a08a2be
> Sorry NTP have been connected for a while :)
> 
> I will enable some more debug to trace what is happening.
> 
> /Sean

Hi Sean,

thx for testing. Is the FIFO enabled before the suspend (in other words, is
st_lsm6dsx_resume_fifo running in st_lsm6dsx_resume?) what is the value of
sensor->ts_ref after the resume?

Regards,
Lorenzo

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 29/05/2020 09.44, Lorenzo Bianconi wrote:
> On May 29, Sean Nyekjaer wrote:
>>
>>>>
>>>> Could a solution, be to call st_lsm6dsx_reset_hw_ts() in st_lsm6dsx_resume()
>>>> ?
>>>
>>> yes, I think so. Could you please try to patch below? Thanks.
>>>
>>
>> Hi Lorenzo,
>>
>> I have tried your patch, and the timestamp seems to behave like before.
>>
>> https://gist.github.com/sknsean/959d3421f66cb49144e7841a8a08a2be
>> Sorry NTP have been connected for a while :)
>>
>> I will enable some more debug to trace what is happening.
>>
>> /Sean
> 
> Hi Sean,
> 
> thx for testing. Is the FIFO enabled before the suspend (in other words, is
> st_lsm6dsx_resume_fifo running in st_lsm6dsx_resume?) what is the value of
> sensor->ts_ref after the resume?

I have applied this patch:
diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c 
b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c

index 7de10bd636ea..915829f89d31 100644

--- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c

+++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c

@@ -304,12 +304,28 @@ static int st_lsm6dsx_reset_hw_ts(struct 
st_lsm6dsx_hw *hw)



  int st_lsm6dsx_resume_fifo(struct st_lsm6dsx_hw *hw)

  {

-       int err;

+       int err, i;

+       struct st_lsm6dsx_sensor *sensor;



+       printk("st_lsm6dsx_resume_fifo\n");

+       for (i = 0; i < ST_LSM6DSX_ID_MAX; i++) {

+               if (!hw->iio_devs[i])

+                       continue;

+

+               sensor = iio_priv(hw->iio_devs[i]);

+               printk("Before[%d]: %lld\n", i, sensor->ts_ref);

+       }

         /* reset hw ts counter */

         err = st_lsm6dsx_reset_hw_ts(hw);

         if (err < 0)

                 return err;

+       for (i = 0; i < ST_LSM6DSX_ID_MAX; i++) {

+               if (!hw->iio_devs[i])

+                       continue;

+

+               sensor = iio_priv(hw->iio_devs[i]);

+               printk("After[%d]: %lld\n", i, sensor->ts_ref);

+       }



         return st_lsm6dsx_set_fifo_mode(hw, ST_LSM6DSX_FIFO_CONT);

  }

And dmesg:
[  949.295585] st_lsm6dsx_resume_fifo

[  949.295617] Before[0]: 0

[  949.295636] Before[1]: 0

[  949.296456] After[0]: 1590740890980204361

[  949.296476] After[1]: 1590740890980207987

[  953.380200] PM: suspend entry (deep)

[  953.790084] Filesystems sync: 0.409 seconds

[  953.795329] Freezing user space processes ... (elapsed 0.002 seconds) 
done.

[  953.798124] OOM killer disabled.

[  953.798140] Freezing remaining freezable tasks ... (elapsed 0.001 
seconds) done.

[  953.800016] printk: Suspending console(s) (use no_console_suspend to 
debug)

[  953.869535] PM: suspend devices took 0.070 seconds

[  953.883280] Disabling non-boot CPUs ...

[  953.897700] st_lsm6dsx_resume_fifo

[  953.897732] Before[0]: 1590740890980204361

[  953.897752] Before[1]: 1590740890980207987

[  953.898572] After[0]: 1590740895583500924

[  953.898594] After[1]: 1590740895583504049

[  953.914484] PM: resume devices took 0.020 seconds

[  953.914533] OOM killer enabled.

[  953.914552] Restarting tasks ... done.

[  953.947170] PM: suspend exit

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 3781 bytes --]

> 
> 
> On 29/05/2020 09.44, Lorenzo Bianconi wrote:
> > On May 29, Sean Nyekjaer wrote:
> > > 
> > > > > 
> > > > > Could a solution, be to call st_lsm6dsx_reset_hw_ts() in st_lsm6dsx_resume()
> > > > > ?
> > > > 
> > > > yes, I think so. Could you please try to patch below? Thanks.
> > > > 
> > > 
> > > Hi Lorenzo,
> > > 
> > > I have tried your patch, and the timestamp seems to behave like before.
> > > 
> > > https://gist.github.com/sknsean/959d3421f66cb49144e7841a8a08a2be
> > > Sorry NTP have been connected for a while :)
> > > 
> > > I will enable some more debug to trace what is happening.
> > > 
> > > /Sean
> > 
> > Hi Sean,
> > 
> > thx for testing. Is the FIFO enabled before the suspend (in other words, is
> > st_lsm6dsx_resume_fifo running in st_lsm6dsx_resume?) what is the value of
> > sensor->ts_ref after the resume?
> 
> I have applied this patch:
> diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
> b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
> 
> index 7de10bd636ea..915829f89d31 100644
> 
> --- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
> 
> +++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
> 
> @@ -304,12 +304,28 @@ static int st_lsm6dsx_reset_hw_ts(struct st_lsm6dsx_hw
> *hw)
> 
> 
> 
>  int st_lsm6dsx_resume_fifo(struct st_lsm6dsx_hw *hw)
> 
>  {
> 
> -       int err;
> 
> +       int err, i;
> 
> +       struct st_lsm6dsx_sensor *sensor;
> 
> 
> 
> +       printk("st_lsm6dsx_resume_fifo\n");
> 
> +       for (i = 0; i < ST_LSM6DSX_ID_MAX; i++) {
> 
> +               if (!hw->iio_devs[i])
> 
> +                       continue;
> 
> +
> 
> +               sensor = iio_priv(hw->iio_devs[i]);
> 
> +               printk("Before[%d]: %lld\n", i, sensor->ts_ref);
> 
> +       }
> 
>         /* reset hw ts counter */
> 
>         err = st_lsm6dsx_reset_hw_ts(hw);
> 
>         if (err < 0)
> 
>                 return err;
> 
> +       for (i = 0; i < ST_LSM6DSX_ID_MAX; i++) {
> 
> +               if (!hw->iio_devs[i])
> 
> +                       continue;
> 
> +
> 
> +               sensor = iio_priv(hw->iio_devs[i]);
> 
> +               printk("After[%d]: %lld\n", i, sensor->ts_ref);
> 
> +       }
> 
> 
> 
>         return st_lsm6dsx_set_fifo_mode(hw, ST_LSM6DSX_FIFO_CONT);
> 
>  }
> 
> And dmesg:
> [  949.295585] st_lsm6dsx_resume_fifo
> 
> [  949.295617] Before[0]: 0
> 
> [  949.295636] Before[1]: 0
> 
> [  949.296456] After[0]: 1590740890980204361
> 
> [  949.296476] After[1]: 1590740890980207987
> 
> [  953.380200] PM: suspend entry (deep)
> 
> [  953.790084] Filesystems sync: 0.409 seconds
> 
> [  953.795329] Freezing user space processes ... (elapsed 0.002 seconds)
> done.
> 
> [  953.798124] OOM killer disabled.
> 
> [  953.798140] Freezing remaining freezable tasks ... (elapsed 0.001
> seconds) done.
> 
> [  953.800016] printk: Suspending console(s) (use no_console_suspend to
> debug)
> 
> [  953.869535] PM: suspend devices took 0.070 seconds
> 
> [  953.883280] Disabling non-boot CPUs ...
> 
> [  953.897700] st_lsm6dsx_resume_fifo
> 
> [  953.897732] Before[0]: 1590740890980204361
> 
> [  953.897752] Before[1]: 1590740890980207987
> 
> [  953.898572] After[0]: 1590740895583500924
> 
> [  953.898594] After[1]: 1590740895583504049
> 
> [  953.914484] PM: resume devices took 0.020 seconds
> 
> [  953.914533] OOM killer enabled.
> 
> [  953.914552] Restarting tasks ... done.
> 
> [  953.947170] PM: suspend exit
> 
> /Sean

Ack, values seem properly updated, while values reported to the upserspace are
using wrong value? could you please try to dump ts samples reading the hw queue
after the resume?

Regards,
Lorenzo

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

> 
> Ack, values seem properly updated, while values reported to the upserspace are
> using wrong value? could you please try to dump ts samples reading the hw queue
> after the resume?
> 
> Regards,
> Lorenzo
> 

I have add the raw timestamps to the trace:
https://gist.github.com/sknsean/1eb3c074d6f2d134632582a4771322bb

Both with and without the proposed patch :)

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 603 bytes --]

On May 29, Sean Nyekjaer wrote:
> 
> > 
> > Ack, values seem properly updated, while values reported to the upserspace are
> > using wrong value? could you please try to dump ts samples reading the hw queue
> > after the resume?
> > 
> > Regards,
> > Lorenzo
> > 
> 
> I have add the raw timestamps to the trace:
> https://gist.github.com/sknsean/1eb3c074d6f2d134632582a4771322bb
> 
> Both with and without the proposed patch :)
> 
> /Sean

are these values from the hw FIFO? can you please add sensor->ts_ref to the trace and
a log into st_lsm6dsx_reset_hw_ts?

Regards,
Lorenzo

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 29/05/2020 14.16, Lorenzo Bianconi wrote:
> On May 29, Sean Nyekjaer wrote:
>>
>>>
>>> Ack, values seem properly updated, while values reported to the upserspace are
>>> using wrong value? could you please try to dump ts samples reading the hw queue
>>> after the resume?
>>>
>>> Regards,
>>> Lorenzo
>>>
>>
>> I have add the raw timestamps to the trace:
>> https://gist.github.com/sknsean/1eb3c074d6f2d134632582a4771322bb
>>
>> Both with and without the proposed patch :)
>>
>> /Sean
> 
> are these values from the hw FIFO? can you please add sensor->ts_ref to the trace and
> a log into st_lsm6dsx_reset_hw_ts?

The values are from the timestamp got when reading /dev/iio:deviceX.
Will add hw FIFO and ts_ref stamps to the trace next Tuesday

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 29/05/2020 14.16, Lorenzo Bianconi wrote:
> On May 29, Sean Nyekjaer wrote:
>>
>>>
>>> Ack, values seem properly updated, while values reported to the upserspace are
>>> using wrong value? could you please try to dump ts samples reading the hw queue
>>> after the resume?
>>>
>>> Regards,
>>> Lorenzo
>>>
>>
>> I have add the raw timestamps to the trace:
>> https://gist.github.com/sknsean/1eb3c074d6f2d134632582a4771322bb
>>
>> Both with and without the proposed patch :)
>>
>> /Sean
> 
> are these values from the hw FIFO? can you please add sensor->ts_ref to the trace and
> a log into st_lsm6dsx_reset_hw_ts?
> 

Hi,

This certainly looks weird,

https://gist.github.com/sknsean/b32bae140008cf446a8fea58e305da47

Seems like the ts_ref is updated and used but not read/used in userspace...

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

>> are these values from the hw FIFO? can you please add sensor->ts_ref 
>> to the trace and
>> a log into st_lsm6dsx_reset_hw_ts?
>>
> 
> Hi,
> 
> This certainly looks weird,
> 
> https://gist.github.com/sknsean/b32bae140008cf446a8fea58e305da47
> 
> Seems like the ts_ref is updated and used but not read/used in userspace...
> 
> /Sean

added to st_lsm6dsx_read_fifo :

printk("ts_ref %lld, ts %lld, sample_time %lld\n", acc_sensor->ts_ref, 
ts, acc_sensor->ts_ref + ts);

https://gist.github.com/sknsean/3ad1e9e05cb0e2ef811a3c83492a1980

Suspend again was 15sec

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 02/06/2020 15.39, Sean Nyekjaer wrote:
>>> are these values from the hw FIFO? can you please add sensor->ts_ref 
>>> to the trace and
>>> a log into st_lsm6dsx_reset_hw_ts?
>>>
>>
>> Hi,
>>
>> This certainly looks weird,
>>
>> https://gist.github.com/sknsean/b32bae140008cf446a8fea58e305da47
>>
>> Seems like the ts_ref is updated and used but not read/used in 
>> userspace...
>>
>> /Sean
> 
> added to st_lsm6dsx_read_fifo :
> 
> printk("ts_ref %lld, ts %lld, sample_time %lld\n", acc_sensor->ts_ref, 
> ts, acc_sensor->ts_ref + ts);
> 
> https://gist.github.com/sknsean/3ad1e9e05cb0e2ef811a3c83492a1980
> 
> Suspend again was 15sec
> 
> /Sean

Hi,

Some more findings :)
https://gist.github.com/sknsean/d31e48b65515361309cd238dcf68600f

To me it looks like ktime_get_real_ns() isn't ready or updated when we 
are calling iio_get_time_ns().
If we look in the trace ktime_get_real_ns() it's ready when we are 
getting the first sample after suspend.

Running with this patch:
https://gist.github.com/sknsean/415d1b9c34f20db4419a0c61a58eb188
+
The first from this thread.

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 1976 bytes --]

> 
> 
> On 02/06/2020 15.39, Sean Nyekjaer wrote:
> > > > are these values from the hw FIFO? can you please add
> > > > sensor->ts_ref to the trace and
> > > > a log into st_lsm6dsx_reset_hw_ts?
> > > > 
> > > 
> > > Hi,
> > > 
> > > This certainly looks weird,
> > > 
> > > https://gist.github.com/sknsean/b32bae140008cf446a8fea58e305da47
> > > 
> > > Seems like the ts_ref is updated and used but not read/used in
> > > userspace...
> > > 
> > > /Sean
> > 
> > added to st_lsm6dsx_read_fifo :
> > 
> > printk("ts_ref %lld, ts %lld, sample_time %lld\n", acc_sensor->ts_ref,
> > ts, acc_sensor->ts_ref + ts);
> > 
> > https://gist.github.com/sknsean/3ad1e9e05cb0e2ef811a3c83492a1980
> > 
> > Suspend again was 15sec
> > 
> > /Sean
> 
> Hi,
> 
> Some more findings :)
> https://gist.github.com/sknsean/d31e48b65515361309cd238dcf68600f
> 
> To me it looks like ktime_get_real_ns() isn't ready or updated when we are
> calling iio_get_time_ns().
> If we look in the trace ktime_get_real_ns() it's ready when we are getting
> the first sample after suspend.
> 
> Running with this patch:
> https://gist.github.com/sknsean/415d1b9c34f20db4419a0c61a58eb188
> +
> The first from this thread.
> 
> /Sean

Hi Sean,

looking at the logs I guess we should not reset the sensor hw ts. Could you
please try the below patch?

Regards,
Lorenzo

diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
index 0b776cb91928..4f8a9bcee77b 100644
--- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
+++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
@@ -2445,6 +2445,8 @@ static int __maybe_unused st_lsm6dsx_resume(struct device *dev)
 		if (!(hw->suspend_mask & BIT(sensor->id)))
 			continue;
 
+		sensor->ts_ref = iio_get_time_ns(hw->iio_devs[i]);
+
 		if (sensor->id == ST_LSM6DSX_ID_EXT0 ||
 		    sensor->id == ST_LSM6DSX_ID_EXT1 ||
 		    sensor->id == ST_LSM6DSX_ID_EXT2)

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 03/06/2020 10.06, Lorenzo Bianconi wrote:
>>
>>
>> On 02/06/2020 15.39, Sean Nyekjaer wrote:
>>>>> are these values from the hw FIFO? can you please add
>>>>> sensor->ts_ref to the trace and
>>>>> a log into st_lsm6dsx_reset_hw_ts?
>>>>>
>>>>
>>>> Hi,
>>>>
>>>> This certainly looks weird,
>>>>
>>>> https://gist.github.com/sknsean/b32bae140008cf446a8fea58e305da47
>>>>
>>>> Seems like the ts_ref is updated and used but not read/used in
>>>> userspace...
>>>>
>>>> /Sean
>>>
>>> added to st_lsm6dsx_read_fifo :
>>>
>>> printk("ts_ref %lld, ts %lld, sample_time %lld\n", acc_sensor->ts_ref,
>>> ts, acc_sensor->ts_ref + ts);
>>>
>>> https://gist.github.com/sknsean/3ad1e9e05cb0e2ef811a3c83492a1980
>>>
>>> Suspend again was 15sec
>>>
>>> /Sean
>>
>> Hi,
>>
>> Some more findings :)
>> https://gist.github.com/sknsean/d31e48b65515361309cd238dcf68600f
>>
>> To me it looks like ktime_get_real_ns() isn't ready or updated when we are
>> calling iio_get_time_ns().
>> If we look in the trace ktime_get_real_ns() it's ready when we are getting
>> the first sample after suspend.
>>
>> Running with this patch:
>> https://gist.github.com/sknsean/415d1b9c34f20db4419a0c61a58eb188
>> +
>> The first from this thread.
>>
>> /Sean
> 
> Hi Sean,
> 
> looking at the logs I guess we should not reset the sensor hw ts. Could you
> please try the below patch?
> 
> Regards,
> Lorenzo
> 
> diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> index 0b776cb91928..4f8a9bcee77b 100644
> --- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> +++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> @@ -2445,6 +2445,8 @@ static int __maybe_unused st_lsm6dsx_resume(struct device *dev)
>   		if (!(hw->suspend_mask & BIT(sensor->id)))
>   			continue;
>   
> +		sensor->ts_ref = iio_get_time_ns(hw->iio_devs[i]);
> +
>   		if (sensor->id == ST_LSM6DSX_ID_EXT0 ||
>   		    sensor->id == ST_LSM6DSX_ID_EXT1 ||
>   		    sensor->id == ST_LSM6DSX_ID_EXT2)
> 

Hmm, suspend again for 15s.

https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1

[  105.520634] PM: suspend exit
[  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time 
1591097310641881385

[  105.548416] ktime_get_real_ns: 1591097322928175385

CLOCK_REALTIME isn't ready in the resume function. I think we need to 
link it to CLOCK_BOOTTIME (Which ticking under suspend) instead.

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 2997 bytes --]

> 
> 
> On 03/06/2020 10.06, Lorenzo Bianconi wrote:
> > > 
> > > 
> > > On 02/06/2020 15.39, Sean Nyekjaer wrote:
> > > > > > are these values from the hw FIFO? can you please add
> > > > > > sensor->ts_ref to the trace and
> > > > > > a log into st_lsm6dsx_reset_hw_ts?
> > > > > > 
> > > > > 
> > > > > Hi,
> > > > > 
> > > > > This certainly looks weird,
> > > > > 
> > > > > https://gist.github.com/sknsean/b32bae140008cf446a8fea58e305da47
> > > > > 
> > > > > Seems like the ts_ref is updated and used but not read/used in
> > > > > userspace...
> > > > > 
> > > > > /Sean
> > > > 
> > > > added to st_lsm6dsx_read_fifo :
> > > > 
> > > > printk("ts_ref %lld, ts %lld, sample_time %lld\n", acc_sensor->ts_ref,
> > > > ts, acc_sensor->ts_ref + ts);
> > > > 
> > > > https://gist.github.com/sknsean/3ad1e9e05cb0e2ef811a3c83492a1980
> > > > 
> > > > Suspend again was 15sec
> > > > 
> > > > /Sean
> > > 
> > > Hi,
> > > 
> > > Some more findings :)
> > > https://gist.github.com/sknsean/d31e48b65515361309cd238dcf68600f
> > > 
> > > To me it looks like ktime_get_real_ns() isn't ready or updated when we are
> > > calling iio_get_time_ns().
> > > If we look in the trace ktime_get_real_ns() it's ready when we are getting
> > > the first sample after suspend.
> > > 
> > > Running with this patch:
> > > https://gist.github.com/sknsean/415d1b9c34f20db4419a0c61a58eb188
> > > +
> > > The first from this thread.
> > > 
> > > /Sean
> > 
> > Hi Sean,
> > 
> > looking at the logs I guess we should not reset the sensor hw ts. Could you
> > please try the below patch?
> > 
> > Regards,
> > Lorenzo
> > 
> > diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> > index 0b776cb91928..4f8a9bcee77b 100644
> > --- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> > +++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> > @@ -2445,6 +2445,8 @@ static int __maybe_unused st_lsm6dsx_resume(struct device *dev)
> >   		if (!(hw->suspend_mask & BIT(sensor->id)))
> >   			continue;
> > +		sensor->ts_ref = iio_get_time_ns(hw->iio_devs[i]);
> > +
> >   		if (sensor->id == ST_LSM6DSX_ID_EXT0 ||
> >   		    sensor->id == ST_LSM6DSX_ID_EXT1 ||
> >   		    sensor->id == ST_LSM6DSX_ID_EXT2)
> > 
> 
> Hmm, suspend again for 15s.
> 
> https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
> 
> [  105.520634] PM: suspend exit
> [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
> 1591097310641881385
> 
> [  105.548416] ktime_get_real_ns: 1591097322928175385
> 
> CLOCK_REALTIME isn't ready in the resume function. I think we need to link
> it to CLOCK_BOOTTIME (Which ticking under suspend) instead.

With latest patch it seems to me the time reported is now monotonic so it seems
correct. What is the clocktype you set? you can check it in:
/sys/bus/iio/devices/iio:device<x>/current_timestamp_clock

Regards,
Lorenzo

> 
> /Sean

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

>>
>> Hmm, suspend again for 15s.
>>
>> https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
>>
>> [  105.520634] PM: suspend exit
>> [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
>> 1591097310641881385
>>
>> [  105.548416] ktime_get_real_ns: 1591097322928175385
>>
>> CLOCK_REALTIME isn't ready in the resume function. I think we need to link
>> it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
> 
> With latest patch it seems to me the time reported is now monotonic so it seems
> correct. What is the clocktype you set? you can check it in:
> /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock

default: realtime

In the dump above the ktime_get_real_ns(first fifo dump after suspend) - 
  ts_ref + ts is = 12,286294 sec...

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 1015 bytes --]

> > > 
> > > Hmm, suspend again for 15s.
> > > 
> > > https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
> > > 
> > > [  105.520634] PM: suspend exit
> > > [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
> > > 1591097310641881385
> > > 
> > > [  105.548416] ktime_get_real_ns: 1591097322928175385
> > > 
> > > CLOCK_REALTIME isn't ready in the resume function. I think we need to link
> > > it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
> > 
> > With latest patch it seems to me the time reported is now monotonic so it seems
> > correct. What is the clocktype you set? you can check it in:
> > /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock
> 
> default: realtime
> 
> In the dump above the ktime_get_real_ns(first fifo dump after suspend) -
> ts_ref + ts is = 12,286294 sec...
> 
> /Sean

right. Could you please add to the dump log the ts_ref value in st_lsm6dsx_resume()
just after iio_get_time_ns()?

Regards,
Lorenzo

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 03/06/2020 12.51, Lorenzo Bianconi wrote:
>>>>
>>>> Hmm, suspend again for 15s.
>>>>
>>>> https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
>>>>
>>>> [  105.520634] PM: suspend exit
>>>> [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
>>>> 1591097310641881385
>>>>
>>>> [  105.548416] ktime_get_real_ns: 1591097322928175385
>>>>
>>>> CLOCK_REALTIME isn't ready in the resume function. I think we need to link
>>>> it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
>>>
>>> With latest patch it seems to me the time reported is now monotonic so it seems
>>> correct. What is the clocktype you set? you can check it in:
>>> /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock
>>
>> default: realtime
>>
>> In the dump above the ktime_get_real_ns(first fifo dump after suspend) -
>> ts_ref + ts is = 12,286294 sec...
>>
>> /Sean
> 
> right. Could you please add to the dump log the ts_ref value in st_lsm6dsx_resume()
> just after iio_get_time_ns()?
> 
Sure,

[  173.849649] ktime_get_real_ns: 1591097391339190269

[  173.855244] ts_ref 1591097386868224810, ts 4488650000, sample_time 
1591097391356874810

[  173.855272] ktime_get_real_ns: 1591097391344812894

[  173.861256] PM: suspend devices took 0.080 seconds

[  173.875214] Disabling non-boot CPUs ...
[  173.887482] sensor->ts_ref[1] = 1591097391377130644

[  173.906546] PM: resume devices took 0.020 seconds

[  174.028152] OOM killer enabled.
[  174.031331] Restarting tasks ... done.
[  174.078636] PM: suspend exit
[  174.127877] ts_ref 1591097391377130644, ts 4531750000, sample_time 
1591097395908880644

[  174.136383] ktime_get_real_ns: 1591097405112347968

[  174.145841] ts_ref 1591097391377130644, ts 4570200000, sample_time 
1591097395947330644

[  174.154031] ktime_get_real_ns: 1591097405129995760

Missing 13,73 sec :(

If the CLOCK_REALTIME was updated in resume(), I think the first patch 
proposal was better.

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 2283 bytes --]

> 
> 
> On 03/06/2020 12.51, Lorenzo Bianconi wrote:
> > > > > 
> > > > > Hmm, suspend again for 15s.
> > > > > 
> > > > > https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
> > > > > 
> > > > > [  105.520634] PM: suspend exit
> > > > > [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
> > > > > 1591097310641881385
> > > > > 
> > > > > [  105.548416] ktime_get_real_ns: 1591097322928175385
> > > > > 
> > > > > CLOCK_REALTIME isn't ready in the resume function. I think we need to link
> > > > > it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
> > > > 
> > > > With latest patch it seems to me the time reported is now monotonic so it seems
> > > > correct. What is the clocktype you set? you can check it in:
> > > > /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock
> > > 
> > > default: realtime
> > > 
> > > In the dump above the ktime_get_real_ns(first fifo dump after suspend) -
> > > ts_ref + ts is = 12,286294 sec...
> > > 
> > > /Sean
> > 
> > right. Could you please add to the dump log the ts_ref value in st_lsm6dsx_resume()
> > just after iio_get_time_ns()?
> > 
> Sure,
> 
> [  173.849649] ktime_get_real_ns: 1591097391339190269
> 
> [  173.855244] ts_ref 1591097386868224810, ts 4488650000, sample_time
> 1591097391356874810
> 
> [  173.855272] ktime_get_real_ns: 1591097391344812894
> 
> [  173.861256] PM: suspend devices took 0.080 seconds
> 
> [  173.875214] Disabling non-boot CPUs ...
> [  173.887482] sensor->ts_ref[1] = 1591097391377130644
> 
> [  173.906546] PM: resume devices took 0.020 seconds
> 
> [  174.028152] OOM killer enabled.
> [  174.031331] Restarting tasks ... done.
> [  174.078636] PM: suspend exit
> [  174.127877] ts_ref 1591097391377130644, ts 4531750000, sample_time
> 1591097395908880644
> 
> [  174.136383] ktime_get_real_ns: 1591097405112347968
> 
> [  174.145841] ts_ref 1591097391377130644, ts 4570200000, sample_time
> 1591097395947330644
> 
> [  174.154031] ktime_get_real_ns: 1591097405129995760
> 
> Missing 13,73 sec :(
> 
> If the CLOCK_REALTIME was updated in resume(), I think the first patch
> proposal was better.

Can you please try to use CLOCK_BOOTTIME instead?

Regards,
Lorenzo

> 
> /Sean

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 03/06/2020 14.12, Lorenzo Bianconi wrote:
>>
>>
>> On 03/06/2020 12.51, Lorenzo Bianconi wrote:
>>>>>>
>>>>>> Hmm, suspend again for 15s.
>>>>>>
>>>>>> https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
>>>>>>
>>>>>> [  105.520634] PM: suspend exit
>>>>>> [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
>>>>>> 1591097310641881385
>>>>>>
>>>>>> [  105.548416] ktime_get_real_ns: 1591097322928175385
>>>>>>
>>>>>> CLOCK_REALTIME isn't ready in the resume function. I think we need to link
>>>>>> it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
>>>>>
>>>>> With latest patch it seems to me the time reported is now monotonic so it seems
>>>>> correct. What is the clocktype you set? you can check it in:
>>>>> /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock
>>>>
>>>> default: realtime
>>>>
>>>> In the dump above the ktime_get_real_ns(first fifo dump after suspend) -
>>>> ts_ref + ts is = 12,286294 sec...
>>>>
>>>> /Sean
>>>
>>> right. Could you please add to the dump log the ts_ref value in st_lsm6dsx_resume()
>>> just after iio_get_time_ns()?
>>>
>> Sure,
>>
>> [  173.849649] ktime_get_real_ns: 1591097391339190269
>>
>> [  173.855244] ts_ref 1591097386868224810, ts 4488650000, sample_time
>> 1591097391356874810
>>
>> [  173.855272] ktime_get_real_ns: 1591097391344812894
>>
>> [  173.861256] PM: suspend devices took 0.080 seconds
>>
>> [  173.875214] Disabling non-boot CPUs ...
>> [  173.887482] sensor->ts_ref[1] = 1591097391377130644
>>
>> [  173.906546] PM: resume devices took 0.020 seconds
>>
>> [  174.028152] OOM killer enabled.
>> [  174.031331] Restarting tasks ... done.
>> [  174.078636] PM: suspend exit
>> [  174.127877] ts_ref 1591097391377130644, ts 4531750000, sample_time
>> 1591097395908880644
>>
>> [  174.136383] ktime_get_real_ns: 1591097405112347968
>>
>> [  174.145841] ts_ref 1591097391377130644, ts 4570200000, sample_time
>> 1591097395947330644
>>
>> [  174.154031] ktime_get_real_ns: 1591097405129995760
>>
>> Missing 13,73 sec :(
>>
>> If the CLOCK_REALTIME was updated in resume(), I think the first patch
>> proposal was better.
> 
> Can you please try to use CLOCK_BOOTTIME instead?
> 

With CLOCK_BOOTTIME and only the ts_ref reset.

[ 4978.971598] ts_ref 4987298377539, ts 19975950000, sample_time 
5007274327539

[ 4978.971618] ktime_get_real_ns: 1591102209947858582
[ 4978.974386] ts_ref 4987298377539, ts 20014375000, sample_time 
5007312752539

[ 4978.974408] ktime_get_real_ns: 1591102209950647832
[ 4978.977333] ts_ref 4987298377539, ts 20052825000, sample_time 
5007351202539

[ 4978.977355] ktime_get_real_ns: 1591102209953595374
[ 4978.980179] ts_ref 4987298377539, ts 20091250000, sample_time 
5007389627539

[ 4978.980199] ktime_get_real_ns: 1591102209956438707
[ 4979.002747] ts_ref 4987298377539, ts 20129700000, sample_time 
5007428077539

[ 4979.002893] ktime_get_real_ns: 1591102209979130499
[ 4979.009099] PM: suspend devices took 0.070 seconds

[ 4979.022969] Disabling non-boot CPUs ...
[ 4979.035611] sensor->ts_ref[1] = 5007372366999
[ 4979.056233] PM: resume devices took 0.030 seconds
[ 4979.157652] OOM killer enabled.
[ 4979.160828] Restarting tasks ... done.
[ 4979.203811] PM: suspend exit
[ 4979.272383] ts_ref 5007372366999, ts 20171250000, sample_time 
5027543616999

[ 4979.279816] ktime_get_real_ns: 1591102224105489426
[ 4979.288129] ts_ref 5007372366999, ts 20209700000, sample_time 
5027582066999

[ 4979.295147] ktime_get_real_ns: 1591102224120826134
[ 4979.303178] ts_ref 5007372366999, ts 20248125000, sample_time 
5027620491999

[ 4979.310393] ktime_get_real_ns: 1591102224136066468
[ 4979.318377] ts_ref 5007372366999, ts 20286575000, sample_time 
5027658941999

[ 4979.325395] ktime_get_real_ns: 1591102224151074634

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 4515 bytes --]

> 
> 
> On 03/06/2020 14.12, Lorenzo Bianconi wrote:
> > > 
> > > 
> > > On 03/06/2020 12.51, Lorenzo Bianconi wrote:
> > > > > > > 
> > > > > > > Hmm, suspend again for 15s.
> > > > > > > 
> > > > > > > https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
> > > > > > > 
> > > > > > > [  105.520634] PM: suspend exit
> > > > > > > [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
> > > > > > > 1591097310641881385
> > > > > > > 
> > > > > > > [  105.548416] ktime_get_real_ns: 1591097322928175385
> > > > > > > 
> > > > > > > CLOCK_REALTIME isn't ready in the resume function. I think we need to link
> > > > > > > it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
> > > > > > 
> > > > > > With latest patch it seems to me the time reported is now monotonic so it seems
> > > > > > correct. What is the clocktype you set? you can check it in:
> > > > > > /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock
> > > > > 
> > > > > default: realtime
> > > > > 
> > > > > In the dump above the ktime_get_real_ns(first fifo dump after suspend) -
> > > > > ts_ref + ts is = 12,286294 sec...
> > > > > 
> > > > > /Sean
> > > > 
> > > > right. Could you please add to the dump log the ts_ref value in st_lsm6dsx_resume()
> > > > just after iio_get_time_ns()?
> > > > 
> > > Sure,
> > > 
> > > [  173.849649] ktime_get_real_ns: 1591097391339190269
> > > 
> > > [  173.855244] ts_ref 1591097386868224810, ts 4488650000, sample_time
> > > 1591097391356874810
> > > 
> > > [  173.855272] ktime_get_real_ns: 1591097391344812894
> > > 
> > > [  173.861256] PM: suspend devices took 0.080 seconds
> > > 
> > > [  173.875214] Disabling non-boot CPUs ...
> > > [  173.887482] sensor->ts_ref[1] = 1591097391377130644
> > > 
> > > [  173.906546] PM: resume devices took 0.020 seconds
> > > 
> > > [  174.028152] OOM killer enabled.
> > > [  174.031331] Restarting tasks ... done.
> > > [  174.078636] PM: suspend exit
> > > [  174.127877] ts_ref 1591097391377130644, ts 4531750000, sample_time
> > > 1591097395908880644
> > > 
> > > [  174.136383] ktime_get_real_ns: 1591097405112347968
> > > 
> > > [  174.145841] ts_ref 1591097391377130644, ts 4570200000, sample_time
> > > 1591097395947330644
> > > 
> > > [  174.154031] ktime_get_real_ns: 1591097405129995760
> > > 
> > > Missing 13,73 sec :(
> > > 
> > > If the CLOCK_REALTIME was updated in resume(), I think the first patch
> > > proposal was better.
> > 
> > Can you please try to use CLOCK_BOOTTIME instead?
> > 
> 
> With CLOCK_BOOTTIME and only the ts_ref reset.
> 
> [ 4978.971598] ts_ref 4987298377539, ts 19975950000, sample_time
> 5007274327539
> 
> [ 4978.971618] ktime_get_real_ns: 1591102209947858582
> [ 4978.974386] ts_ref 4987298377539, ts 20014375000, sample_time
> 5007312752539
> 
> [ 4978.974408] ktime_get_real_ns: 1591102209950647832
> [ 4978.977333] ts_ref 4987298377539, ts 20052825000, sample_time
> 5007351202539
> 
> [ 4978.977355] ktime_get_real_ns: 1591102209953595374
> [ 4978.980179] ts_ref 4987298377539, ts 20091250000, sample_time
> 5007389627539
> 
> [ 4978.980199] ktime_get_real_ns: 1591102209956438707
> [ 4979.002747] ts_ref 4987298377539, ts 20129700000, sample_time
> 5007428077539
> 
> [ 4979.002893] ktime_get_real_ns: 1591102209979130499
> [ 4979.009099] PM: suspend devices took 0.070 seconds
> 
> [ 4979.022969] Disabling non-boot CPUs ...
> [ 4979.035611] sensor->ts_ref[1] = 5007372366999
> [ 4979.056233] PM: resume devices took 0.030 seconds
> [ 4979.157652] OOM killer enabled.
> [ 4979.160828] Restarting tasks ... done.
> [ 4979.203811] PM: suspend exit
> [ 4979.272383] ts_ref 5007372366999, ts 20171250000, sample_time
> 5027543616999
> 
> [ 4979.279816] ktime_get_real_ns: 1591102224105489426
> [ 4979.288129] ts_ref 5007372366999, ts 20209700000, sample_time
> 5027582066999
> 
> [ 4979.295147] ktime_get_real_ns: 1591102224120826134
> [ 4979.303178] ts_ref 5007372366999, ts 20248125000, sample_time
> 5027620491999
> 
> [ 4979.310393] ktime_get_real_ns: 1591102224136066468
> [ 4979.318377] ts_ref 5007372366999, ts 20286575000, sample_time
> 5027658941999
> 
> [ 4979.325395] ktime_get_real_ns: 1591102224151074634
> 
> /Sean

Looking at the timestamps it seems to me the suspend lasts for ~20s, is it
correct? Anyway I agree with you I think we need to use my first patch. Can you
please give it a whirl with CLOCK_BOOTIME?

Regards,
Lorenzo

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 03/06/2020 14.56, Lorenzo Bianconi wrote:
>>
>>
>> On 03/06/2020 14.12, Lorenzo Bianconi wrote:
>>>>
>>>>
>>>> On 03/06/2020 12.51, Lorenzo Bianconi wrote:
>>>>>>>>
>>>>>>>> Hmm, suspend again for 15s.
>>>>>>>>
>>>>>>>> https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
>>>>>>>>
>>>>>>>> [  105.520634] PM: suspend exit
>>>>>>>> [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
>>>>>>>> 1591097310641881385
>>>>>>>>
>>>>>>>> [  105.548416] ktime_get_real_ns: 1591097322928175385
>>>>>>>>
>>>>>>>> CLOCK_REALTIME isn't ready in the resume function. I think we need to link
>>>>>>>> it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
>>>>>>>
>>>>>>> With latest patch it seems to me the time reported is now monotonic so it seems
>>>>>>> correct. What is the clocktype you set? you can check it in:
>>>>>>> /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock
>>>>>>
>>>>>> default: realtime
>>>>>>
>>>>>> In the dump above the ktime_get_real_ns(first fifo dump after suspend) -
>>>>>> ts_ref + ts is = 12,286294 sec...
>>>>>>
>>>>>> /Sean
>>>>>
>>>>> right. Could you please add to the dump log the ts_ref value in st_lsm6dsx_resume()
>>>>> just after iio_get_time_ns()?
>>>>>
>>>> Sure,
>>>>
>>>> [  173.849649] ktime_get_real_ns: 1591097391339190269
>>>>
>>>> [  173.855244] ts_ref 1591097386868224810, ts 4488650000, sample_time
>>>> 1591097391356874810
>>>>
>>>> [  173.855272] ktime_get_real_ns: 1591097391344812894
>>>>
>>>> [  173.861256] PM: suspend devices took 0.080 seconds
>>>>
>>>> [  173.875214] Disabling non-boot CPUs ...
>>>> [  173.887482] sensor->ts_ref[1] = 1591097391377130644
>>>>
>>>> [  173.906546] PM: resume devices took 0.020 seconds
>>>>
>>>> [  174.028152] OOM killer enabled.
>>>> [  174.031331] Restarting tasks ... done.
>>>> [  174.078636] PM: suspend exit
>>>> [  174.127877] ts_ref 1591097391377130644, ts 4531750000, sample_time
>>>> 1591097395908880644
>>>>
>>>> [  174.136383] ktime_get_real_ns: 1591097405112347968
>>>>
>>>> [  174.145841] ts_ref 1591097391377130644, ts 4570200000, sample_time
>>>> 1591097395947330644
>>>>
>>>> [  174.154031] ktime_get_real_ns: 1591097405129995760
>>>>
>>>> Missing 13,73 sec :(
>>>>
>>>> If the CLOCK_REALTIME was updated in resume(), I think the first patch
>>>> proposal was better.
>>>
>>> Can you please try to use CLOCK_BOOTTIME instead?
>>>
>>
>> With CLOCK_BOOTTIME and only the ts_ref reset.
>>
>> [ 4978.971598] ts_ref 4987298377539, ts 19975950000, sample_time
>> 5007274327539
>>
>> [ 4978.971618] ktime_get_real_ns: 1591102209947858582
>> [ 4978.974386] ts_ref 4987298377539, ts 20014375000, sample_time
>> 5007312752539
>>
>> [ 4978.974408] ktime_get_real_ns: 1591102209950647832
>> [ 4978.977333] ts_ref 4987298377539, ts 20052825000, sample_time
>> 5007351202539
>>
>> [ 4978.977355] ktime_get_real_ns: 1591102209953595374
>> [ 4978.980179] ts_ref 4987298377539, ts 20091250000, sample_time
>> 5007389627539
>>
>> [ 4978.980199] ktime_get_real_ns: 1591102209956438707
>> [ 4979.002747] ts_ref 4987298377539, ts 20129700000, sample_time
>> 5007428077539
>>
>> [ 4979.002893] ktime_get_real_ns: 1591102209979130499
>> [ 4979.009099] PM: suspend devices took 0.070 seconds
>>
>> [ 4979.022969] Disabling non-boot CPUs ...
>> [ 4979.035611] sensor->ts_ref[1] = 5007372366999
>> [ 4979.056233] PM: resume devices took 0.030 seconds
>> [ 4979.157652] OOM killer enabled.
>> [ 4979.160828] Restarting tasks ... done.
>> [ 4979.203811] PM: suspend exit
>> [ 4979.272383] ts_ref 5007372366999, ts 20171250000, sample_time
>> 5027543616999
>>
>> [ 4979.279816] ktime_get_real_ns: 1591102224105489426
>> [ 4979.288129] ts_ref 5007372366999, ts 20209700000, sample_time
>> 5027582066999
>>
>> [ 4979.295147] ktime_get_real_ns: 1591102224120826134
>> [ 4979.303178] ts_ref 5007372366999, ts 20248125000, sample_time
>> 5027620491999
>>
>> [ 4979.310393] ktime_get_real_ns: 1591102224136066468
>> [ 4979.318377] ts_ref 5007372366999, ts 20286575000, sample_time
>> 5027658941999
>>
>> [ 4979.325395] ktime_get_real_ns: 1591102224151074634
>>
>> /Sean
> 
> Looking at the timestamps it seems to me the suspend lasts for ~20s, is it
> correct? Anyway I agree with you I think we need to use my first patch. Can you
> please give it a whirl with CLOCK_BOOTIME?

With boottime, and the first patch.

The suspend command is:
echo 0 > /sys/class/rtc/rtc0/wakealarm && echo +15 > 
/sys/class/rtc/rtc0/wakealarm && echo mem > /sys/power/state

So I would expect the suspend time to be less than 15 sec.

[ 6537.865508] ts_ref 6585250169306, ts 8625925000, sample_time 
6593876094306

[ 6537.865536] ktime_get_real_ns: 1591103796485022099

[ 6537.871552] PM: suspend devices took 0.080 seconds

[ 6537.885280] Disabling non-boot CPUs ...

[ 6537.899371] st_lsm6dsx_resume_fifo

[ 6537.899402] Before[0]: 1591103787879280639

[ 6537.899422] Before[1]: 6585250169306

[ 6537.900217] st_lsm6dsx_reset_hw_ts

[ 6537.900259] ktime_get_real_ns: 1591103796519856474, ktime_get_ns: 
6537884499736, ktime_get_raw_ns: 6537884504487

[ 6537.900292] ktime_get_real_ns: 1591103796519893224, ktime_get_ns: 
6537884536486, ktime_get_raw_ns: 6537884539029

[ 6537.900310] After[0]: 1591103796519853599

[ 6537.900328] After[1]: 6593880296516

[ 6537.900356] ktime_get_real_ns: 1591103796519957140, ktime_get_ns: 
6537884601902, ktime_get_raw_ns: 6537884604445

[ 6537.918836] PM: resume devices took 0.030 seconds

[ 6538.080211] OOM killer enabled.

[ 6538.083390] Restarting tasks ... done.

[ 6538.136320] ts_ref 6593880296516, ts 38050000, sample_time 6593918346516

[ 6538.143076] ktime_get_real_ns: 1591103810106102968

[ 6538.149991] PM: suspend exit

[ 6538.155039] ts_ref 6593880296516, ts 76500000, sample_time 6593956796516

[ 6538.162015] ktime_get_real_ns: 1591103810125036385

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 6954 bytes --]

> 
> 
> On 03/06/2020 14.56, Lorenzo Bianconi wrote:
> > > 
> > > 
> > > On 03/06/2020 14.12, Lorenzo Bianconi wrote:
> > > > > 
> > > > > 
> > > > > On 03/06/2020 12.51, Lorenzo Bianconi wrote:
> > > > > > > > > 
> > > > > > > > > Hmm, suspend again for 15s.
> > > > > > > > > 
> > > > > > > > > https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
> > > > > > > > > 
> > > > > > > > > [  105.520634] PM: suspend exit
> > > > > > > > > [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
> > > > > > > > > 1591097310641881385
> > > > > > > > > 
> > > > > > > > > [  105.548416] ktime_get_real_ns: 1591097322928175385
> > > > > > > > > 
> > > > > > > > > CLOCK_REALTIME isn't ready in the resume function. I think we need to link
> > > > > > > > > it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
> > > > > > > > 
> > > > > > > > With latest patch it seems to me the time reported is now monotonic so it seems
> > > > > > > > correct. What is the clocktype you set? you can check it in:
> > > > > > > > /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock
> > > > > > > 
> > > > > > > default: realtime
> > > > > > > 
> > > > > > > In the dump above the ktime_get_real_ns(first fifo dump after suspend) -
> > > > > > > ts_ref + ts is = 12,286294 sec...
> > > > > > > 
> > > > > > > /Sean
> > > > > > 
> > > > > > right. Could you please add to the dump log the ts_ref value in st_lsm6dsx_resume()
> > > > > > just after iio_get_time_ns()?
> > > > > > 
> > > > > Sure,
> > > > > 
> > > > > [  173.849649] ktime_get_real_ns: 1591097391339190269
> > > > > 
> > > > > [  173.855244] ts_ref 1591097386868224810, ts 4488650000, sample_time
> > > > > 1591097391356874810
> > > > > 
> > > > > [  173.855272] ktime_get_real_ns: 1591097391344812894
> > > > > 
> > > > > [  173.861256] PM: suspend devices took 0.080 seconds
> > > > > 
> > > > > [  173.875214] Disabling non-boot CPUs ...
> > > > > [  173.887482] sensor->ts_ref[1] = 1591097391377130644
> > > > > 
> > > > > [  173.906546] PM: resume devices took 0.020 seconds
> > > > > 
> > > > > [  174.028152] OOM killer enabled.
> > > > > [  174.031331] Restarting tasks ... done.
> > > > > [  174.078636] PM: suspend exit
> > > > > [  174.127877] ts_ref 1591097391377130644, ts 4531750000, sample_time
> > > > > 1591097395908880644
> > > > > 
> > > > > [  174.136383] ktime_get_real_ns: 1591097405112347968
> > > > > 
> > > > > [  174.145841] ts_ref 1591097391377130644, ts 4570200000, sample_time
> > > > > 1591097395947330644
> > > > > 
> > > > > [  174.154031] ktime_get_real_ns: 1591097405129995760
> > > > > 
> > > > > Missing 13,73 sec :(
> > > > > 
> > > > > If the CLOCK_REALTIME was updated in resume(), I think the first patch
> > > > > proposal was better.
> > > > 
> > > > Can you please try to use CLOCK_BOOTTIME instead?
> > > > 
> > > 
> > > With CLOCK_BOOTTIME and only the ts_ref reset.
> > > 
> > > [ 4978.971598] ts_ref 4987298377539, ts 19975950000, sample_time
> > > 5007274327539
> > > 
> > > [ 4978.971618] ktime_get_real_ns: 1591102209947858582
> > > [ 4978.974386] ts_ref 4987298377539, ts 20014375000, sample_time
> > > 5007312752539
> > > 
> > > [ 4978.974408] ktime_get_real_ns: 1591102209950647832
> > > [ 4978.977333] ts_ref 4987298377539, ts 20052825000, sample_time
> > > 5007351202539
> > > 
> > > [ 4978.977355] ktime_get_real_ns: 1591102209953595374
> > > [ 4978.980179] ts_ref 4987298377539, ts 20091250000, sample_time
> > > 5007389627539
> > > 
> > > [ 4978.980199] ktime_get_real_ns: 1591102209956438707
> > > [ 4979.002747] ts_ref 4987298377539, ts 20129700000, sample_time
> > > 5007428077539
> > > 
> > > [ 4979.002893] ktime_get_real_ns: 1591102209979130499
> > > [ 4979.009099] PM: suspend devices took 0.070 seconds
> > > 
> > > [ 4979.022969] Disabling non-boot CPUs ...
> > > [ 4979.035611] sensor->ts_ref[1] = 5007372366999
> > > [ 4979.056233] PM: resume devices took 0.030 seconds
> > > [ 4979.157652] OOM killer enabled.
> > > [ 4979.160828] Restarting tasks ... done.
> > > [ 4979.203811] PM: suspend exit
> > > [ 4979.272383] ts_ref 5007372366999, ts 20171250000, sample_time
> > > 5027543616999
> > > 
> > > [ 4979.279816] ktime_get_real_ns: 1591102224105489426
> > > [ 4979.288129] ts_ref 5007372366999, ts 20209700000, sample_time
> > > 5027582066999
> > > 
> > > [ 4979.295147] ktime_get_real_ns: 1591102224120826134
> > > [ 4979.303178] ts_ref 5007372366999, ts 20248125000, sample_time
> > > 5027620491999
> > > 
> > > [ 4979.310393] ktime_get_real_ns: 1591102224136066468
> > > [ 4979.318377] ts_ref 5007372366999, ts 20286575000, sample_time
> > > 5027658941999
> > > 
> > > [ 4979.325395] ktime_get_real_ns: 1591102224151074634
> > > 
> > > /Sean
> > 
> > Looking at the timestamps it seems to me the suspend lasts for ~20s, is it
> > correct? Anyway I agree with you I think we need to use my first patch. Can you
> > please give it a whirl with CLOCK_BOOTIME?
> 
> With boottime, and the first patch.
> 
> The suspend command is:
> echo 0 > /sys/class/rtc/rtc0/wakealarm && echo +15 >
> /sys/class/rtc/rtc0/wakealarm && echo mem > /sys/power/state
> 
> So I would expect the suspend time to be less than 15 sec.
> 
> [ 6537.865508] ts_ref 6585250169306, ts 8625925000, sample_time
> 6593876094306
> 
> [ 6537.865536] ktime_get_real_ns: 1591103796485022099
> 
> [ 6537.871552] PM: suspend devices took 0.080 seconds
> 
> [ 6537.885280] Disabling non-boot CPUs ...
> 
> [ 6537.899371] st_lsm6dsx_resume_fifo
> 
> [ 6537.899402] Before[0]: 1591103787879280639
> 
> [ 6537.899422] Before[1]: 6585250169306
> 
> [ 6537.900217] st_lsm6dsx_reset_hw_ts
> 
> [ 6537.900259] ktime_get_real_ns: 1591103796519856474, ktime_get_ns:
> 6537884499736, ktime_get_raw_ns: 6537884504487
> 
> [ 6537.900292] ktime_get_real_ns: 1591103796519893224, ktime_get_ns:
> 6537884536486, ktime_get_raw_ns: 6537884539029
> 
> [ 6537.900310] After[0]: 1591103796519853599
> 
> [ 6537.900328] After[1]: 6593880296516
> 
> [ 6537.900356] ktime_get_real_ns: 1591103796519957140, ktime_get_ns:
> 6537884601902, ktime_get_raw_ns: 6537884604445
> 
> [ 6537.918836] PM: resume devices took 0.030 seconds
> 
> [ 6538.080211] OOM killer enabled.
> 
> [ 6538.083390] Restarting tasks ... done.
> 
> [ 6538.136320] ts_ref 6593880296516, ts 38050000, sample_time 6593918346516
> 
> [ 6538.143076] ktime_get_real_ns: 1591103810106102968
> 
> [ 6538.149991] PM: suspend exit
> 
> [ 6538.155039] ts_ref 6593880296516, ts 76500000, sample_time 6593956796516
> 
> [ 6538.162015] ktime_get_real_ns: 1591103810125036385
> 
> /Sean

so to follow-up:
- you set clock_boottime for the accel
- the expected suspend time is ~15s
- the reported time is ~8s (looking at ts_ref).

Could you please post even the syslog just before the suspend?

Regards,
Lorenzo


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

On 03/06/2020 15.40, Lorenzo Bianconi wrote:
>>
>>
>> On 03/06/2020 14.56, Lorenzo Bianconi wrote:
>>>>
>>>>
>>>> On 03/06/2020 14.12, Lorenzo Bianconi wrote:
>>>>>>
>>>>>>
>>>>>> On 03/06/2020 12.51, Lorenzo Bianconi wrote:
>>>>>>>>>>
>>>>>>>>>> Hmm, suspend again for 15s.
>>>>>>>>>>
>>>>>>>>>> https://gist.github.com/sknsean/911ae4ae2e74ebe1e7eca1405c645ff1
>>>>>>>>>>
>>>>>>>>>> [  105.520634] PM: suspend exit
>>>>>>>>>> [  105.540206] ts_ref 1591097307780181385, ts 2861700000, sample_time
>>>>>>>>>> 1591097310641881385
>>>>>>>>>>
>>>>>>>>>> [  105.548416] ktime_get_real_ns: 1591097322928175385
>>>>>>>>>>
>>>>>>>>>> CLOCK_REALTIME isn't ready in the resume function. I think we need to link
>>>>>>>>>> it to CLOCK_BOOTTIME (Which ticking under suspend) instead.
>>>>>>>>>
>>>>>>>>> With latest patch it seems to me the time reported is now monotonic so it seems
>>>>>>>>> correct. What is the clocktype you set? you can check it in:
>>>>>>>>> /sys/bus/iio/devices/iio:device<x>/current_timestamp_clock
>>>>>>>>
>>>>>>>> default: realtime
>>>>>>>>
>>>>>>>> In the dump above the ktime_get_real_ns(first fifo dump after suspend) -
>>>>>>>> ts_ref + ts is = 12,286294 sec...
>>>>>>>>
>>>>>>>> /Sean
>>>>>>>
>>>>>>> right. Could you please add to the dump log the ts_ref value in st_lsm6dsx_resume()
>>>>>>> just after iio_get_time_ns()?
>>>>>>>
>>>>>> Sure,
>>>>>>
>>>>>> [  173.849649] ktime_get_real_ns: 1591097391339190269
>>>>>>
>>>>>> [  173.855244] ts_ref 1591097386868224810, ts 4488650000, sample_time
>>>>>> 1591097391356874810
>>>>>>
>>>>>> [  173.855272] ktime_get_real_ns: 1591097391344812894
>>>>>>
>>>>>> [  173.861256] PM: suspend devices took 0.080 seconds
>>>>>>
>>>>>> [  173.875214] Disabling non-boot CPUs ...
>>>>>> [  173.887482] sensor->ts_ref[1] = 1591097391377130644
>>>>>>
>>>>>> [  173.906546] PM: resume devices took 0.020 seconds
>>>>>>
>>>>>> [  174.028152] OOM killer enabled.
>>>>>> [  174.031331] Restarting tasks ... done.
>>>>>> [  174.078636] PM: suspend exit
>>>>>> [  174.127877] ts_ref 1591097391377130644, ts 4531750000, sample_time
>>>>>> 1591097395908880644
>>>>>>
>>>>>> [  174.136383] ktime_get_real_ns: 1591097405112347968
>>>>>>
>>>>>> [  174.145841] ts_ref 1591097391377130644, ts 4570200000, sample_time
>>>>>> 1591097395947330644
>>>>>>
>>>>>> [  174.154031] ktime_get_real_ns: 1591097405129995760
>>>>>>
>>>>>> Missing 13,73 sec :(
>>>>>>
>>>>>> If the CLOCK_REALTIME was updated in resume(), I think the first patch
>>>>>> proposal was better.
>>>>>
>>>>> Can you please try to use CLOCK_BOOTTIME instead?
>>>>>
>>>>
>>>> With CLOCK_BOOTTIME and only the ts_ref reset.
>>>>
>>>> [ 4978.971598] ts_ref 4987298377539, ts 19975950000, sample_time
>>>> 5007274327539
>>>>
>>>> [ 4978.971618] ktime_get_real_ns: 1591102209947858582
>>>> [ 4978.974386] ts_ref 4987298377539, ts 20014375000, sample_time
>>>> 5007312752539
>>>>
>>>> [ 4978.974408] ktime_get_real_ns: 1591102209950647832
>>>> [ 4978.977333] ts_ref 4987298377539, ts 20052825000, sample_time
>>>> 5007351202539
>>>>
>>>> [ 4978.977355] ktime_get_real_ns: 1591102209953595374
>>>> [ 4978.980179] ts_ref 4987298377539, ts 20091250000, sample_time
>>>> 5007389627539
>>>>
>>>> [ 4978.980199] ktime_get_real_ns: 1591102209956438707
>>>> [ 4979.002747] ts_ref 4987298377539, ts 20129700000, sample_time
>>>> 5007428077539
>>>>
>>>> [ 4979.002893] ktime_get_real_ns: 1591102209979130499
>>>> [ 4979.009099] PM: suspend devices took 0.070 seconds
>>>>
>>>> [ 4979.022969] Disabling non-boot CPUs ...
>>>> [ 4979.035611] sensor->ts_ref[1] = 5007372366999
>>>> [ 4979.056233] PM: resume devices took 0.030 seconds
>>>> [ 4979.157652] OOM killer enabled.
>>>> [ 4979.160828] Restarting tasks ... done.
>>>> [ 4979.203811] PM: suspend exit
>>>> [ 4979.272383] ts_ref 5007372366999, ts 20171250000, sample_time
>>>> 5027543616999
>>>>
>>>> [ 4979.279816] ktime_get_real_ns: 1591102224105489426
>>>> [ 4979.288129] ts_ref 5007372366999, ts 20209700000, sample_time
>>>> 5027582066999
>>>>
>>>> [ 4979.295147] ktime_get_real_ns: 1591102224120826134
>>>> [ 4979.303178] ts_ref 5007372366999, ts 20248125000, sample_time
>>>> 5027620491999
>>>>
>>>> [ 4979.310393] ktime_get_real_ns: 1591102224136066468
>>>> [ 4979.318377] ts_ref 5007372366999, ts 20286575000, sample_time
>>>> 5027658941999
>>>>
>>>> [ 4979.325395] ktime_get_real_ns: 1591102224151074634
>>>>
>>>> /Sean
>>>
>>> Looking at the timestamps it seems to me the suspend lasts for ~20s, is it
>>> correct? Anyway I agree with you I think we need to use my first patch. Can you
>>> please give it a whirl with CLOCK_BOOTIME?
>>
>> With boottime, and the first patch.
>>
>> The suspend command is:
>> echo 0 > /sys/class/rtc/rtc0/wakealarm && echo +15 >
>> /sys/class/rtc/rtc0/wakealarm && echo mem > /sys/power/state
>>
>> So I would expect the suspend time to be less than 15 sec.
>>
>> [ 6537.865508] ts_ref 6585250169306, ts 8625925000, sample_time
>> 6593876094306
>>
>> [ 6537.865536] ktime_get_real_ns: 1591103796485022099
>>
>> [ 6537.871552] PM: suspend devices took 0.080 seconds
>>
>> [ 6537.885280] Disabling non-boot CPUs ...
>>
>> [ 6537.899371] st_lsm6dsx_resume_fifo
>>
>> [ 6537.899402] Before[0]: 1591103787879280639
>>
>> [ 6537.899422] Before[1]: 6585250169306
>>
>> [ 6537.900217] st_lsm6dsx_reset_hw_ts
>>
>> [ 6537.900259] ktime_get_real_ns: 1591103796519856474, ktime_get_ns:
>> 6537884499736, ktime_get_raw_ns: 6537884504487
>>
>> [ 6537.900292] ktime_get_real_ns: 1591103796519893224, ktime_get_ns:
>> 6537884536486, ktime_get_raw_ns: 6537884539029
>>
>> [ 6537.900310] After[0]: 1591103796519853599
>>
>> [ 6537.900328] After[1]: 6593880296516
>>
>> [ 6537.900356] ktime_get_real_ns: 1591103796519957140, ktime_get_ns:
>> 6537884601902, ktime_get_raw_ns: 6537884604445
>>
>> [ 6537.918836] PM: resume devices took 0.030 seconds
>>
>> [ 6538.080211] OOM killer enabled.
>>
>> [ 6538.083390] Restarting tasks ... done.
>>
>> [ 6538.136320] ts_ref 6593880296516, ts 38050000, sample_time 6593918346516
>>
>> [ 6538.143076] ktime_get_real_ns: 1591103810106102968
>>
>> [ 6538.149991] PM: suspend exit
>>
>> [ 6538.155039] ts_ref 6593880296516, ts 76500000, sample_time 6593956796516
>>
>> [ 6538.162015] ktime_get_real_ns: 1591103810125036385
>>
>> /Sean
> 
> so to follow-up:
> - you set clock_boottime for the accel
> - the expected suspend time is ~15s
> - the reported time is ~8s (looking at ts_ref).
Yes :)
> 
> Could you please post even the syslog just before the suspend?
> 

https://gist.github.com/sknsean/047169d1e192783eaae0504879fed484

Looks like CLOCK_BOOTTIME isn't updated either in the resume() function.

/Sean

Added some more debug:

================================
diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c 
b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c

index fa02e90e95c3..cabadf4f04e7 100644

--- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c

+++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c

@@ -2417,6 +2417,8 @@ static int __maybe_unused 
st_lsm6dsx_suspend(struct device *dev)

         if (hw->fifo_mask)

                 err = st_lsm6dsx_flush_fifo(hw);



+       printk("st_lsm6dsx_suspend boottime %lld\n", 
ktime_get_boottime_ns());

+

         return err;

  }



@@ -2453,6 +2455,8 @@ static int __maybe_unused st_lsm6dsx_resume(struct 
device *dev)

         if (hw->fifo_mask)

                 err = st_lsm6dsx_resume_fifo(hw);



+       printk("st_lsm6dsx_resume boottime %lld\n", 
ktime_get_boottime_ns());

+

         return err;

  }

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

Hi Thomas,

I have a question regarding CLOCK_REALTIME and CLOCK_BOOTTIME when 
resuming from suspend.

We have run into problems with 
drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c + the first patch from 
Lorenzo Bianconi in this thread.
The accelerometer have an internal FIFO that includes a timestamp. When 
we resume from suspend,
the driver resets the fifo ts counter and sets an internal reference to 
that time.
But to me it looks like both CLOCK_REALTIME and CLOCK_BOOTIME aren't 
ready when st_lsm6dsx_resume() is called.

If this is a limitation, can you point to other drivers that have been 
able to workaround it?
Or can we wait for a flag or similar?

Best regards,
Sean Nyekjaer

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Thomas Gleixner]

Sean,

Sean Nyekjaer <sean@geanix.com> writes:
> I have a question regarding CLOCK_REALTIME and CLOCK_BOOTTIME when 
> resuming from suspend.
>
> We have run into problems with
> drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c + the first patch from
> Lorenzo Bianconi in this thread.  The accelerometer have an internal
> FIFO that includes a timestamp. When we resume from suspend, the
> driver resets the fifo ts counter and sets an internal reference to
> that time.
>
> But to me it looks like both CLOCK_REALTIME and CLOCK_BOOTIME aren't 
> ready when st_lsm6dsx_resume() is called.

That depends on your system. Timekeeping is resumed way before drivers
are resumed, but the suspend time injection might happen late when there
is no early device to read from. In this case it happens when the RTC is
resumed.

If the IIO driver resumes before the RTC which injects the suspend time,
then the core time is still in the past. And RTC is using the default
resume mechanism, so depending on device/class registration order this
might be the case. Deferring to the PM & RTC wizards.

Thanks,

        tglx

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Sean Nyekjaer]

>  From f4ea9019d3b6fb1ad80747cf378bf1fbdebd3dd8 Mon Sep 17 00:00:00 2001
> Message-Id: <f4ea9019d3b6fb1ad80747cf378bf1fbdebd3dd8.1590699935.git.lorenzo@kernel.org>
> From: Lorenzo Bianconi <lorenzo@kernel.org>
> Date: Thu, 28 May 2020 23:05:16 +0200
> Subject: [PATCH] iio: imu: st_lsm6dsx: reset hw ts after resume
>
> Signed-off-by: Lorenzo Bianconi <lorenzo@kernel.org>
> ---
>   drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h       |  3 +--
>   .../iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c    | 23 ++++++++++++-------
>   drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c  |  2 +-
>   3 files changed, 17 insertions(+), 11 deletions(-)
>
> diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h
> index b56df409ed0f..529970195b39 100644
> --- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h
> +++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx.h
> @@ -436,8 +436,7 @@ int st_lsm6dsx_update_watermark(struct st_lsm6dsx_sensor *sensor,
>   				u16 watermark);
>   int st_lsm6dsx_update_fifo(struct st_lsm6dsx_sensor *sensor, bool enable);
>   int st_lsm6dsx_flush_fifo(struct st_lsm6dsx_hw *hw);
> -int st_lsm6dsx_set_fifo_mode(struct st_lsm6dsx_hw *hw,
> -			     enum st_lsm6dsx_fifo_mode fifo_mode);
> +int st_lsm6dsx_resume_fifo(struct st_lsm6dsx_hw *hw);
>   int st_lsm6dsx_read_fifo(struct st_lsm6dsx_hw *hw);
>   int st_lsm6dsx_read_tagged_fifo(struct st_lsm6dsx_hw *hw);
>   int st_lsm6dsx_check_odr(struct st_lsm6dsx_sensor *sensor, u32 odr, u8 *val);
> diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
> index afd00daeefb2..7de10bd636ea 100644
> --- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
> +++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_buffer.c
> @@ -184,8 +184,8 @@ static int st_lsm6dsx_update_decimators(struct st_lsm6dsx_hw *hw)
>   	return err;
>   }
>   
> -int st_lsm6dsx_set_fifo_mode(struct st_lsm6dsx_hw *hw,
> -			     enum st_lsm6dsx_fifo_mode fifo_mode)
> +static int st_lsm6dsx_set_fifo_mode(struct st_lsm6dsx_hw *hw,
> +				    enum st_lsm6dsx_fifo_mode fifo_mode)
>   {
>   	unsigned int data;
>   
> @@ -302,6 +302,18 @@ static int st_lsm6dsx_reset_hw_ts(struct st_lsm6dsx_hw *hw)
>   	return 0;
>   }
>   
> +int st_lsm6dsx_resume_fifo(struct st_lsm6dsx_hw *hw)
> +{
> +	int err;
> +
> +	/* reset hw ts counter */
> +	err = st_lsm6dsx_reset_hw_ts(hw);
> +	if (err < 0)
> +		return err;
> +
> +	return st_lsm6dsx_set_fifo_mode(hw, ST_LSM6DSX_FIFO_CONT);
> +}
> +
>   /*
>    * Set max bulk read to ST_LSM6DSX_MAX_WORD_LEN/ST_LSM6DSX_MAX_TAGGED_WORD_LEN
>    * in order to avoid a kmalloc for each bus access
> @@ -675,12 +687,7 @@ int st_lsm6dsx_update_fifo(struct st_lsm6dsx_sensor *sensor, bool enable)
>   		goto out;
>   
>   	if (fifo_mask) {
> -		/* reset hw ts counter */
> -		err = st_lsm6dsx_reset_hw_ts(hw);
> -		if (err < 0)
> -			goto out;
> -
> -		err = st_lsm6dsx_set_fifo_mode(hw, ST_LSM6DSX_FIFO_CONT);
> +		err = st_lsm6dsx_resume_fifo(hw);
>   		if (err < 0)
>   			goto out;
>   	}
> diff --git a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> index 0b776cb91928..b3a08e3e2359 100644
> --- a/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> +++ b/drivers/iio/imu/st_lsm6dsx/st_lsm6dsx_core.c
> @@ -2458,7 +2458,7 @@ static int __maybe_unused st_lsm6dsx_resume(struct device *dev)
>   	}
>   
>   	if (hw->fifo_mask)
> -		err = st_lsm6dsx_set_fifo_mode(hw, ST_LSM6DSX_FIFO_CONT);
> +		err = st_lsm6dsx_resume_fifo(hw);
>   
>   	return err;
>   }
Hi Lorenzo,

Will you sent this as a real patch?

/Sean

Re: IIO timestamp get skewed when suspending (st_lsm6dsx)

[Lorenzo Bianconi]

[-- Attachment #1: Type: text/plain, Size: 168 bytes --]

[...]

> >   }
> Hi Lorenzo,
> 
> Will you sent this as a real patch?

Hi Sean,

sure, I will post it so you can test it.

Regards,
Lorenzo

> 
> /Sean

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]