drivers: timer: nrf: Optimize k_cycle_get_32(). #9275

pizi-nordic · 2018-08-03T13:10:31Z

The previous implementation of _timer_cycle_get_32() (which is directly
mapped to k_cycle_get_32()) taken from 87 to 132 cycles. As result it
was too heavy for using it as source of time for logger.

This commit makes this function faster by removing redundant access
to the RTC register (each access consumed 28 CPU cycles) as well as
loop, which made this call non-deterministic.

After these changes the k_cycle_get_32() needs only 50-52 cycles
in to calculate 32-bit timestamp.

This PR fixes #8798.

codecov-io · 2018-08-03T13:34:31Z

Codecov Report

Merging #9275 into master will not change coverage.
The diff coverage is n/a.

@@           Coverage Diff           @@
##           master    #9275   +/-   ##
=======================================
  Coverage   52.65%   52.65%           
=======================================
  Files         202      202           
  Lines       25330    25330           
  Branches     5301     5301           
=======================================
  Hits        13337    13337           
  Misses       9894     9894           
  Partials     2099     2099

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 18cec24...481011a. Read the comment docs.

carlescufi · 2018-08-03T21:52:10Z

recheck

cvinayak · 2018-08-04T09:11:08Z

drivers/timer/nrf_rtc_timer.c

-				 RTC_MASK;
-		rtc_prev = rtc_now;
-		rtc_now = RTC_COUNTER;
-	} while (rtc_now != rtc_prev);


This loop ensures that at any realtime the returned value is not off by 1 system clock tick.

I think that such "protection" does not give any value:

int get_time() { int time; /* * If RTC_REGISTER changes here, code below will get updated value. */ do { time = RTC_REGISTER; /* * If RTC_REGISTER changes here, the loop will actually delay * return from the function and returned value will include * effect of the delay. */ } while (time != RTC_REGISTER) /* * If RTC_REGISTER changes here, value returned by this function will * be off by 1 system clock cycle. */ return time; }

In both versions, the one with loop and the one without, there is risk that a "stale" value will be returned. It is unavoidable, as even return from the function takes time and RTC counter could be updated during that period. I personally do not see any benefit from this loop (especially as in this case access to RTC is atomic and there is no risk that we get inconsistent value of the register).

What you are not considering is the one clock tick that elapses, and the kernel cannot tolerate a stale clock tick. You can use your implementation on nRF52 boards and run a typical peripheral sample, it will stall eventually when the system clock ticks between the reading of the kernel variable and reading of the RTC counter.

Are you mentioning here problem you pointed there: #9275 (comment) ? If so, please look on my comment posted here: #9275 (comment)

I understand your explanation. except for:
/*

If RTC_REGISTER changes here, value returned by this function will

be off by 1 system clock tick.
*/

Here the returned value is only off by 1 cycle, not 1 system clock tick.

But as long as, tests cases pass as before, I am ok with the changes (because I am not very well informed on the kernel's use of this function).

That is true. I had 1 clock cycle in my mind, not tick. Example updated.

cvinayak · 2018-08-04T09:17:26Z

drivers/timer/nrf_rtc_timer.c

+	ticked_cycles = sys_clock_tick_count * sys_clock_hw_cycles_per_tick;
+
+	/* Number of timer cycles since last announced tick we know about. */
+	elapsed_cycles = rtc_count - (ticked_cycles & RTC_MASK);


rtc_count rollover needs handling. Mask the entire RHS to get the absolute difference.

Fixed. Thank you.
Feel free to look at the updated code.

cvinayak · 2018-08-04T09:22:23Z

drivers/timer/nrf_rtc_timer.c

+	 * outdated at this point. However the value of rtc_count will
+	 * include missed ticks.
+	 */
+	rtc_count = RTC_COUNTER;


When _sys_clock_tick_count is incremented by the ISR between lines 559 and 571, then at that realtime, system clock ticks versus the returned value from this function is off by 1 clock tick. (kernel will setup a wake up in the past, causing a hang).

I think that it is compensated by rtc_count. Please note that the _sys_clock_tick_count is read before the RTC_COUNTER register (this order is enforced by compiler barrier). As RTC_COUNTER is not reset on tick, it will include the missed time.

Please look at the following example:

RTC_COUNTER value:...............100..............200...............300 tick:..............................1................2.................3 _sys_clock_tick_count read: ^ RTC_COUNTER read: ^

In this example we we read _sys_clock_tick_count somewhere between tick 1 and 2. The read value was 1. Then we got an interrupt, which delayed RTC_COUNTER read (which returned 250, as RTC is counting all the time). The final calculation uses cached value of _sys_clock_tick_count (which is stale in this example) and current value of RTC_COUNTER:

ticked_cycles = cached _sys_clock_tick_count * RTC_COUNTS_PER_TICK = 1 * 100 = 100
elapsed_cycles = RTC_COUNT - ticked_cycles = 250 - 100 = 150
(please note that elapsed_cycles is larger than one tick).

total_time = 100 + 150 = 250 (correct)

anangl · 2018-08-06T06:36:31Z

drivers/timer/nrf_rtc_timer.c

-		rtc_now = RTC_COUNTER;
-	} while (rtc_now != rtc_prev);
+	/* Get number of announced ticks. */
+	sys_clock_tick_count = _sys_clock_tick_count;


I don't see much value in having the number of sys ticks in a local variable. Actually, it may be a bit confusing.
What would be wrong in computing timer cycles directly here? Like this:

/* Number of timer cycles announced as ticks so far. */ ticked_cycles = _sys_clock_tick_count * sys_clock_hw_cycles_per_tick;

I would also simplify the following part. To me seeing just this:

/* Make sure that compiler will not reverse access to RTC and * _sys_clock_tick_count. */ compiler_barrier(); /* Number of timer cycles since last announced tick we know about. */ elapsed_cycles = ((RTC_COUNTER - ticked_cycles) & RTC_MASK); return ticked_cycles + elapsed_cycles;

would make it easier to get what is actually done here.

I tried to explain the whole idea, however you are right that the code was a bit too long for the job.
Feel free to look at the updated code.

anangl · 2018-08-06T13:18:54Z

drivers/timer/nrf_rtc_timer.c

+
+	/* Number of timer cycles since last announced tick we know about.
+	 *
+	 * The value of RTC_COUNTER is not reset on tick, so it could


Not only it could, but even it will compensate this.

anangl · 2018-08-06T13:23:37Z

drivers/timer/nrf_rtc_timer.c

+	 * which could have happen between the ticked_cycles calculation
+	 * and the code below.
+	 */
+	elapsed_cycles = (RTC_COUNTER - (ticked_cycles & RTC_MASK)) & RTC_MASK;


Do you really need to do this masking twice? I think that only the final one will be sufficient (the upper bits are discarded anyway, so it doesn't matter if they are all zeros, all ones, or a mix of these).

@cvinayak: What is your opinion about this?

I agree with @anangl, single overall masking is sufficient.

I thought so, however I wanted to hear your opinion before I do the change. Fixed.

cvinayak · 2018-08-06T13:50:33Z

@pizi-nordic could you check #9310 , which is failing even before your PR over master, this was the test suite that used to fail prior to the changes done for #3665 in #374

pizi-nordic · 2018-08-06T13:53:22Z

@cvinayak: #9137 should fix #9310. You also might need changes from #9073.

cvinayak · 2018-08-06T14:13:55Z

@pizi-nordic could you also change the implementation in lines 278, 336, and 379 in a separate commit.

pizi-nordic · 2018-08-06T14:51:50Z

@cvinayak: Done, please check.

cvinayak · 2018-08-06T17:53:53Z

drivers/timer/nrf_rtc_timer.c

-		rtc_prev = rtc_now;
-		rtc_now = RTC_COUNTER;
-	} while (rtc_prev != rtc_now);
+	rtc_elapsed = (RTC_COUNTER - rtc_past) & RTC_MASK;


you have to read the rtc_past before RTC_COUNTER, just like what you did in the other commit.

Updated. Please note, that old code did the opposite (RTC_COUNTER was read before rtc_prev).

cvinayak · 2018-08-06T17:58:32Z

drivers/timer/nrf_rtc_timer.c


+	rtc_elapsed = (RTC_COUNTER - rtc_past) & RTC_MASK;


same here, rtc_past needs to be read before RTC_COUNTER, as rtc_past is modified by ISR. Is it ok if rtc_past changes between the statements?

Updated. Similarly like in the previous case, the old code did the opposite (RTC_COUNTER was read before rtc_prev).

anangl · 2018-08-07T07:48:37Z

drivers/timer/nrf_rtc_timer.c

-	return (sys_clock_tick_count * sys_clock_hw_cycles_per_tick) +
-	       elapsed_cycles;
+	/* Number of timer cycles announced as ticks so far. */
+	ticked_cycles = _sys_clock_tick_count * sys_clock_hw_cycles_per_tick;


Now I realized that this information was stored in rtc_past, so actually there's no need to do this multiplication here.

There is subtle difference:

rtc_past = (_sys_clock_tick_count * sys_clock_hw_cycles_per_tick) & RTC_MASK; ticked_cycles = (_sys_clock_tick_count * sys_clock_hw_cycles_per_tick);

We are doing this multiplication because we want 32-bit timestamp which will not wrap up when RTC do so.

Right. I missed it.

However, ;-)
it seems that rtc_past could be stored without prior masking (then it could be used instead of the multiplication mentioned above), as in all places where it is later used the masking would be done anyway (either by using RTC_MASK or in hardware when rtc_compare_set is called).

But I guess this can be left as a field for future optimizations.

cvinayak · 2018-08-07T20:48:55Z

drivers/timer/nrf_rtc_timer.c


-	/*Convert number of Machine cycles to SYS TICS*/
+	/* Convert number of Machine cycles to SYS TICS */


SYS_TICKS. Otherwise, PR LGTM now.

The previous implementation of _timer_cycle_get_32() (which is directly mapped to k_cycle_get_32()) taken from 87 to 132 cycles. As result it was too heavy for using it as source of time for logger. This commit makes this function faster by removing redundant access to the RTC register (each access consumed 28 CPU cycles) as well as loop, which made this call non-deterministic. After these changes the k_cycle_get_32() needs only 50-52 cycles in to calculate 32-bit timestamp. Signed-off-by: Piotr Zięcik <[email protected]>

cvinayak · 2018-08-08T19:19:40Z

@pizi-nordic @carlescufi LGTM

ioannisg · 2018-08-10T10:00:34Z

drivers/timer/nrf_rtc_timer.c

+	/* Read _sys_clock_tick_count and rtc_past before RTC_COUNTER */
+	elapsed = _sys_clock_tick_count;
+	rtc_past_copy = rtc_past;
+	compiler_barrier();


Why do we need the compiler_barrier here? should we add an inline comment that justifies it?

According to @cvinayak, the rtc_past must be read before RTC_COUNTER. Barrier ensures the correct order.

Comment regarding barrier usage is in other function in this file. I have not seen a reason for placing same comment in other places. Do you think, that it is needed?

I don't see the problem of placing the same comment in 2 locations in a file. It is really educative in this case.

ioannisg

Looks good, only few minor comments from my side.

This commit removes redundant reads of RTC_COUNTER register propagating optimizations made in the k_cycle_get_32() function. Signed-off-by: Piotr Zięcik <[email protected]>

pizi-nordic requested review from cvinayak and anangl August 3, 2018 13:18

cvinayak requested changes Aug 4, 2018

View reviewed changes

anangl reviewed Aug 6, 2018

View reviewed changes

pizi-nordic force-pushed the faster_k_cycle_get_32 branch from a103a78 to e8a3ebe Compare August 6, 2018 12:37

anangl reviewed Aug 6, 2018

View reviewed changes

pizi-nordic force-pushed the faster_k_cycle_get_32 branch 2 times, most recently from 531c87d to 06321e7 Compare August 6, 2018 13:49

cvinayak requested changes Aug 6, 2018

View reviewed changes

pizi-nordic mentioned this pull request Aug 7, 2018

nRF52_PCA10040: Failing test_slice_reset #9310

Closed

anangl reviewed Aug 7, 2018

View reviewed changes

pizi-nordic force-pushed the faster_k_cycle_get_32 branch from 0f8807d to 07fd9cf Compare August 7, 2018 10:47

cvinayak requested changes Aug 7, 2018

View reviewed changes

anangl approved these changes Aug 8, 2018

View reviewed changes

pizi-nordic force-pushed the faster_k_cycle_get_32 branch from 07fd9cf to 9650c4d Compare August 8, 2018 13:49

cvinayak approved these changes Aug 8, 2018

View reviewed changes

cvinayak requested a review from carlescufi August 8, 2018 19:19

ioannisg reviewed Aug 10, 2018

View reviewed changes

driver: timer: nrf: Remove redundant RTC_COUNTER reads.

481011a

This commit removes redundant reads of RTC_COUNTER register propagating optimizations made in the k_cycle_get_32() function. Signed-off-by: Piotr Zięcik <[email protected]>

pizi-nordic force-pushed the faster_k_cycle_get_32 branch from 9650c4d to 481011a Compare August 13, 2018 14:43

ioannisg approved these changes Aug 13, 2018

View reviewed changes

nashif merged commit 24abedb into zephyrproject-rtos:master Aug 13, 2018

pizi-nordic deleted the faster_k_cycle_get_32 branch August 20, 2018 12:40


		/Convert number of Machine cycles to SYS TICS/
		/* Convert number of Machine cycles to SYS TICS */

drivers: timer: nrf: Optimize k_cycle_get_32(). #9275

drivers: timer: nrf: Optimize k_cycle_get_32(). #9275

Conversation

pizi-nordic commented Aug 3, 2018

codecov-io commented Aug 3, 2018 • edited Loading

Codecov Report

carlescufi commented Aug 3, 2018

Choose a reason for hiding this comment

pizi-nordic Aug 6, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pizi-nordic Aug 6, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pizi-nordic Aug 6, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pizi-nordic Aug 6, 2018 • edited Loading

Choose a reason for hiding this comment

cvinayak commented Aug 6, 2018

pizi-nordic commented Aug 6, 2018 • edited Loading

cvinayak commented Aug 6, 2018

pizi-nordic commented Aug 6, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cvinayak commented Aug 8, 2018

Choose a reason for hiding this comment

pizi-nordic Aug 10, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ioannisg left a comment

Choose a reason for hiding this comment

codecov-io commented Aug 3, 2018 •

edited

Loading

pizi-nordic Aug 6, 2018 •

edited

Loading

pizi-nordic Aug 6, 2018 •

edited

Loading

pizi-nordic Aug 6, 2018 •

edited

Loading

pizi-nordic Aug 6, 2018 •

edited

Loading

pizi-nordic commented Aug 6, 2018 •

edited

Loading

pizi-nordic Aug 10, 2018 •

edited

Loading