Subscription interval is not exact

[HubertHugo]

SHA: 5d8599d195a93dfe5473f64e4f888c322e5df1d2 platform: nRF52840 all-clusters-app

Interval between two report data massages is not exactly the same as the one set as maxInterval. It sends messages fractions of seconds later and after ~15 iterations there is over a second of shift relative to maxInterval*15. It is because timer is set after the report data message is delivered from DUT, so time of processing it is added to the interval. Should it work that way?

onoff subscribe on-time 10 10 1 1
[1655290369.705164][59815:59820] CHIP:TOO: Sending command to node 0x1
[1655290369.705215][59815:59820] CHIP:CSM: FindOrEstablishSession: PeerId = E4D1E42D6E4E70B9:0000000000000001
[1655290369.705250][59815:59820] CHIP:TOO: Sending SubscribeAttribute to:
[1655290369.705278][59815:59820] CHIP:TOO: 	cluster 0x0000_0006, attribute: 0x0000_4001, endpoint 1
[1655290369.705422][59815:59820] CHIP:IN: Prepared secure message 0x556cdbdb4668 to 0x0000000000000001 (1)  of type 0x3 and protocolId (0, 1) on exchange 46797i with MessageCounter:127636367.
[1655290369.705469][59815:59820] CHIP:IN: Sending encrypted msg 0x556cdbdb4668 with MessageCounter:127636367 to 0x0000000000000001 (1) at monotonic time: 0000000000CDC23B msec
[1655290369.705658][59815:59820] CHIP:DMG: MoveToState ReadClient[0x7f44000043e0]: Moving to [AwaitingIn]
[1655290369.838184][59815:59820] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:188732742 on exchange 46797i
[1655290369.838218][59815:59820] CHIP:EM: Found matching exchange: 46797i, Delegate: 0x7f44000043e0
[1655290369.838240][59815:59820] CHIP:EM: Rxd Ack; Removing MessageCounter:127636367 from Retrans Table on exchange 46797i
[1655290369.838247][59815:59820] CHIP:EM: Removed CHIP MessageCounter:127636367 from RetransTable on exchange 46797i
[1655290369.838292][59815:59820] CHIP:DMG: ReportDataMessage =
[...]
[1655290379.957396][59815:59820] CHIP:DMG: ReportDataMessage =
[1655290390.029809][59815:59820] CHIP:DMG: ReportDataMessage =
[1655290400.095938][59815:59820] CHIP:DMG: ReportDataMessage =
[...]
[1655290933.573732][59815:59820] CHIP:DMG: ReportDataMessage =

[bzbarsky-apple]

@mrjerryjohns @yunhanw-google

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.