2010-06-23 19:22:23

by Patrick Pannuto

[permalink] [raw]
Subject: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

*** INTRO ***

As discussed here ( http://lkml.org/lkml/2007/8/3/250 ), msleep(1) is not
precise enough for many drivers (yes, sleep precision is an unfair notion,
but consistently sleeping for ~an order of magnitude greater than requested
is worth fixing). This patch adds a usleep API so that udelay does not have
to be used. Obviously not every udelay can be replaced (those in atomic
contexts or being used for simple bitbanging come to mind), but there are
many, many examples of

mydriver_write(...)
/* Wait for hardware to latch */
udelay(100)

in various drivers where a busy-wait loop is neither beneficial nor
necessary, but msleep simply does not provide enough precision and people
are using a busy-wait loop instead.


*** SOME QUANTIFIABLE (?) NUMBERS ***

My focus is on Android, so I started by replacing the udelays in
drivers/i2c/busses/i2c-msm.c:

267: udelay(100) --> usleep_range(100, 200)
283: udelay(100) --> usleep_range(100, 200)
333: udelay(20) --> usleep(20)

and measured wakeups after Android was completely booted and stable
across 100 trials (throwing away the first) like so:

for i in {1..100}; do
echo "=== Trial $i" >> test.txt;
echo 1 > /proc/timer_stats; sleep 10; echo 0 > /proc/timer_stats;
cat /proc/timer_stats >> test.txt;
sleep 2s;
done

then averaged the results to see if there was any benefit:

=== ORIGINAL (99 samples) ========================================= ORIGINAL ===
Avg: 188.760000 wakeups in 9.911010 secs (19.045486 wkups/sec) [18876 total]
Wakeups: Min - 179, Max - 208, Mean - 190.666667, Stdev - 6.601194

=== USLEEP (99 samples) ============================================= USLEEP ===
Avg: 188.200000 wakeups in 9.911230 secs (18.988561 wkups/sec) [18820 total]
Wakeups: Min - 181, Max - 213, Mean - 190.101010, Stdev - 6.950757

While not particularly rigorous, the results seem to indicate that there may be
some benefit from pursuing this.


*** HOW MUCH BENEFIT? ***

Somewhat arbitrarily choosing 100 as a cut-off for udelay VS usleep:

git grep 'udelay([[:digit:]]\+)' |
perl -F"[\(\)]" -anl -e 'print if $F[1] >= 100' | wc -l

yeilds 1093 on Linus's tree. There are 313 instances of >= 1000 and still
another 53 >= 10000us of busy wait! (If AVOID_POPS is configured in, the
es18xx driver will udelay(100000) or *0.1 seconds of busy wait*)


*** SUMMARY ***

I believe the usleep functions provide a tangible benefit, but would like
some input before I go for a more thorough udelay removal. Also, at what
point is a reasonable cutoff between udelay and usleep? I found two dated
(2007) papers discussing the overhead of a context switch:

http://www.cs.rochester.edu/u/cli/research/switch.pdf
IBM eServer, dual 2.0GHz Pentium Xeon; 512 KB L2, cache line 128B
Linux 2.6.17, RHEL 9, gcc 3.2.2 (-O0)
3.8 us / context switch

http://delivery.acm.org/10.1145/1290000/1281703/a3-david.pdf
ARMv5, ARM926EJ-S on an OMAP1610 (set to 120MHz clock)
Linux 2.6.20-rc5-omap1
48 us / context switch

However, there is more to consider than just context switching; is there
anyone who knows an appropriate cut-off, or an appropriate way to measure
and find one?


Finally, to address any potential questions of why this isn't built on
top of do_nanosleep, the function usleep_range seems very valuable for
power applications; many of the delays are simply waiting for something
to complete, thus I would prefer if they did not themselves instigate
a wake-up; also, do_nanosleep seems like it is built to be an interface
for the user-space nanosleep function - it did not seem like a good fit.

-Pat



>From 26193064936016e3f679c911b4e988a3de97c531 Mon Sep 17 00:00:00 2001
From: Patrick Pannuto <[email protected]>
Date: Tue, 22 Jun 2010 10:08:08 -0700
Subject: [PATCH] timer: Added usleep[_range][_interruptable] timer

usleep[_range][_interruptable] are finer precision implmentations
of msleep[_interruptable] and are designed to be drop-in
replacements for udelay where a precise sleep / busy-wait is
unnecessary. They also allow an easy interface to specify slack
when a precise (ish) wakeup is unnecessary to help minimize wakeups

Change-Id: I277737744ca58061323837609b121a0fc9d27f33
Change-Id: I088f14e905fc569c0a728fff5dc61ef25f49bb1e
Signed-off-by: Patrick Pannuto <[email protected]>
---
include/linux/delay.h | 12 ++++++++++++
kernel/timer.c | 44 ++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 56 insertions(+), 0 deletions(-)

diff --git a/include/linux/delay.h b/include/linux/delay.h
index fd832c6..13f5378 100644
--- a/include/linux/delay.h
+++ b/include/linux/delay.h
@@ -45,6 +45,18 @@ extern unsigned long lpj_fine;
void calibrate_delay(void);
void msleep(unsigned int msecs);
unsigned long msleep_interruptible(unsigned int msecs);
+void usleep_range(unsigned long min, unsigned long max);
+unsigned long usleep_range_interruptible(unsigned long min, unsigned long max);
+
+static inline void usleep(unsigned long usecs)
+{
+ usleep_range(usecs, usecs);
+}
+
+static inline unsigned long usleep_interruptible(unsigned long usecs)
+{
+ return usleep_range_interruptible(usecs, usecs);
+}

static inline void ssleep(unsigned int seconds)
{
diff --git a/kernel/timer.c b/kernel/timer.c
index 5db5a8d..1587dad 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -1684,3 +1684,47 @@ unsigned long msleep_interruptible(unsigned int msecs)
}

EXPORT_SYMBOL(msleep_interruptible);
+
+static int __sched do_usleep_range(unsigned long min, unsigned long max)
+{
+ ktime_t kmin;
+ unsigned long delta;
+
+ kmin = ktime_set(0, min * NSEC_PER_USEC);
+ delta = max - min;
+ return schedule_hrtimeout_range(&kmin, delta, HRTIMER_MODE_REL);
+}
+
+/**
+ * usleep_range - Drop in replacement for udelay where wakeup is flexible
+ * @min: Minimum time in usecs to sleep
+ * @max: Maximum time in usecs to sleep
+ */
+void usleep_range(unsigned long min, unsigned long max)
+{
+ __set_current_state(TASK_UNINTERRUPTIBLE);
+ do_usleep_range(min, max);
+}
+EXPORT_SYMBOL(usleep_range);
+
+/**
+ * usleep_range_interruptible - sleep waiting for signals
+ * @min: Minimum time in usecs to sleep
+ * @max: Maximum time in usecs to sleep
+ */
+unsigned long usleep_range_interruptible(unsigned long min, unsigned long max)
+{
+ int err;
+ ktime_t start;
+
+ start = ktime_get();
+
+ __set_current_state(TASK_INTERRUPTIBLE);
+ err = do_usleep_range(min, max);
+
+ if (err == -EINTR)
+ return ktime_us_delta(ktime_get(), start);
+ else
+ return 0;
+}
+EXPORT_SYMBOL(usleep_range_interruptible);
--
1.7.1


2010-06-23 20:05:57

by Daniel Walker

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

On Wed, 2010-06-23 at 12:22 -0700, Patrick Pannuto wrote:
> *** INTRO ***
>
> As discussed here ( http://lkml.org/lkml/2007/8/3/250 ), msleep(1) is not
> precise enough for many drivers (yes, sleep precision is an unfair notion,
> but consistently sleeping for ~an order of magnitude greater than requested
> is worth fixing). This patch adds a usleep API so that udelay does not have
> to be used. Obviously not every udelay can be replaced (those in atomic
> contexts or being used for simple bitbanging come to mind), but there are
> many, many examples of
>
> mydriver_write(...)
> /* Wait for hardware to latch */
> udelay(100)
>
> in various drivers where a busy-wait loop is neither beneficial nor
> necessary, but msleep simply does not provide enough precision and people
> are using a busy-wait loop instead.

I think one thing for you to answer would be, why do you think udelay is
a problem? I don't honestly see that many udelay()'s around, and
especially not in important code paths .. Instead of adding a new API
like this you might just rework the problem areas.

Are you approaching this from performance? or battery life? or what?

> *** SOME QUANTIFIABLE (?) NUMBERS ***
>

> then averaged the results to see if there was any benefit:
>
> === ORIGINAL (99 samples) ========================================= ORIGINAL ===
> Avg: 188.760000 wakeups in 9.911010 secs (19.045486 wkups/sec) [18876 total]
> Wakeups: Min - 179, Max - 208, Mean - 190.666667, Stdev - 6.601194
>
> === USLEEP (99 samples) ============================================= USLEEP ===
> Avg: 188.200000 wakeups in 9.911230 secs (18.988561 wkups/sec) [18820 total]
> Wakeups: Min - 181, Max - 213, Mean - 190.101010, Stdev - 6.950757
>
> While not particularly rigorous, the results seem to indicate that there may be
> some benefit from pursuing this.

This is sort of ambiguous .. I don't think you replaced enough of these
for it to have much of an impact. It's actually counter intuitive
because your changes add more timers, yet they reduced average wakeups
by a tiny amount .. Why do you think that is ?

> *** HOW MUCH BENEFIT? ***
>
> Somewhat arbitrarily choosing 100 as a cut-off for udelay VS usleep:
>
> git grep 'udelay([[:digit:]]\+)' |
> perl -F"[\(\)]" -anl -e 'print if $F[1] >= 100' | wc -l
>
> yeilds 1093 on Linus's tree. There are 313 instances of >= 1000 and still
> another 53 >= 10000us of busy wait! (If AVOID_POPS is configured in, the
> es18xx driver will udelay(100000) or *0.1 seconds of busy wait*)

I'd say a better question is how often do they run?

Another thing is that your usleep() can't replace udelay() in critical
sections. However, if your doing udelay() in non-critical areas, I don't
think there is anything stopping preemption during the udelay() .. So
udelay() doesn't really cut off the whole system when it runs unless it
_is_ in a critical section.

Although it looks like you've spent a good deal of time on this write
up, the reasoning for these changes is still illusive (at least to me)..

Daniel
--
Sent by a consultant of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.

2010-06-23 20:21:33

by Patrick Pannuto

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

Daniel Walker wrote:
> On Wed, 2010-06-23 at 12:22 -0700, Patrick Pannuto wrote:
>> *** INTRO ***
>>
>> As discussed here ( http://lkml.org/lkml/2007/8/3/250 ), msleep(1) is not
>> precise enough for many drivers (yes, sleep precision is an unfair notion,
>> but consistently sleeping for ~an order of magnitude greater than requested
>> is worth fixing). This patch adds a usleep API so that udelay does not have
>> to be used. Obviously not every udelay can be replaced (those in atomic
>> contexts or being used for simple bitbanging come to mind), but there are
>> many, many examples of
>>
>> mydriver_write(...)
>> /* Wait for hardware to latch */
>> udelay(100)
>>
>> in various drivers where a busy-wait loop is neither beneficial nor
>> necessary, but msleep simply does not provide enough precision and people
>> are using a busy-wait loop instead.
>
> I think one thing for you to answer would be, why do you think udelay is
> a problem? I don't honestly see that many udelay()'s around, and
> especially not in important code paths .. Instead of adding a new API
> like this you might just rework the problem areas.
>
> Are you approaching this from performance? or battery life? or what?

First and foremost: power. If switching from udelay to usleep lets the processor
go to a lower C-state once in awhile, then I would consider this a win.

>
>> *** SOME QUANTIFIABLE (?) NUMBERS ***
>>
>
>> then averaged the results to see if there was any benefit:
>>
>> === ORIGINAL (99 samples) ========================================= ORIGINAL ===
>> Avg: 188.760000 wakeups in 9.911010 secs (19.045486 wkups/sec) [18876 total]
>> Wakeups: Min - 179, Max - 208, Mean - 190.666667, Stdev - 6.601194
>>
>> === USLEEP (99 samples) ============================================= USLEEP ===
>> Avg: 188.200000 wakeups in 9.911230 secs (18.988561 wkups/sec) [18820 total]
>> Wakeups: Min - 181, Max - 213, Mean - 190.101010, Stdev - 6.950757
>>
>> While not particularly rigorous, the results seem to indicate that there may be
>> some benefit from pursuing this.
>
> This is sort of ambiguous .. I don't think you replaced enough of these
> for it to have much of an impact. It's actually counter intuitive
> because your changes add more timers, yet they reduced average wakeups
> by a tiny amount .. Why do you think that is ?
>

Yes, this test was leftover from a different project that involved refactoring
timers, so it was available and easy. My guess for the reduction in number of
wakeups is that the processor is able to do other work during the 100us it was
previously busy-waiting, and thus had to wake up less often.

I don't know a good way to test this, if you do, please advise and I will
happily pursue it.

>> *** HOW MUCH BENEFIT? ***
>>
>> Somewhat arbitrarily choosing 100 as a cut-off for udelay VS usleep:
>>
>> git grep 'udelay([[:digit:]]\+)' |
>> perl -F"[\(\)]" -anl -e 'print if $F[1] >= 100' | wc -l
>>
>> yeilds 1093 on Linus's tree. There are 313 instances of >= 1000 and still
>> another 53 >= 10000us of busy wait! (If AVOID_POPS is configured in, the
>> es18xx driver will udelay(100000) or *0.1 seconds of busy wait*)
>
> I'd say a better question is how often do they run?

The i2c guys will get hit any time there is contention / heavy traffic on the
i2c bus (they're in the i2c_poll_notbusy path, also the i2c_poll_writeready),
so any time there is a lot of peripheral traffic (e.g. the phone is probably
doing a lot of stuff), then there are long (ish) busy-wait loops that are
unnecessary.

I haven't researched extensively, but I imagine there are a fair number of
other code paths like this; udelays polling until devices aren't busy - and
devices are generally only busy under some degree of load, not a good time
to busy wait if you don't have to IMHO

>
> Another thing is that your usleep() can't replace udelay() in critical
> sections. However, if your doing udelay() in non-critical areas, I don't
> think there is anything stopping preemption during the udelay() .. So
> udelay() doesn't really cut off the whole system when it runs unless it
> _is_ in a critical section.
>

I mentioned elsewhere that this can't replace all udelays; as for those that
can be pre-empted, it seems like only a win to give up your time slice to
something that will do real work (or sleep at a lower c-state and use less
power) than to sit and loop. Yes, you *could* be pre-empted from doing
absolutely nothing, but I don't think you should *have* to be for the
system to make a more productive use of those cycles.

> Although it looks like you've spent a good deal of time on this write
> up, the reasoning for these changes is still illusive (at least to me)..
>
> Daniel

2010-06-23 20:56:55

by Daniel Walker

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

On Wed, 2010-06-23 at 13:21 -0700, Patrick Pannuto wrote:
> Daniel Walker wrote:
> > On Wed, 2010-06-23 at 12:22 -0700, Patrick Pannuto wrote:
> >> *** INTRO ***
> >>
> >> As discussed here ( http://lkml.org/lkml/2007/8/3/250 ), msleep(1) is not
> >> precise enough for many drivers (yes, sleep precision is an unfair notion,
> >> but consistently sleeping for ~an order of magnitude greater than requested
> >> is worth fixing). This patch adds a usleep API so that udelay does not have
> >> to be used. Obviously not every udelay can be replaced (those in atomic
> >> contexts or being used for simple bitbanging come to mind), but there are
> >> many, many examples of
> >>
> >> mydriver_write(...)
> >> /* Wait for hardware to latch */
> >> udelay(100)
> >>
> >> in various drivers where a busy-wait loop is neither beneficial nor
> >> necessary, but msleep simply does not provide enough precision and people
> >> are using a busy-wait loop instead.
> >
> > I think one thing for you to answer would be, why do you think udelay is
> > a problem? I don't honestly see that many udelay()'s around, and
> > especially not in important code paths .. Instead of adding a new API
> > like this you might just rework the problem areas.
> >
> > Are you approaching this from performance? or battery life? or what?
>
> First and foremost: power. If switching from udelay to usleep lets the processor
> go to a lower C-state once in awhile, then I would consider this a win.

It's not clear if your changes would actually do that tho.. Since your
adding little tiny length timers instead of super long timers.. You want
more long length timers to get into a lower power state.

> >
> >> *** SOME QUANTIFIABLE (?) NUMBERS ***
> >>
> >
> >> then averaged the results to see if there was any benefit:
> >>
> >> === ORIGINAL (99 samples) ========================================= ORIGINAL ===
> >> Avg: 188.760000 wakeups in 9.911010 secs (19.045486 wkups/sec) [18876 total]
> >> Wakeups: Min - 179, Max - 208, Mean - 190.666667, Stdev - 6.601194
> >>
> >> === USLEEP (99 samples) ============================================= USLEEP ===
> >> Avg: 188.200000 wakeups in 9.911230 secs (18.988561 wkups/sec) [18820 total]
> >> Wakeups: Min - 181, Max - 213, Mean - 190.101010, Stdev - 6.950757
> >>
> >> While not particularly rigorous, the results seem to indicate that there may be
> >> some benefit from pursuing this.
> >
> > This is sort of ambiguous .. I don't think you replaced enough of these
> > for it to have much of an impact. It's actually counter intuitive
> > because your changes add more timers, yet they reduced average wakeups
> > by a tiny amount .. Why do you think that is ?
> >
>
> Yes, this test was leftover from a different project that involved refactoring
> timers, so it was available and easy. My guess for the reduction in number of
> wakeups is that the processor is able to do other work during the 100us it was
> previously busy-waiting, and thus had to wake up less often.

As I said in the prior email the udelay()'s don't preclude other types
of work since you can get preempted.

I think your results are just showing noise ..

> I don't know a good way to test this, if you do, please advise and I will
> happily pursue it.

You could test residency in specific power states .. Since you want to
test if your reducing power consumption .. However, I'd replace a ton
more of these udelay()'s , I don't think you'll get a decent results
with out that.

> >> *** HOW MUCH BENEFIT? ***
> >>
> >> Somewhat arbitrarily choosing 100 as a cut-off for udelay VS usleep:
> >>
> >> git grep 'udelay([[:digit:]]\+)' |
> >> perl -F"[\(\)]" -anl -e 'print if $F[1] >= 100' | wc -l
> >>
> >> yeilds 1093 on Linus's tree. There are 313 instances of >= 1000 and still
> >> another 53 >= 10000us of busy wait! (If AVOID_POPS is configured in, the
> >> es18xx driver will udelay(100000) or *0.1 seconds of busy wait*)
> >
> > I'd say a better question is how often do they run?
>
> The i2c guys will get hit any time there is contention / heavy traffic on the
> i2c bus (they're in the i2c_poll_notbusy path, also the i2c_poll_writeready),
> so any time there is a lot of peripheral traffic (e.g. the phone is probably
> doing a lot of stuff), then there are long (ish) busy-wait loops that are
> unnecessary.

If the phone is "doing a lot of stuff" then pretty good chance power
saving is at a minimum anyway. Try to be more specific .. For example,
is there some specific app that is causes power problems, and maybe that
app eventually gets into those i2c calls.

> I haven't researched extensively, but I imagine there are a fair number of
> other code paths like this; udelays polling until devices aren't busy - and
> devices are generally only busy under some degree of load, not a good time
> to busy wait if you don't have to IMHO


The busy waits your replacing are small in length on average .. If you
have timers that trigger in small intervals then your not going to
increase residency in any _lower_ power states .. It's possible that you
could increase residency in the top level power state, but it seem like
it would be really marginal .. You need to show that udelay()'s have an
outside of noise impact on something ..

> >
> > Another thing is that your usleep() can't replace udelay() in critical
> > sections. However, if your doing udelay() in non-critical areas, I don't
> > think there is anything stopping preemption during the udelay() .. So
> > udelay() doesn't really cut off the whole system when it runs unless it
> > _is_ in a critical section.
> >
>
> I mentioned elsewhere that this can't replace all udelays; as for those that
> can be pre-empted, it seems like only a win to give up your time slice to
> something that will do real work (or sleep at a lower c-state and use less
> power) than to sit and loop. Yes, you *could* be pre-empted from doing
> absolutely nothing, but I don't think you should *have* to be for the
> system to make a more productive use of those cycles.

I think you need to do some more research on what your actually doing to
the system. From what your showing us one could make a lot of different
arguments as to what this change will actually do. You really need some
sort of test that doesn't leave a lot of room for argument.

Daniel

--
Sent by a consultant of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.

2010-06-23 22:04:44

by Andreas Mohr

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

> I think you need to do some more research on what your actually doing to
> the system. From what your showing us one could make a lot of different
> arguments as to what this change will actually do. You really need some
> sort of test that doesn't leave a lot of room for argument.

I think the underlying issue he's having is that the timer APIs are simply
unadapted, they're awkward to use.

>From a driver POV, there really isn't much that you'd really CARE ABOUT
when entering any delay.

All you care about is to get a reliable delay, with the following characteristics:
- requested delay value
- wakeup spread (do I need this with hawk-eye precision, or is it ok if
wakeup is in the next century)
- something else? (perhaps "I need a warm/cold cache"?)

Whether this is preemptable, yieldable, power-managementable or entirely switch-offable
is ENTIRELY FRIGGIN' UNIMPORTANT to a driver, in most cases - it DOES NOT CARE about it.
The driver tells the OS what kind of delay characteristics it needs,
and it's the _OSes_ job to always do the most of that, be that a correspondingly deep
power management idle mode or whatever (one could argue that it should even know
on its own whether a critical section has to be obeyed or not, i.e. whether it's
preemptable or not).

This is just what a _minimal_, perfectly _adapted_ function interface should be.
And I'm afraid the kernel is somewhat off in that regard (mdelay, msleep, udelay,
... OH MY), which likely is why such discussions come up.

And if someone then says "but udelay is a tiny optimized function which is much faster
than some generic interface which would first need to execute a half-dozen branches
to figure out what mode exactly to choose", I say "to hell with it",
let's do the precisely right thing as fast as possible and not the sometimes right thing
perfectly fast (not to mention that always entering via the same central function
might have additional icache benefits, too).

Whether a particular environment is able to support useful power management quantities
in ms, us or even ns should never be a driver's job to worry about,
it should simply pass its requirements to the kernel and that's it.
Such orders of magnitude easily change over time given hardware's progress -
a well-designed, minimal kernel interface however probably won't need to.

Frankly this is just my feeling, I don't have any precise insight into these APIs,
thus I might be way off as to the complications of this and be talking out of my a... :)

Andreas Mohr

2010-06-24 10:22:44

by Andi Kleen

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

Patrick Pannuto <[email protected]> writes:

Overall it seems like a good improvement.

> +
> +static inline void usleep(unsigned long usecs)
> +{
> + usleep_range(usecs, usecs);
> +}
> +
> +static inline unsigned long usleep_interruptible(unsigned long usecs)

Is the interruptible case even needed? I assume most drivers won't
bother with that and not being interruptible for a few usecs is not a
big issue.

-Andi

--
[email protected] -- Speaking for myself only.

2010-06-24 16:51:25

by Patrick Pannuto

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

Andi Kleen wrote:
> Patrick Pannuto <[email protected]> writes:
>
> Overall it seems like a good improvement.
>
>> +
>> +static inline void usleep(unsigned long usecs)
>> +{
>> + usleep_range(usecs, usecs);
>> +}
>> +
>> +static inline unsigned long usleep_interruptible(unsigned long usecs)
>
> Is the interruptible case even needed? I assume most drivers won't
> bother with that and not being interruptible for a few usecs is not a
> big issue.

Honestly, I don't think so, but I was mirroring the msleep API when
I wrote it so I included it for completeness. I can't think of a use
case where it is necessary / useful. I will remove it unless anyone
can think of an application for it?

2010-06-26 21:44:10

by Pavel Machek

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

Hi!

> > Yes, this test was leftover from a different project that involved refactoring
> > timers, so it was available and easy. My guess for the reduction in number of
> > wakeups is that the processor is able to do other work during the 100us it was
> > previously busy-waiting, and thus had to wake up less often.
>
> As I said in the prior email the udelay()'s don't preclude other types
> of work since you can get preempted.

Yes, you can get preempted, but you'll still spin in the tight loop
counting...

So it does not preclude other task, but then you'll spin
unneccessarily.
Pavel
--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

2010-06-28 18:03:18

by Patrick Pannuto

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

>
> You could test residency in specific power states .. Since you want to
> test if your reducing power consumption .. However, I'd replace a ton
> more of these udelay()'s , I don't think you'll get a decent results
> with out that.
>

Ok.

>
> The busy waits your replacing are small in length on average .. If you
> have timers that trigger in small intervals then your not going to
> increase residency in any _lower_ power states .. It's possible that you
> could increase residency in the top level power state, but it seem like
> it would be really marginal .. You need to show that udelay()'s have an
> outside of noise impact on something ..
>

Ok.

>
> I think you need to do some more research on what your actually doing to
> the system. From what your showing us one could make a lot of different
> arguments as to what this change will actually do. You really need some
> sort of test that doesn't leave a lot of room for argument.
>

Well here we go then.

First, I would note that IMO is both telling and remarkable that the
following (almost) worked and allowed the system to boot successfully:

(a little long since you can cut off half of it and just get a list of
affected / candidate files, the following is a glorified sed that
replaces all instances of udelay with usleep for udelay's >= 50us)

git grep 'udelay([[:digit:]]\+)' |
perl -F"[\(\)]" -anl -e 'print if $F[1] >= 50' |
cut -d: -f1 |
uniq |
grep -v staging |
xargs perl -i -wlpe
's/udelay/usleep/ if m/udelay\((\d+)\)/g && $1 >= 50'

The usb driver and one power routine that was in a critical section had
to be reverted; everything else ran successfully.


*** MEASUREMENT TECHNIQUE ***

/proc/msm_pm_stats will dump information on residency in power states as
the system is running; dumps were taken 15s, 30s, 60s, 120s, 180s, and
240s from boot. 10 trials were performed for each build. A trial was run
replacing udelay >1000, >500, >100, >=100, >=50.

origin: 0 changes (0 total)
over1000: 106 changes (106 total)
over500: 193 changes (299 total)
over100: 302 changes (601 total)
equal100: 423 changes (1024 total)
equal50: 220 changes (1244 total)

Now, a concern is obviously that these changes hit drivers that are not
used in this system, or that many will be hit only once in boot /
initialization / etc; this shows plainly in the results and will be
addressed.


*** RESULTS ***

Complete results are attached (please forgive the ugly stats.py, it
evolved; it's functional for the task at hand, but certainly not pretty).

--> Long results also at end of email

>From the final results, after 240s:

TIME STATE #TIMES CALLED TIME IN STATE | DELTA FROM ORG

////////////////////////////////////////////////////////////////////////////////
=== origin (10 samples) =================================== RUNTIME: 241.535 ===
240 idle-spin -- 2.3 1.45001e-05
240 not-idle -- 88368.2 67.8311703321
240 idle-request -- 88367.2 23337.6322655
240 idle-wfi -- 88364.9 172.296383696
=== over1000 (10 samples) ====== (delta: -0.00999999998604) RUNTIME: 241.525 ===
240 idle-spin -- 3.1 1.91666e-05 | 4.6665e-06
240 not-idle -- 88723.9 65.6361809172 | -2.1949894149
240 idle-request -- 88722.9 23311.9855603 | -25.6467051707
240 idle-wfi -- 88719.8 174.493487111 | 2.1971034149
=== over500 (10 samples) ======== (delta: -0.0339999999851) RUNTIME: 241.501 ===
240 idle-spin -- 2.3 1.88334e-05 | 4.3333e-06
240 not-idle -- 88636.3 67.0242803241 | -0.806890008
240 idle-request -- 88635.3 23280.1632631 | -57.469002442
240 idle-wfi -- 88633.0 173.077055869 | 0.7806721723
=== over100 (10 samples) ======== (delta: -0.0539999999921) RUNTIME: 241.481 ===
240 idle-spin -- 0.9 6.6666e-06 | -7.8335e-06
240 not-idle -- 88599.0 67.190273164 | -0.6408971681
240 idle-request -- 88597.9 23253.4797828 | -84.1524827638
240 idle-wfi -- 88597.0 172.884529866 | 0.5881461694
=== equal100 (10 samples) ================== (delta: -0.025) RUNTIME: 241.51 ===
240 idle-spin -- 1.4 9.5002e-06 | -4.9999e-06
240 not-idle -- 88685.9 66.5067348407 | -1.3244354914
240 idle-request -- 88684.9 23294.4341497 | -43.1981158192
240 idle-wfi -- 88683.5 173.60379269 | 1.3074089936
=== equal50 (10 samples) ======== (delta: -0.0289999999804) RUNTIME: 241.506 ===
240 idle-spin -- 2.0 9.6664e-06 | -4.8337e-06
240 not-idle -- 88537.4 65.8619214556 | -1.9692488765
240 idle-request -- 88536.4 22979.3665406 | -358.265724952
240 idle-wfi -- 88534.4 174.247270576 | 1.9508868794


There appears to be very little change outside of noise from origin through
equal100, however, once equal50 is reached, there is a noticeable change.
Further investigation revealed that before equal100, none of the changes
could be guaranteed to hit the testing target (which, if nothing else,
provides a nice baseline for noise). The equal100 test included 3 changes
that could positively be sure to hit target and the equal50 test another
4 changes. The equal50 test was the only test that seems to conclusively
show immediate benefit, but it *does* show benefit.

(here "positively sure" are arch-specific drivers that changed, easy to
search for; it's likely that more did hit the target along the way)


*** CONCLUSIONS ***

I submit that the concept of usleep introduces no harm and does have the
potential for benefit. I further submit that as processors get faster, the
benefit from a usleep versus a udelay will only improve. Finally, I would note
that the success of the "sed" implies to me that many users of udelay would
prefer the semantics of a usleep call; it is simply unavailable and msleep is
simply too imprecise for callers to use, which is in and of itself a case
for a usleep API.

I invite comments, questions, etc, and am happy to run more tests; however,
I would like to request that if you for any reason believe this data to be
imprecise or insufficient that you please provide me with the *exact* test you
would like me to run and would like to see data from, since it does take a
fair amount of time to run these tests.

Finally, I would like to re-iterate my point that unnecessary busy-waiting,
while it *can* be pre-empted, *is* wasteful and __if it can easily be avoided,
it should be__.

-Pat


*** LONG RESULTS ***

==> Attached is pm_stats.tar.gz, it contains results as TEST_TRIALNO,
flash.sh to run tests (./flash.sh pm_stats TESTNAME) run from an Android
product directory, and stats.py to generate statistics. Forgive stats.py,
it is ugly and an abuse of python.

TIME STATE #TIMES CALLED TIME IN STATE | DELTA FROM ORG

////////////////////////////////////////////////////////////////////////////////
=== origin (10 samples) ==================================== RUNTIME: 15.253 ===
15 idle-spin -- 1.1 4.8332e-06
15 not-idle -- 59265.1 9.3842608833
15 idle-request -- 59262.2 21892.7762788
15 idle-wfi -- 59261.1 4.4754141812
=== over1000 (10 samples) ======== (delta: -0.00299999999115) RUNTIME: 15.25 ===
15 idle-spin -- 0.7 3.6666e-06 | -1.1666e-06
15 not-idle -- 59243.9 9.3891611869 | 0.0049003036
15 idle-request -- 59237.1 21897.8631197 | 5.0868408908
15 idle-wfi -- 59236.4 4.4665700454 | -0.0088441358
=== over500 (10 samples) ======== (delta: -0.00899999999674) RUNTIME: 15.244 ===
15 idle-spin -- 0.5 2.8334e-06 | -1.9998e-06
15 not-idle -- 59267.2 9.3819648583 | -0.002296025
15 idle-request -- 59263.2 21894.5342115 | 1.75793271321
15 idle-wfi -- 59262.7 4.4662633725 | -0.0091508087
=== over100 (10 samples) ======== (delta: -0.00200000000186) RUNTIME: 15.251 ===
15 idle-spin -- 0.1 1.1666e-06 | -3.6666e-06
15 not-idle -- 59222.3 9.4040358354 | 0.0197749521
15 idle-request -- 59213.6 21893.1330305 | 0.356751724303
15 idle-wfi -- 59213.5 4.4462678975 | -0.0291462837
=== equal100 (10 samples) ======= (delta: -0.00599999999395) RUNTIME: 15.247 ===
15 idle-spin -- 0.1 5e-07 | -4.3332e-06
15 not-idle -- 59311.6 9.392722999 | 0.0084621157
15 idle-request -- 59306.0 21900.290705 | 7.5144261487
15 idle-wfi -- 59305.9 4.4606828991 | -0.0147312821
=== equal50 (10 samples) ====================== (delta: 0.0) RUNTIME: 15.253 ===
15 idle-spin -- 0.6 1.8333e-06 | -2.9999e-06
15 not-idle -- 59267.0 9.4182486803 | 0.033987797
15 idle-request -- 59261.4 21613.5706545 | -279.205624353
15 idle-wfi -- 59260.8 4.4418992194 | -0.0335149618
////////////////////////////////////////////////////////////////////////////////
=== origin (10 samples) ==================================== RUNTIME: 30.494 ===
30 idle-spin -- 1.2 5.1666e-06
30 not-idle -- 69462.2 21.80567204
30 idle-request -- 69462.2 22568.1921778
30 idle-wfi -- 69461.0 6.8173021886
=== over1000 (10 samples) ======= (delta: -0.00100000001257) RUNTIME: 30.493 ===
30 idle-spin -- 1.1 6.3332e-06 | 1.1666e-06
30 not-idle -- 69436.0 21.7969753263 | -0.0086967137
30 idle-request -- 69436.0 22564.1587592 | -4.0334186002
30 idle-wfi -- 69434.9 6.8029330699 | -0.0143691187
=== over500 (10 samples) ======== (delta: -0.00700000001816) RUNTIME: 30.487 ===
30 idle-spin -- 0.6 3.1667e-06 | -1.9999e-06
30 not-idle -- 69474.6 21.7808043443 | -0.0248676957
30 idle-request -- 69474.6 22564.0631218 | -4.1290559666
30 idle-wfi -- 69474.0 6.7958443852 | -0.0214578034
=== over100 (10 samples) ========= (delta: 0.00099999998929) RUNTIME: 30.495 ===
30 idle-spin -- 0.2 1.6666e-06 | -3.5e-06
30 not-idle -- 69379.1 21.8042313156 | -0.0014407244
30 idle-request -- 69379.1 22551.153217 | -17.0389607525
30 idle-wfi -- 69378.9 6.7590274145 | -0.0582747741
=== equal100 (10 samples) ======= (delta: -0.00300000001443) RUNTIME: 30.491 ===
30 idle-spin -- 0.2 1e-06 | -4.1666e-06
30 not-idle -- 69455.7 21.8058526573 | 0.0001806173
30 idle-request -- 69455.7 22570.70418 | 2.51200219339
30 idle-wfi -- 69455.5 6.7603640729 | -0.0569381157
=== equal50 (10 samples) ======== (delta: -0.00100000002421) RUNTIME: 30.493 ===
30 idle-spin -- 0.9 3.8332e-06 | -1.3334e-06
30 not-idle -- 69449.7 21.8319953111 | 0.0263232711
30 idle-request -- 69449.7 22271.8053346 | -296.386843177
30 idle-wfi -- 69448.8 6.7478177546 | -0.069484434
////////////////////////////////////////////////////////////////////////////////
=== origin (10 samples) ===================================== RUNTIME: 60.78 ===
60 idle-spin -- 1.9 1.16667e-05
60 not-idle -- 79366.8 49.3036608463
60 idle-request -- 79366.3 22907.1705373
60 idle-wfi -- 79364.4 9.0110567161
=== over1000 (10 samples) ========= (delta: 0.0139999999898) RUNTIME: 60.794 ===
60 idle-spin -- 2.0 1.36668e-05 | 2.0001e-06
60 not-idle -- 79493.9 49.8914426181 | 0.5877817718
60 idle-request -- 79491.4 22894.3020036 | -12.8685336944
60 idle-wfi -- 79489.4 9.0156314459 | 0.0045747298
=== over500 (10 samples) ========== (delta: -0.010999999987) RUNTIME: 60.769 ===
60 idle-spin -- 1.5 1.14999e-05 | -1.668e-07
60 not-idle -- 79513.5 49.7980203079 | 0.4943594616
60 idle-request -- 79512.6 22869.995713 | -37.1748243636
60 idle-wfi -- 79511.1 9.0027399223 | -0.0083167938
=== over100 (10 samples) ========= (delta: -0.0229999999865) RUNTIME: 60.757 ===
60 idle-spin -- 0.8 6.3332e-06 | -5.3335e-06
60 not-idle -- 79399.4 49.8599212971 | 0.5562604508
60 idle-request -- 79396.8 22849.5517755 | -57.6187617949
60 idle-wfi -- 79396.0 8.9517647664 | -0.0592919497
=== equal100 (10 samples) ======= (delta: -0.00699999999488) RUNTIME: 60.773 ===
60 idle-spin -- 1.0 6.1667e-06 | -5.5e-06
60 not-idle -- 79508.7 49.7887594666 | 0.4850986203
60 idle-request -- 79506.3 22878.2886511 | -28.8818862207
60 idle-wfi -- 79505.3 8.9810057637 | -0.0300509524
=== equal50 (10 samples) ======== (delta: -0.00799999999581) RUNTIME: 60.772 ===
60 idle-spin -- 1.4 5.9998e-06 | -5.6669e-06
60 not-idle -- 79401.8 49.7245356251 | 0.4208747788
60 idle-request -- 79401.8 22589.3334706 | -317.837066708
60 idle-wfi -- 79400.4 8.9224572725 | -0.0885994436
////////////////////////////////////////////////////////////////////////////////
=== origin (10 samples) =================================== RUNTIME: 121.018 ===
120 idle-spin -- 2.3 1.45001e-05
120 not-idle -- 84534.3 65.4829273526
120 idle-request -- 84533.2 23073.5171825
120 idle-wfi -- 84530.9 54.1388846978
=== over1000 (10 samples) ======== (delta: 0.0149999999907) RUNTIME: 121.033 ===
120 idle-spin -- 2.9 1.76667e-05 | 3.1666e-06
120 not-idle -- 84899.7 62.9539904388 | -2.5289369138
120 idle-request -- 84898.6 23058.6542567 | -14.8629258454
120 idle-wfi -- 84895.7 56.6840665995 | 2.5451819017
=== over500 (10 samples) ======= (delta: -0.00999999999767) RUNTIME: 121.008 ===
120 idle-spin -- 2.1 1.61667e-05 | 1.6666e-06
120 not-idle -- 84810.4 64.5704918038 | -0.9124355488
120 idle-request -- 84809.3 23020.7240229 | -52.7931596084
120 idle-wfi -- 84807.2 55.0429809068 | 0.904096209
=== over100 (10 samples) ======== (delta: -0.0209999999963) RUNTIME: 120.997 ===
120 idle-spin -- 0.9 6.6666e-06 | -7.8335e-06
120 not-idle -- 84773.7 64.6287104755 | -0.8542168771
120 idle-request -- 84772.7 23002.4330668 | -71.0841157664
120 idle-wfi -- 84771.8 54.9635557389 | 0.8246710411
=== equal100 (10 samples) ======= (delta: 0.00600000000559) RUNTIME: 121.024 ===
120 idle-spin -- 1.4 9.5002e-06 | -4.9999e-06
120 not-idle -- 84843.8 63.8751059888 | -1.6078213638
120 idle-request -- 84842.8 23042.7777274 | -30.7394551461
120 idle-wfi -- 84841.4 55.7466510555 | 1.6077663577
=== equal50 (10 samples) ======= (delta: -0.00099999998929) RUNTIME: 121.017 ===
120 idle-spin -- 2.0 9.6664e-06 | -4.8337e-06
120 not-idle -- 84767.4 63.0424664541 | -2.4404608985
120 idle-request -- 84766.4 22740.2895937 | -333.227588835
120 idle-wfi -- 84764.4 56.5740535877 | 2.4351688899
////////////////////////////////////////////////////////////////////////////////
=== origin (10 samples) =================================== RUNTIME: 181.273 ===
180 idle-spin -- 2.3 1.45001e-05
180 not-idle -- 86458.1 66.7356990125
180 idle-request -- 86457.1 23202.3433604
180 idle-wfi -- 86454.8 113.126771849
=== over1000 (10 samples) ========= (delta: 0.010999999987) RUNTIME: 181.284 ===
180 idle-spin -- 3.0 1.83333e-05 | 3.8332e-06
180 not-idle -- 86831.3 64.5482361081 | -2.1874629044
180 idle-request -- 86830.3 23181.3150713 | -21.028289176
180 idle-wfi -- 86827.3 115.331773087 | 2.2050012376
=== over500 (10 samples) ======== (delta: -0.0250000000117) RUNTIME: 181.248 ===
180 idle-spin -- 2.2 1.68334e-05 | 2.3333e-06
180 not-idle -- 86733.7 65.9390319914 | -0.7966670211
180 idle-request -- 86732.7 23151.5750952 | -50.7682652808
180 idle-wfi -- 86730.5 113.915960535 | 0.7891886856
=== over100 (10 samples) ======== (delta: -0.0339999999968) RUNTIME: 181.239 ===
180 idle-spin -- 0.9 6.6666e-06 | -7.8335e-06
180 not-idle -- 86696.8 66.0923128287 | -0.6433861838
180 idle-request -- 86695.7 23122.6406168 | -79.7027435974
180 idle-wfi -- 86694.8 113.744699867 | 0.6179280181
=== equal100 (10 samples) ======= (delta: -0.0060000000056) RUNTIME: 181.267 ===
180 idle-spin -- 1.4 9.5002e-06 | -4.9999e-06
180 not-idle -- 86765.3 65.4099056755 | -1.325793337
180 idle-request -- 86764.2 23156.7172921 | -45.6260683097
180 idle-wfi -- 86762.8 114.457775355 | 1.3310035056
=== equal50 (10 samples) ======= (delta: -0.00799999998418) RUNTIME: 181.265 ===
180 idle-spin -- 2.0 9.6664e-06 | -4.8337e-06
180 not-idle -- 86665.1 64.770143973 | -1.9655550395
180 idle-request -- 86664.1 22851.7003915 | -350.642968977
180 idle-wfi -- 86662.1 115.098642558 | 1.971870709
////////////////////////////////////////////////////////////////////////////////
=== origin (10 samples) =================================== RUNTIME: 241.535 ===
240 idle-spin -- 2.3 1.45001e-05
240 not-idle -- 88368.2 67.8311703321
240 idle-request -- 88367.2 23337.6322655
240 idle-wfi -- 88364.9 172.296383696
=== over1000 (10 samples) ====== (delta: -0.00999999998604) RUNTIME: 241.525 ===
240 idle-spin -- 3.1 1.91666e-05 | 4.6665e-06
240 not-idle -- 88723.9 65.6361809172 | -2.1949894149
240 idle-request -- 88722.9 23311.9855603 | -25.6467051707
240 idle-wfi -- 88719.8 174.493487111 | 2.1971034149
=== over500 (10 samples) ======== (delta: -0.0339999999851) RUNTIME: 241.501 ===
240 idle-spin -- 2.3 1.88334e-05 | 4.3333e-06
240 not-idle -- 88636.3 67.0242803241 | -0.806890008
240 idle-request -- 88635.3 23280.1632631 | -57.469002442
240 idle-wfi -- 88633.0 173.077055869 | 0.7806721723
=== over100 (10 samples) ======== (delta: -0.0539999999921) RUNTIME: 241.481 ===
240 idle-spin -- 0.9 6.6666e-06 | -7.8335e-06
240 not-idle -- 88599.0 67.190273164 | -0.6408971681
240 idle-request -- 88597.9 23253.4797828 | -84.1524827638
240 idle-wfi -- 88597.0 172.884529866 | 0.5881461694
=== equal100 (10 samples) ================== (delta: -0.025) RUNTIME: 241.51 ===
240 idle-spin -- 1.4 9.5002e-06 | -4.9999e-06
240 not-idle -- 88685.9 66.5067348407 | -1.3244354914
240 idle-request -- 88684.9 23294.4341497 | -43.1981158192
240 idle-wfi -- 88683.5 173.60379269 | 1.3074089936
=== equal50 (10 samples) ======== (delta: -0.0289999999804) RUNTIME: 241.506 ===
240 idle-spin -- 2.0 9.6664e-06 | -4.8337e-06
240 not-idle -- 88537.4 65.8619214556 | -1.9692488765
240 idle-request -- 88536.4 22979.3665406 | -358.265724952
240 idle-wfi -- 88534.4 174.247270576 | 1.9508868794


Attachments:
pm_stats.tar.gz (117.05 kB)

2010-06-28 19:39:42

by Daniel Walker

[permalink] [raw]
Subject: Re: [RFC] [PATCH] timer: Added usleep[_range][_interruptable] timer

On Mon, 2010-06-28 at 11:03 -0700, Patrick Pannuto wrote:

> Well here we go then.

Great.


> *** RESULTS ***
>
> Complete results are attached (please forgive the ugly stats.py, it
> evolved; it's functional for the task at hand, but certainly not pretty).
>
> --> Long results also at end of email
>
> From the final results, after 240s:
>
> TIME STATE #TIMES CALLED TIME IN STATE | DELTA FROM ORG
>
> ////////////////////////////////////////////////////////////////////////////////
> === origin (10 samples) =================================== RUNTIME: 241.535 ===

What's the 10 samples here?

> 240 idle-spin -- 2.3 1.45001e-05
> 240 not-idle -- 88368.2 67.8311703321
> 240 idle-request -- 88367.2 23337.6322655
> 240 idle-wfi -- 88364.9 172.296383696

I'm going to assume you did ten in "origin" (i.e. control runs) and
averaged. However, you need to explicitly say that ..

What units is "time in state", and what interfacing does the timing? Are
these states in order from least power saving to most power savings?

> === over1000 (10 samples) ====== (delta: -0.00999999998604) RUNTIME: 241.525 ===
> 240 idle-spin -- 3.1 1.91666e-05 | 4.6665e-06
> 240 not-idle -- 88723.9 65.6361809172 | -2.1949894149
> 240 idle-request -- 88722.9 23311.9855603 | -25.6467051707
> 240 idle-wfi -- 88719.8 174.493487111 | 2.1971034149
> === over500 (10 samples) ======== (delta: -0.0339999999851) RUNTIME: 241.501 ===
> 240 idle-spin -- 2.3 1.88334e-05 | 4.3333e-06
> 240 not-idle -- 88636.3 67.0242803241 | -0.806890008
> 240 idle-request -- 88635.3 23280.1632631 | -57.469002442
> 240 idle-wfi -- 88633.0 173.077055869 | 0.7806721723
> === over100 (10 samples) ======== (delta: -0.0539999999921) RUNTIME: 241.481 ===
> 240 idle-spin -- 0.9 6.6666e-06 | -7.8335e-06
> 240 not-idle -- 88599.0 67.190273164 | -0.6408971681
> 240 idle-request -- 88597.9 23253.4797828 | -84.1524827638
> 240 idle-wfi -- 88597.0 172.884529866 | 0.5881461694
> === equal100 (10 samples) ================== (delta: -0.025) RUNTIME: 241.51 ===
> 240 idle-spin -- 1.4 9.5002e-06 | -4.9999e-06
> 240 not-idle -- 88685.9 66.5067348407 | -1.3244354914
> 240 idle-request -- 88684.9 23294.4341497 | -43.1981158192
> 240 idle-wfi -- 88683.5 173.60379269 | 1.3074089936
> === equal50 (10 samples) ======== (delta: -0.0289999999804) RUNTIME: 241.506 ===
> 240 idle-spin -- 2.0 9.6664e-06 | -4.8337e-06
> 240 not-idle -- 88537.4 65.8619214556 | -1.9692488765
> 240 idle-request -- 88536.4 22979.3665406 | -358.265724952
> 240 idle-wfi -- 88534.4 174.247270576 | 1.9508868794
>
>
> There appears to be very little change outside of noise from origin through
> equal100, however, once equal50 is reached, there is a noticeable change.

it all looks pretty noisy still, but it could be that your just
providing too much information ...

Ok, so the idle-request state had residency of 22979us (guessing units)
in equal50, and 23338us in the control. Which is %1.5 less. I would
think you want more residency rather than less right?

Replacing 50us udelays with timers will cause more timers to trigger at
a high frequency, which would cause you to be running timer code more
often rather than doing something else (maybe being in a sleep state).
So the number make some sense.

Does over100 include everything from 100 to 1000 ?

Daniel