[Testing] [OLPC-AU] Testing summary, Auckland - 17 March 2012

Jerry Vonau jvonau at shaw.ca
Mon Mar 26 05:10:18 EDT 2012


On Thu, 2012-03-22 at 09:27 -0400, Paul Fox wrote: 
> jerry wrote:
>  > On Wed, 2012-03-21 at 16:13 -0400, Paul Fox wrote:
>  > > tabitha wrote:
>  > >  > Testing Summary, Auckland - 17 March 2012
>  > >  > Who: Fabiana, John, Oliver, Rachel, Tom
>  > >  > 
>  > >  > Tested build 30 customized on XO-1.75 and build 206 11.3.1-au on XO 1.5.
>  > >  > 
>  > >  > XO-1.5 Summary (details below):
>  > >  > Power saving blanks the screen while recording a video
>  > > ...
>  > >  > build 206 11.3.1-au on XO 1.5:
>  > >  > Rosella:
>  > >  > Record activity - works fine for photo and video. high and low res.
>  > >  > even long ones. But quite quickly the screen goes black - it is not
>  > >  > going to sleep - there is no flashing of the power light and it
>  > >  > continues recording. On Ivy it takes 1 minute to go black. Tabitha
>  > > 
>  > > jerry vonau tells me that the powerd version in this release is
>  > > based on my powerd-44.  i cannot reproduce this problem with our
>  > > os31 running with either powerd 44 or 46.
>  > > 
>  > > i don't know where to find the au modified packages, so i can't
>  > > test the specific version that was being run above.
>  > > 
>  > 
>  > Hi Paul,
> 
> jerry -- i think i've asked twice now (okay, i suppose it was just
> implied, above) for a pointer to the modified version of powerd that
> was included in your build 206.  where can i find that code?
> 

I'll dig that up, I forgot to branch the public git repo at that point
in time. I've placed copies of what was in au206, au207 in the public
git repo. 

> > 
>  > I was tracking down why my XO-1.5's would never dim/blank in the normal
>  > course of operation with version 46. I chose to modify version 44 as I
> 
> so you're working on a different problem than the one above.  the problem
> above is that the screen _does_ dim and blank when Record is active.
> 

I feel that inhibits should not prevent the XO from dimming (think XS on
XO here), it didn't occur to me that camera usage was being used to
prevent the laptop from dimming.


> > was working with that as a baseline for some modifications. Well I
>  > turned my attention to version 46 and I think I found the issue I was
>  > having. In r1.patch I added some tracing to laptop_busy to get some idea
>  > what was occurring, it looked like cpu_or_network_busy was keeping the
>  > laptop from suspending, so I added r2.patch to capture more data. The
>  > tracing uncovered on a XO-1.5 that check_network_activity would always
>  > return 0 thus preventing the next step in the cycle from occurring. I
> 
> certainly if check_network_activity always returns 0, then the machine
> will never dim or sleep.  why is it always returning 0?  oh.  there's
> a bug in your patch, i think.  see below.
> 

Sigh, too many long days, your correct on that one, I was just adding
logging, that you point out below was corrected.

> > corrected the issue for me with r3-patch. What are your thoughts?
>  > 
> 
> i'm not sure of the value of showing me a set of work-in-progress
> patches.  one patch would be sufficient, i think.
> 
> 
> r1-patch:
>  > diff --git a/powerd b/powerd
>  > index edbd8e9..5c9cb0c 100755
>  > --- a/powerd
>  > +++ b/powerd
>  > @@ -2700,8 +2700,11 @@ sleep_action()
>  >      # use it here.
>  >      if laptop_busy
>  >      then
>  > +        trace laptop_busy TRUE
>  >          reset_idlecounters  # restart the timers
>  >          return
>  > +    else
>  > +        trace laptop_busy FALSE 
>  >      fi
>  >  
>  >      # sleep until it's time to shut down
> 
> the above looks fine.
> 
> 
> r2-patch:
>  > diff --git a/powerd b/powerd
>  > index edbd8e9..bf595d3 100755
>  > --- a/powerd
>  > +++ b/powerd
>  > @@ -978,6 +978,7 @@ then
>  >  
>  >      check_camera_activity()
>  >      {
>  > +        trace check_camera_activity
>  >          case $1 in
>  >          start)
>  >              camera_ints=$(camera_interrupts start)
>  > @@ -1123,6 +1124,7 @@ check_cpu_activity()
>  >  
>  >  cpu_or_network_busy()
>  >  {
>  > +    trace start cpu_or_network_busy 
>  >      check_cpu_activity start
>  >      check_network_activity start
>  >      check_camera_activity start
>  > @@ -1131,6 +1133,8 @@ cpu_or_network_busy()
>  >      # check for events while doing so.  we can afford this extra
>  >      # wait seconds because we arranged to be signalled 5 seconds
>  >      # before actually wanting to suspend.
>  > +    trace loop cpu_or_network_busy 
>  > +
>  >      start=$(seconds)
>  >      while : BUSYCHECK loop
>  >      do
>  > @@ -1138,9 +1142,16 @@ cpu_or_network_busy()
>  >          test $(( $(seconds) - start )) -ge $BUSYCHECK && break
>  >      done
>  >  
>  > +    trace busycheck cpu_or_network_busy 
>  > +
>  >      check_cpu_activity finish && return 0
>  > +    trace cpu cpu_or_network_busy 
>  > +
> 
> everything is fine up to here.
> 
>  >      check_network_activity finish && return 0
>  > -    check_camera_activity finish && return 0
>  > +    trace network cpu_or_network_busy 
>  > +
>  > +    check_camera_activity finish
>  > +    trace camera cpu_or_network_busy && return 0
> 
> you're no longer checking the return value from check_camera_activity
> at all -- you're checking the result of a trace statement.  as a result
> cpu_or_network_busy() will always report busy-ness and keep the laptop
> awake.
> 

As you said corrected below.

> >  
>  >      return 1
>  >  }
> 
> r3-patch:
>  > diff --git a/powerd b/powerd
>  > index bf595d3..e849f87 100755
>  > --- a/powerd
>  > +++ b/powerd
>  > @@ -1010,7 +1010,9 @@ else
>  >          test $1 = "finish" && \
>  >              grep -q via-dma /proc/interrupts && \
>  >              trace camera busy
>  > +            return 0
>  >      }
>  > +    return 1
>  >  fi
> 
> you've a) forced check_camera_activity() to always return 0, and b)
> added a "return 1" outside of the body of the function.  so this
> doesn't seem right.

I used the behaviour of the XO-1 routine just above as a guide, return 0
for busy else return 1. I have removed that modification from the
patches for the next image au210.


> 
>  >  
>  >  
>  > @@ -1151,7 +1153,7 @@ cpu_or_network_busy()
>  >      trace network cpu_or_network_busy 
>  >  
>  >      check_camera_activity finish
>  > -    trace camera cpu_or_network_busy && return 0
>  > +    trace camera cpu_or_network_busy
>  >  
>  >      return 1
>  >  }
> 
> here you've fixed the issue i mentioned regarding r2-patch, so that
> you're no longer checking the return value of a trace call.  that's
> good.  but you're still not checking the value of check_camera_activity
> at all, which i guess is why you didn't notice that it's always
> returning success.
> 

The reason I omitted '&& return 0' is because of seeing different
behaviour in cpu_or_network_busy between suspended and not suspended
that the added tracing uncovered. It's true laptop_busy works well
before a suspend is done as shown below. 

#### Start pre-suspended ####

: @ 1332491401 got wakeup: keypress @ 1332491401, slept 17
Running disable_mesh.sh resume  
: @ 1332491402 got event: useractive, 1332491401, , , .
: @ 1332491402 backlight restore
: @ 1332491402 got event: fake_useractive, 1332491401, keypress, , . 
: @ 1332491402 backlight restore
: @ 1332491411 got event: timer, 1332491411, 60, , .
: @ 1332491412 got event: useridle1, 1332491412, , , .
: @ 1332491412 general inhibit: 0
: @ 1332491412 start cpu_or_network_busy
: @ 1332491412 loop cpu_or_network_busy
: @ 1332491417 busycheck cpu_or_network_busy
: @ 1332491417 cpu cpu_or_network_busy
: @ 1332491417 network busy
: @ 1332491417 laptop_busy TRUE
: @ 1332491427 got event: useridle1, 1332491427, , , .
: @ 1332491427 general inhibit: 0
: @ 1332491427 start cpu_or_network_busy
: @ 1332491427 loop cpu_or_network_busy
: @ 1332491432 busycheck cpu_or_network_busy
: @ 1332491432 cpu cpu_or_network_busy
: @ 1332491432 network busy
: @ 1332491432 laptop_busy TRUE
: @ 1332491442 got event: useridle1, 1332491442, , , .
: @ 1332491442 general inhibit: 0
: @ 1332491442 start cpu_or_network_busy
: @ 1332491442 loop cpu_or_network_busy
: @ 1332491447 busycheck cpu_or_network_busy
: @ 1332491447 cpu cpu_or_network_busy
: @ 1332491447 network cpu_or_network_busy
: @ 1332491447 camera cpu_or_network_busy
: @ 1332491447 laptop_busy FALSE
: @ 1332491447 backlight is_off
: @ 1332491447 snoozing: until_dim 7200 30 75
: @ 1332491447 until-sleep_type is until_dim-soft
rtcwake: wakeup from "mem" using /dev/rtc0 at Fri Mar 23 08:31:22 2012

#### End pre-suspended ####

However once suspended and a 'wlanpacket' wakeup is generated there is a
difference in the logging, 'network busy' doesn't prevent the next
suspend from occurring:

#### Start post-suspend ####

rtcwake: wakeup from "mem" using /dev/rtc0 at Fri Mar 23 08:31:22 2012

: @ 1332491451 got wakeup: wlanpacket @ 1332491451, slept 3
: @ 1332491451 until-sleep_type is until_dim-soft
: @ 1332491453 network busy
rtcwake: wakeup from "mem" using /dev/rtc0 at Fri Mar 23 08:31:24 2012

: @ 1332491458 got wakeup: wlanpacket @ 1332491458, slept 5
: @ 1332491459 until-sleep_type is until_dim-soft
: @ 1332491461 network busy
rtcwake: wakeup from "mem" using /dev/rtc0 at Fri Mar 23 08:31:26 2012

: @ 1332491465 got wakeup: wlanpacket @ 1332491465, slept 4
: @ 1332491466 until-sleep_type is until_dim-soft
: @ 1332491467 network busy
rtcwake: wakeup from "mem" using /dev/rtc0 at Fri Mar 23 08:31:29 2012

: @ 1332491472 got wakeup: wlanpacket @ 1332491472, slept 5
: @ 1332491473 until-sleep_type is until_dim-soft
: @ 1332491477 network busy
rtcwake: wakeup from "mem" using /dev/rtc0 at Fri Mar 23 08:31:31 2012

: @ 1332491482 got wakeup: wlanpacket @ 1332491482, slept 5
: @ 1332491482 until-sleep_type is until_dim-soft
: @ 1332491484 network busy
rtcwake: wakeup from "mem" using /dev/rtc0 at Fri Mar 23 08:31:33 2012


#### End post-suspend ####

I should of ran this trace past you first, the logged I added revealed
the difference between the two states. Looks like my cheap hack to
check_camera_activity was just hiding that there appears to be a need to
break out of busycheck's 5 second loop, like inhibited_by_files does to
restore the countdown to 15 seconds thus resetting the idle_counters. 

The above tracing is from last week, I have os31 installed and the
behaviour is the same. I'll patch that if you want to see that the
tracing is the same. 


> please point me to your release repo for powerd.  i'd like to get back
> to understanding the problem reported by the testing group.
> 

Problem resolved as of March 24 round of testing.

Jerry



More information about the Testing mailing list