[Xenomai-core] Problem with periodic timer on PPC40x identified

[Xenomai-core] Problem with periodic timer on PPC40x identified

[Niklaus Giger]

Hi

Finally I got some time to debug the whole problem with my BDI.
I see that in hal.c thal_set_local_cpu_timer the PIT is loaded with a value of 
568 which is far too low, as the PIT is running at 400 MHz. So it will 
trigger an interrupt every 1,4 microsecond and therefore overload the system.

I am not sure about the time units stored in __ipipe_decr_ticks. I tried to 
use 400 as my board is running at 400 MHz.
A quick breakpoint in ppc4xx_calibrate_decr in the file 
arch/syslib/ppc4xx_setup.c verified that bdinfo has the correct value of 
400'000'000 as frequency.

In hal.c and ipipe-core are two occurences of
    mtspr(SPRN_PIT, __ipipe_decr_ticks); 
which I replaced by the above computed constant
    mtspr(SPRN_PIT, __ipipe_decr_ticks * 400); 

Now the the board comes up, but calling in the vxworks skin 
taskDelay(sysClkRateGet()*10) delays me only about 5 seconds and not 10 as 
expected.

I have one possible explanation that the value of 568 is the result of a 
implicit truncation to 32 bits in ipipe_tune_timer. tb_ticks_per_jiffy is 
1600000, sysClkRate is 10000. Therefore a maximal delay of 1 ms = 1000*1000 
ns leads to 1000*1000*16000 = 0x25'40BE'4000.

If would be nice if somebode could shed some light on this issue.

My preliminary patch looked like this, but I am sure that we need quite a 
different solution.

+++ ksrc/arch/powerpc/hal.c	(Arbeitskopie)
@@ -81,7 +81,9 @@
  */
 static void rthal_set_local_cpu_timer(void)
 {
+#ifndef CONFIG_40x
     long ticks;
+#endif
     rthal_declare_cpuid;
 
     rthal_load_cpuid();
@@ -90,7 +92,7 @@
 #ifdef CONFIG_40x
     /* Enable and set auto-reload. */
     mtspr(SPRN_TCR, mfspr(SPRN_TCR) | TCR_ARE);
-    mtspr(SPRN_PIT, __ipipe_decr_ticks);
+    mtspr(SPRN_PIT, __ipipe_decr_ticks * 400); /* TODO: How do we get this 
value from the board info */
 #else /* !CONFIG_40x */
     ticks = (long)(__ipipe_decr_next[cpuid] - __ipipe_read_timebase());
     set_dec(ticks > 0 ? ticks : 0);
Index: ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch
===================================================================
--- ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	(Revision 
1650)
+++ ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	
(Arbeitskopie)
@@ -3581,7 +3581,8 @@
 +#ifdef CONFIG_40x
 +	/* Enable and set auto-reload. */
 +	mtspr(SPRN_TCR, mfspr(SPRN_TCR) | TCR_ARE);
-+	mtspr(SPRN_PIT, __ipipe_decr_ticks);
++	mtspr(SPRN_PIT, __ipipe_decr_ticks * 400 ); /* TODO: How do we get this 
value from the board info */
+
 +#else	/* !CONFIG_40x */
 +	__ipipe_decr_next[cpuid] = __ipipe_read_timebase() + __ipipe_decr_ticks;
 +	set_dec(__ipipe_decr_ticks);

Best regards

-- 
Niklaus Giger

Re: [Xenomai-core] Problem with periodic timer on PPC40x identified

[Wolfgang Grandegger]

Hi Niklaus,
Niklaus Giger wrote:
> Hi
> 
> Finally I got some time to debug the whole problem with my BDI.
> I see that in hal.c thal_set_local_cpu_timer the PIT is loaded with a value of 
> 568 which is far too low, as the PIT is running at 400 MHz. So it will 
> trigger an interrupt every 1,4 microsecond and therefore overload the system.
> 
> I am not sure about the time units stored in __ipipe_decr_ticks. I tried to 
> use 400 as my board is running at 400 MHz.
> A quick breakpoint in ppc4xx_calibrate_decr in the file 
> arch/syslib/ppc4xx_setup.c verified that bdinfo has the correct value of 
> 400'000'000 as frequency.
> 
> In hal.c and ipipe-core are two occurences of
>     mtspr(SPRN_PIT, __ipipe_decr_ticks); 
> which I replaced by the above computed constant
>     mtspr(SPRN_PIT, __ipipe_decr_ticks * 400); 
> 
> Now the the board comes up, but calling in the vxworks skin 
> taskDelay(sysClkRateGet()*10) delays me only about 5 seconds and not 10 as 
> expected.
> 
> I have one possible explanation that the value of 568 is the result of a 
> implicit truncation to 32 bits in ipipe_tune_timer. tb_ticks_per_jiffy is 
> 1600000, sysClkRate is 10000. Therefore a maximal delay of 1 ms = 1000*1000 
> ns leads to 1000*1000*16000 = 0x25'40BE'4000.
> 
> If would be nice if somebode could shed some light on this issue.

I briefly look why the value of __ipipe_decr_ticks is bogus. Maybe the 
calculation fails due to 32-bit constraints in 
arch/ppc/kernel/ipipe-core.c:pipe_tune_timer():

   int ipipe_tune_timer(unsigned long ns, int flags)
   {
         unsigned long x, ticks;

         if (flags & IPIPE_RESET_TIMER)
                 ticks = tb_ticks_per_jiffy;
         else {
                 ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
  		^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                 if (ticks > tb_ticks_per_jiffy)
                         return -EINVAL;
         }
 

         x = ipipe_critical_enter(&__ipipe_set_decr); /* Sync with all
                                                         CPUs */
         __ipipe_decr_ticks = ticks;
         __ipipe_set_decr();
         ipipe_critical_exit(x);
 

          return 0;
  }
 

Does replacing the calculation of ticks with

         ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);

help. A proper calculation might use mulhwu or rthal_imuldiv.

Wolfgang.


> 
> My preliminary patch looked like this, but I am sure that we need quite a 
> different solution.
> 
> +++ ksrc/arch/powerpc/hal.c	(Arbeitskopie)
> @@ -81,7 +81,9 @@
>   */
>  static void rthal_set_local_cpu_timer(void)
>  {
> +#ifndef CONFIG_40x
>      long ticks;
> +#endif
>      rthal_declare_cpuid;
>  
>      rthal_load_cpuid();
> @@ -90,7 +92,7 @@
>  #ifdef CONFIG_40x
>      /* Enable and set auto-reload. */
>      mtspr(SPRN_TCR, mfspr(SPRN_TCR) | TCR_ARE);
> -    mtspr(SPRN_PIT, __ipipe_decr_ticks);
> +    mtspr(SPRN_PIT, __ipipe_decr_ticks * 400); /* TODO: How do we get this 
> value from the board info */
>  #else /* !CONFIG_40x */
>      ticks = (long)(__ipipe_decr_next[cpuid] - __ipipe_read_timebase());
>      set_dec(ticks > 0 ? ticks : 0);
> Index: ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch
> ===================================================================
> --- ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	(Revision 
> 1650)
> +++ ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	
> (Arbeitskopie)
> @@ -3581,7 +3581,8 @@
>  +#ifdef CONFIG_40x
>  +	/* Enable and set auto-reload. */
>  +	mtspr(SPRN_TCR, mfspr(SPRN_TCR) | TCR_ARE);
> -+	mtspr(SPRN_PIT, __ipipe_decr_ticks);
> ++	mtspr(SPRN_PIT, __ipipe_decr_ticks * 400 ); /* TODO: How do we get this 
> value from the board info */
> +
>  +#else	/* !CONFIG_40x */
>  +	__ipipe_decr_next[cpuid] = __ipipe_read_timebase() + __ipipe_decr_ticks;
>  +	set_dec(__ipipe_decr_ticks);
> 
> Best regards
> 

Re: [Xenomai-core] Problem with periodic timer on PPC40x identified

[Philippe Gerum]

On Sat, 2006-09-23 at 22:55 +0200, Wolfgang Grandegger wrote:
> Hi Niklaus,
> Niklaus Giger wrote:
> > Hi
> > 
> > Finally I got some time to debug the whole problem with my BDI.
> > I see that in hal.c thal_set_local_cpu_timer the PIT is loaded with a value of 
> > 568 which is far too low, as the PIT is running at 400 MHz. So it will 
> > trigger an interrupt every 1,4 microsecond and therefore overload the system.
> > 
> > I am not sure about the time units stored in __ipipe_decr_ticks. I tried to 
> > use 400 as my board is running at 400 MHz.
> > A quick breakpoint in ppc4xx_calibrate_decr in the file 
> > arch/syslib/ppc4xx_setup.c verified that bdinfo has the correct value of 
> > 400'000'000 as frequency.
> > 
> > In hal.c and ipipe-core are two occurences of
> >     mtspr(SPRN_PIT, __ipipe_decr_ticks); 
> > which I replaced by the above computed constant
> >     mtspr(SPRN_PIT, __ipipe_decr_ticks * 400); 
> > 
> > Now the the board comes up, but calling in the vxworks skin 
> > taskDelay(sysClkRateGet()*10) delays me only about 5 seconds and not 10 as 
> > expected.
> > 
> > I have one possible explanation that the value of 568 is the result of a 
> > implicit truncation to 32 bits in ipipe_tune_timer. tb_ticks_per_jiffy is 
> > 1600000, sysClkRate is 10000. Therefore a maximal delay of 1 ms = 1000*1000 
> > ns leads to 1000*1000*16000 = 0x25'40BE'4000.
> > 
> > If would be nice if somebode could shed some light on this issue.
> 
> I briefly look why the value of __ipipe_decr_ticks is bogus. Maybe the 
> calculation fails due to 32-bit constraints in 
> arch/ppc/kernel/ipipe-core.c:pipe_tune_timer():
> 

That would make sense, since the issue never happens when the nucleus
noots in oneshot timing mode, just because this code is not used in this
case. Well, I'm really going to kill this ugly hw-managed periodic mode
in the next release, and rebase the periodic timing over the oneshot
mode as we discussed. This code is just silly and error-prone.

>    int ipipe_tune_timer(unsigned long ns, int flags)
>    {
>          unsigned long x, ticks;
> 
>          if (flags & IPIPE_RESET_TIMER)
>                  ticks = tb_ticks_per_jiffy;
>          else {
>                  ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
>   		^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>                  if (ticks > tb_ticks_per_jiffy)
>                          return -EINVAL;
>          }
>  
> 
>          x = ipipe_critical_enter(&__ipipe_set_decr); /* Sync with all
>                                                          CPUs */
>          __ipipe_decr_ticks = ticks;
>          __ipipe_set_decr();
>          ipipe_critical_exit(x);
>  
> 
>           return 0;
>   }
>  
> 
> Does replacing the calculation of ticks with
> 
>          ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);
> 
> help. A proper calculation might use mulhwu or rthal_imuldiv.

mulhwu then, because we should not introduce Xenomai HAL level ops in
the Adeos abstraction.

> 
> Wolfgang.
> 
> 
> > 
> > My preliminary patch looked like this, but I am sure that we need quite a 
> > different solution.
> > 
> > +++ ksrc/arch/powerpc/hal.c	(Arbeitskopie)
> > @@ -81,7 +81,9 @@
> >   */
> >  static void rthal_set_local_cpu_timer(void)
> >  {
> > +#ifndef CONFIG_40x
> >      long ticks;
> > +#endif
> >      rthal_declare_cpuid;
> >  
> >      rthal_load_cpuid();
> > @@ -90,7 +92,7 @@
> >  #ifdef CONFIG_40x
> >      /* Enable and set auto-reload. */
> >      mtspr(SPRN_TCR, mfspr(SPRN_TCR) | TCR_ARE);
> > -    mtspr(SPRN_PIT, __ipipe_decr_ticks);
> > +    mtspr(SPRN_PIT, __ipipe_decr_ticks * 400); /* TODO: How do we get this 
> > value from the board info */
> >  #else /* !CONFIG_40x */
> >      ticks = (long)(__ipipe_decr_next[cpuid] - __ipipe_read_timebase());
> >      set_dec(ticks > 0 ? ticks : 0);
> > Index: ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch
> > ===================================================================
> > --- ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	(Revision 
> > 1650)
> > +++ ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	
> > (Arbeitskopie)
> > @@ -3581,7 +3581,8 @@
> >  +#ifdef CONFIG_40x
> >  +	/* Enable and set auto-reload. */
> >  +	mtspr(SPRN_TCR, mfspr(SPRN_TCR) | TCR_ARE);
> > -+	mtspr(SPRN_PIT, __ipipe_decr_ticks);
> > ++	mtspr(SPRN_PIT, __ipipe_decr_ticks * 400 ); /* TODO: How do we get this 
> > value from the board info */
> > +
> >  +#else	/* !CONFIG_40x */
> >  +	__ipipe_decr_next[cpuid] = __ipipe_read_timebase() + __ipipe_decr_ticks;
> >  +	set_dec(__ipipe_decr_ticks);
> > 
> > Best regards
> > 
> 
> 
> _______________________________________________
> Xenomai-core mailing list
> Xenomai-core@domain.hid
> https://mail.gna.org/listinfo/xenomai-core
-- 
Philippe.

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Niklaus Giger]

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

Am Samstag, 23. September 2006 22:55 schrieb Wolfgang Grandegger:
> Hi Niklaus,
>
> Niklaus Giger wrote:
<..>
>          if (flags & IPIPE_RESET_TIMER)
>                  ticks = tb_ticks_per_jiffy;
>          else {
>                  ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
>   		^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>                  if (ticks > tb_ticks_per_jiffy)
>                          return -EINVAL;
<..>
> Does replacing the calculation of ticks with
>
>          ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);
>
> help. A proper calculation might use mulhwu or rthal_imuldiv.
Yes. I does. There are two occurrences fixed with the attached patch (+ one 
small ifdef to eliminate a compiler warning in the PPC40x case).
Timing is okay as tested with a small vxworks test program.

Could someone please apply it?

Thanks for your cooperation. 

Best regards

-- 
Niklaus Giger

[-- Attachment #2: ppc40x_periodic.patch --]
[-- Type: text/x-diff, Size: 1261 bytes --]

Index: ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch
===================================================================
--- ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	(Revision 1650)
+++ ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	(Arbeitskopie)
@@ -3595,7 +3595,7 @@
 +	if (flags & IPIPE_RESET_TIMER)
 +		ticks = tb_ticks_per_jiffy;
 +	else {
-+		ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
++		ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);
 +
 +		if (ticks > tb_ticks_per_jiffy)
 +			return -EINVAL;
Index: ksrc/arch/powerpc/hal.c
===================================================================
--- ksrc/arch/powerpc/hal.c	(Revision 1650)
+++ ksrc/arch/powerpc/hal.c	(Arbeitskopie)
@@ -81,7 +81,9 @@
  */
 static void rthal_set_local_cpu_timer(void)
 {
+#ifndef CONFIG_40x
     long ticks;
+#endif
     rthal_declare_cpuid;
 
     rthal_load_cpuid();
@@ -110,7 +112,7 @@
     if (ns == 0)
         ticks = tb_ticks_per_jiffy;
     else {
-        ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
+	ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);
 
         if (ticks > tb_ticks_per_jiffy) {
             DBG("rthal_set_cpu_timers_unsafe: -EINVAL (%lu)\n", ticks);

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Wolfgang Grandegger]

Niklaus Giger wrote:
> Am Samstag, 23. September 2006 22:55 schrieb Wolfgang Grandegger:
>> Hi Niklaus,
>>
>> Niklaus Giger wrote:
> <..>
>>          if (flags & IPIPE_RESET_TIMER)
>>                  ticks = tb_ticks_per_jiffy;
>>          else {
>>                  ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
>>   		^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>>                  if (ticks > tb_ticks_per_jiffy)
>>                          return -EINVAL;
> <..>
>> Does replacing the calculation of ticks with
>>
>>          ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);
>>
>> help. A proper calculation might use mulhwu or rthal_imuldiv.
> Yes. I does. There are two occurrences fixed with the attached patch (+ one 
> small ifdef to eliminate a compiler warning in the PPC40x case).
> Timing is okay as tested with a small vxworks test program.
> 
> Could someone please apply it?
> 
> Thanks for your cooperation. 
> 
> Best regards
> 
> 
> 
> ------------------------------------------------------------------------
> 
> Index: ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch
> ===================================================================
> --- ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	(Revision 1650)
> +++ ksrc/arch/powerpc/patches/adeos-ipipe-2.6.14-ppc-1.4-00.patch	(Arbeitskopie)
> @@ -3595,7 +3595,7 @@
>  +	if (flags & IPIPE_RESET_TIMER)
>  +		ticks = tb_ticks_per_jiffy;
>  +	else {
> -+		ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
> ++		ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);
>  +
>  +		if (ticks > tb_ticks_per_jiffy)
>  +			return -EINVAL;
> Index: ksrc/arch/powerpc/hal.c
> ===================================================================
> --- ksrc/arch/powerpc/hal.c	(Revision 1650)
> +++ ksrc/arch/powerpc/hal.c	(Arbeitskopie)
> @@ -81,7 +81,9 @@
>   */
>  static void rthal_set_local_cpu_timer(void)
>  {
> +#ifndef CONFIG_40x
>      long ticks;
> +#endif
>      rthal_declare_cpuid;
>  
>      rthal_load_cpuid();
> @@ -110,7 +112,7 @@
>      if (ns == 0)
>          ticks = tb_ticks_per_jiffy;
>      else {
> -        ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
> +	ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);
>  
>          if (ticks > tb_ticks_per_jiffy) {
>              DBG("rthal_set_cpu_timers_unsafe: -EINVAL (%lu)\n", ticks);

My suggested fix was just to locate the source of the problem. As 
Philippe suggested, we should use mulhwu (or mulhwu_scale_factor). Have 
a look to arch/ppc/kernel/time.c for further information.

Wolfgang.

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Philippe Gerum]

On Sun, 2006-09-24 at 23:07 +0200, Wolfgang Grandegger wrote:
> Niklaus Giger wrote:
> >  static void rthal_set_local_cpu_timer(void)
> >  {
> > +#ifndef CONFIG_40x
> >      long ticks;
> > +#endif
> >      rthal_declare_cpuid;
> >  
> >      rthal_load_cpuid();
> > @@ -110,7 +112,7 @@
> >      if (ns == 0)
> >          ticks = tb_ticks_per_jiffy;
> >      else {
> > -        ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
> > +	ticks = ns * (tb_ticks_per_jiffy / 10000) / (100000 / HZ);
> >  
> >          if (ticks > tb_ticks_per_jiffy) {
> >              DBG("rthal_set_cpu_timers_unsafe: -EINVAL (%lu)\n", ticks);
> 
> My suggested fix was just to locate the source of the problem. As 
> Philippe suggested, we should use mulhwu (or mulhwu_scale_factor). Have 
> a look to arch/ppc/kernel/time.c for further information.

Ok, we can go for the lazy fix here, since this code is poised to
disappear anyway. I've merged a variant of the above we already use for
the ARM port, which scales down the period to microseconds instead of
losing precision on the count of timebase ticks per jiffy.

- ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
+ ticks = (ns / 1000) * tb_ticks_per_jiffy / (1000000 / HZ);

-- 
Philippe.

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Niklaus Giger]

Am Montag, 25. September 2006 17:57 schrieb Philippe Gerum:
> On Sun, 2006-09-24 at 23:07 +0200, Wolfgang Grandegger wrote:
> > Niklaus Giger wrote:
<..>
> Ok, we can go for the lazy fix here, since this code is poised to
> disappear anyway. I've merged a variant of the above we already use for
> the ARM port, which scales down the period to microseconds instead of
> losing precision on the count of timebase ticks per jiffy.
>
> - ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
> + ticks = (ns / 1000) * tb_ticks_per_jiffy / (1000000 / HZ);
Thanks for finding this solution. I tried to understand mulhwu and 
mulhwu_scale_factor but couldn't figure out a correct solution in a short 
time.

The buildbot cannot presently power on and off my PPC405 target board, as the 
my power outlet switching device is broken and has been sent back for a 
remplacement.

I did however run some tests manually and have the following questions about 
the output:
Why do I get negative values for latenciy values?
Is the output of lines like "Xenomai: Switching display-3238 to secondary mode 
after exception #1025 from user-space at 0x100033c4 (pid 3240)" harmless or 
the result of a activated CONFIG_XENO_OPT_DEBUG<..> option?

Mon Sep 25 20:20:33 UTC 2006
running: ./run -- -T 5 -t2 # latency
*
*
* Type ^C to stop this application.
*
Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
user-space at 0x100033c4 (pid 3240)
== Sampling period: 100 us
== Test mode: in-kernel timer handler
== All results in microseconds
warming up...
RTT|  00:00:01  (in-kernel timer handler, 100 us period, priority 99)
RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
RTD|      -5.108|      -4.754|      -0.905|       0|      -5.108|      -0.905
RTD|      -4.963|      -4.871|       1.155|       0|      -5.108|       1.155
Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
user-space at 0xfda9638 (pid 3240)
RTD|      -4.963|      -4.758|      16.020|       0|      -5.108|      16.020
RTD|      -6.313|      -4.861|      10.980|       0|      -6.313|      16.020
Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
user-space at 0xfe7c1c4 (pid 3240)
---|------------|------------|------------|--------|-------------------------
RTS|      -6.313|      -4.811|      16.020|       0|    00:00:05/00:00:05
Xenomai: stopping RTDM services.

Best regards
-- 
Niklaus Giger

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Philippe Gerum]

On Mon, 2006-09-25 at 22:29 +0200, Niklaus Giger wrote:
> Am Montag, 25. September 2006 17:57 schrieb Philippe Gerum:
> > On Sun, 2006-09-24 at 23:07 +0200, Wolfgang Grandegger wrote:
> > > Niklaus Giger wrote:
> <..>
> > Ok, we can go for the lazy fix here, since this code is poised to
> > disappear anyway. I've merged a variant of the above we already use for
> > the ARM port, which scales down the period to microseconds instead of
> > losing precision on the count of timebase ticks per jiffy.
> >
> > - ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
> > + ticks = (ns / 1000) * tb_ticks_per_jiffy / (1000000 / HZ);
> Thanks for finding this solution. I tried to understand mulhwu and 
> mulhwu_scale_factor but couldn't figure out a correct solution in a short 
> time.
> 
> The buildbot cannot presently power on and off my PPC405 target board, as the 
> my power outlet switching device is broken and has been sent back for a 
> remplacement.
> 
> I did however run some tests manually and have the following questions about 
> the output:
> Why do I get negative values for latenciy values?

Because the timer shot anticipation in /proc/xenomai/latency is too
large for the target, which in fact has a lower intrinsic latency than
expected. The default calibration values are obtained from
include/asm-*/calibration.h.

> Is the output of lines like "Xenomai: Switching display-3238 to secondary mode 
> after exception #1025 from user-space at 0x100033c4 (pid 3240)" harmless or 
> the result of a activated CONFIG_XENO_OPT_DEBUG<..> option?
> 

Oops. It's bad news. A memory access error occured while running the
test. Which Xenomai/Adeos combo are you currently running on the 4xx?

> Mon Sep 25 20:20:33 UTC 2006
> running: ./run -- -T 5 -t2 # latency
> *
> *
> * Type ^C to stop this application.
> *
> Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
> user-space at 0x100033c4 (pid 3240)
> == Sampling period: 100 us
> == Test mode: in-kernel timer handler
> == All results in microseconds
> warming up...
> RTT|  00:00:01  (in-kernel timer handler, 100 us period, priority 99)
> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
> RTD|      -5.108|      -4.754|      -0.905|       0|      -5.108|      -0.905
> RTD|      -4.963|      -4.871|       1.155|       0|      -5.108|       1.155
> Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
> user-space at 0xfda9638 (pid 3240)
> RTD|      -4.963|      -4.758|      16.020|       0|      -5.108|      16.020
> RTD|      -6.313|      -4.861|      10.980|       0|      -6.313|      16.020
> Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
> user-space at 0xfe7c1c4 (pid 3240)
> ---|------------|------------|------------|--------|-------------------------
> RTS|      -6.313|      -4.811|      16.020|       0|    00:00:05/00:00:05
> Xenomai: stopping RTDM services.
> 
> Best regards
-- 
Philippe.

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Niklaus Giger]

Am Montag, 25. September 2006 22:59 schrieb Philippe Gerum:
> On Mon, 2006-09-25 at 22:29 +0200, Niklaus Giger wrote:
> > Am Montag, 25. September 2006 17:57 schrieb Philippe Gerum:
> > > On Sun, 2006-09-24 at 23:07 +0200, Wolfgang Grandegger wrote:
> > > > Niklaus Giger wrote:
<..>
> > Is the output of lines like "Xenomai: Switching display-3238 to secondary
> > mode after exception #1025 from user-space at 0x100033c4 (pid 3240)"
> > harmless or the result of a activated CONFIG_XENO_OPT_DEBUG<..> option?
>
> Oops. It's bad news. A memory access error occured while running the
> test. Which Xenomai/Adeos combo are you currently running on the 4xx?

adeos-ipipe-2.6.14-ppc-1.4-00.patch

Shall I use my BDI (tomorrow evening) to get a stack trace of it? Or something 
else you would like to see?
 
Best regards

-- 
Niklaus Giger

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Wolfgang Grandegger]

Niklaus Giger wrote:
> Am Montag, 25. September 2006 17:57 schrieb Philippe Gerum:
>> On Sun, 2006-09-24 at 23:07 +0200, Wolfgang Grandegger wrote:
>>> Niklaus Giger wrote:
> <..>
>> Ok, we can go for the lazy fix here, since this code is poised to
>> disappear anyway. I've merged a variant of the above we already use for
>> the ARM port, which scales down the period to microseconds instead of
>> losing precision on the count of timebase ticks per jiffy.
>>
>> - ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);
>> + ticks = (ns / 1000) * tb_ticks_per_jiffy / (1000000 / HZ);
> Thanks for finding this solution. I tried to understand mulhwu and 
> mulhwu_scale_factor but couldn't figure out a correct solution in a short 
> time.

I took me also some time to understand the meaning. mulhwu(a,b) returns 
the high 32 bits (32..63) of a*b. A possible quick fix could be:

   if (mulhwu(ns, tb_ticks_per_jiffy) > 0)
	ticks = (ns / 1000) * tb_ticks_per_jiffy / (1000000 / HZ);
   else
	ticks = ns * tb_ticks_per_jiffy / (1000000000 / HZ);

But Philippe already applied a reasonable fix.

> 
> The buildbot cannot presently power on and off my PPC405 target board, as the 
> my power outlet switching device is broken and has been sent back for a 
> remplacement.
> 
> I did however run some tests manually and have the following questions about 
> the output:
> Why do I get negative values for latenciy values?
> Is the output of lines like "Xenomai: Switching display-3238 to secondary mode 
> after exception #1025 from user-space at 0x100033c4 (pid 3240)" harmless or 
> the result of a activated CONFIG_XENO_OPT_DEBUG<..> option?
> 
> Mon Sep 25 20:20:33 UTC 2006
> running: ./run -- -T 5 -t2 # latency
> *
> *
> * Type ^C to stop this application.
> *
> Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
> user-space at 0x100033c4 (pid 3240)
> == Sampling period: 100 us
> == Test mode: in-kernel timer handler
> == All results in microseconds
> warming up...
> RTT|  00:00:01  (in-kernel timer handler, 100 us period, priority 99)
> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
> RTD|      -5.108|      -4.754|      -0.905|       0|      -5.108|      -0.905
> RTD|      -4.963|      -4.871|       1.155|       0|      -5.108|       1.155
> Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
> user-space at 0xfda9638 (pid 3240)
> RTD|      -4.963|      -4.758|      16.020|       0|      -5.108|      16.020
> RTD|      -6.313|      -4.861|      10.980|       0|      -6.313|      16.020
> Xenomai: Switching display-3238 to secondary mode after exception #1025 from 
> user-space at 0xfe7c1c4 (pid 3240)
> ---|------------|------------|------------|--------|-------------------------
> RTS|      -6.313|      -4.811|      16.020|       0|    00:00:05/00:00:05
> Xenomai: stopping RTDM services.
> 
> Best regards

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Philippe Gerum]

On Mon, 2006-09-25 at 23:15 +0200, Niklaus Giger wrote:
> Am Montag, 25. September 2006 22:59 schrieb Philippe Gerum:
> > On Mon, 2006-09-25 at 22:29 +0200, Niklaus Giger wrote:
> > > Am Montag, 25. September 2006 17:57 schrieb Philippe Gerum:
> > > > On Sun, 2006-09-24 at 23:07 +0200, Wolfgang Grandegger wrote:
> > > > > Niklaus Giger wrote:
> <..>
> > > Is the output of lines like "Xenomai: Switching display-3238 to secondary
> > > mode after exception #1025 from user-space at 0x100033c4 (pid 3240)"
> > > harmless or the result of a activated CONFIG_XENO_OPT_DEBUG<..> option?
> >
> > Oops. It's bad news. A memory access error occured while running the
> > test. Which Xenomai/Adeos combo are you currently running on the 4xx?
> 
> adeos-ipipe-2.6.14-ppc-1.4-00.patch
> 
> Shall I use my BDI (tomorrow evening) to get a stack trace of it? Or something 
> else you would like to see?

It would be great if you could first run the very same Xenomai config
over Adeos 1.3-07 instead of 1.4-00, just to see if the issue is still
there on the 4xx. After that, a BDI trace would be nice to have when
time permits.

>  
> Best regards
> 
-- 
Philippe.

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Philippe Gerum]

> On Mon, 2006-09-25 at 22:29 +0200, Niklaus Giger wrote:
> > > Am Montag, 25. September 2006 17:57 schrieb Philippe Gerum:
> > > > On Sun, 2006-09-24 at 23:07 +0200, Wolfgang Grandegger wrote:
> > > > > Niklaus Giger wrote:
> <..>
> > > Is the output of lines like "Xenomai: Switching display-3238 to secondary
> > > mode after exception #1025 from user-space at 0x100033c4 (pid 3240)"
> > > harmless or the result of a activated CONFIG_XENO_OPT_DEBUG<..> option?

A known hw issue seems to exist with the 405GP (revD), which causes the
ESR to be incorrectly set upon FPU emulation trap, which would in turn
cause the spurious exception to be relayed to the nucleus by Adeos. The
patch below is _not_ the final fix, but rather a way to check if this
message is indeed related to the FPU emulation on your board. Does it
silence the exception without breaking the box?

--- arch/ppc/kernel/traps.c~	2006-09-25 17:10:48.000000000 +0200
+++ arch/ppc/kernel/traps.c	2006-09-26 16:14:30.000000000 +0200
@@ -638,9 +638,6 @@
 	unsigned int reason = get_reason(regs);
 	extern int do_mathemu(struct pt_regs *regs);
 
-	if (ipipe_trap_notify(IPIPE_TRAP_PCE,regs))
-	    	return;
-
 #ifdef CONFIG_MATH_EMULATION
 	/* (reason & REASON_ILLEGAL) would be the obvious thing here,
 	 * but there seems to be a hardware bug on the 405GP (RevD)
@@ -655,6 +652,9 @@
 	}
 #endif /* CONFIG_MATH_EMULATION */
 
+	if (ipipe_trap_notify(IPIPE_TRAP_PCE,regs))
+	    	return;
+
 	if (reason & REASON_FP) {
 		/* IEEE FP exception */
 		int code = 0;
-- 
Philippe.

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Niklaus Giger]

Am Dienstag, 26. September 2006 16:21 schrieb Philippe Gerum:
> > On Mon, 2006-09-25 at 22:29 +0200, Niklaus Giger wrote:
> > > > Am Montag, 25. September 2006 17:57 schrieb Philippe Gerum:
> > > > > On Sun, 2006-09-24 at 23:07 +0200, Wolfgang Grandegger wrote:
> > > > > > Niklaus Giger wrote:
> >
> > <..>
> >
> > > > Is the output of lines like "Xenomai: Switching display-3238 to
> > > > secondary mode after exception #1025 from user-space at 0x100033c4
> > > > (pid 3240)" harmless or the result of a activated
> > > > CONFIG_XENO_OPT_DEBUG<..> option?
>
> A known hw issue seems to exist with the 405GP (revD), which causes the
> ESR to be incorrectly set upon FPU emulation trap, which would in turn
> cause the spurious exception to be relayed to the nucleus by Adeos. The
> patch below is _not_ the final fix, but rather a way to check if this
> message is indeed related to the FPU emulation on your board. Does it
> silence the exception without breaking the box?
>
> --- arch/ppc/kernel/traps.c~	2006-09-25 17:10:48.000000000 +0200
> +++ arch/ppc/kernel/traps.c	2006-09-26 16:14:30.000000000 +0200
> @@ -638,9 +638,6 @@
>  	unsigned int reason = get_reason(regs);
>  	extern int do_mathemu(struct pt_regs *regs);
>
> -	if (ipipe_trap_notify(IPIPE_TRAP_PCE,regs))
> -	    	return;
> -
>  #ifdef CONFIG_MATH_EMULATION
>  	/* (reason & REASON_ILLEGAL) would be the obvious thing here,
>  	 * but there seems to be a hardware bug on the 405GP (RevD)
> @@ -655,6 +652,9 @@
>  	}
>  #endif /* CONFIG_MATH_EMULATION */
>
> +	if (ipipe_trap_notify(IPIPE_TRAP_PCE,regs))
> +	    	return;
> +
>  	if (reason & REASON_FP) {
>  		/* IEEE FP exception */
>  		int code = 0;
Tried your patch against adeos-ipipe 1.3. But I still get the same behaviour. 
Here is my proc/cpuinfo.

$ cat /proc/cpuinfo
processor       : 0
cpu             : 405GPr
clock           : 400MHz
revision        : 9.81 (pvr 5091 0951)
bogomips        : 398.33
machine         : Netstal HCU3
plb bus clock   : 133MHz

U-Boot printed the following info:
CPU:   AMCC PowerPC 405GPr Rev. B at 400 MHz (PLB=133, OPB=33, EBC=33 MHz)
, PCI sync clock at 33 MHz       16 kB I-Cache 16 kB D-Cache

Best regards

-- 
Niklaus Giger

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Niklaus Giger]

Here is the stack with adeos-ipipe 1.3 after applying your patch 

(gdb) info stack
#0  xnpod_fault_handler (fltinfo=0xc1489e18) at 
kernel/xenomai/nucleus/pod.c:216
#1  0xc004bad4 in xnpod_trap_fault (fltinfo=0x73) at 
kernel/xenomai/nucleus/pod.c:2907
#2  0xc0043ee8 in xnarch_trap_fault (event=115, domid=0, data=0xc01a9435) at 
include/asm/xenomai/bits/init.h:46
#3  0xc012dc38 in exception_event (event=3223286668, ipd=0x0, data=0xc01a9435) 
at arch/ppc/xenomai/hal.c:385
#4  0xc003fe18 in __ipipe_dispatch_event (event=0, data=0xc1489f50) at 
kernel/ipipe/core.c:665
#5  0xc000aecc in do_page_fault (regs=0xc1489f50, address=268448708, 
error_code=0) at include/linux/ipipe.h:445
#6  0xc0003258 in handle_page_fault ()
Previous frame inner to this frame (corrupt stack?)
(gdb) 

Hope it helps you
-- 
Niklaus Giger

Re: [Xenomai-core] Problem with periodic timer on PPC40x solved

[Philippe Gerum]

On Tue, 2006-09-26 at 21:34 +0200, Niklaus Giger wrote:
> Here is the stack with adeos-ipipe 1.3 after applying your patch 
> 
> (gdb) info stack
> #0  xnpod_fault_handler (fltinfo=0xc1489e18) at 
> kernel/xenomai/nucleus/pod.c:216
> #1  0xc004bad4 in xnpod_trap_fault (fltinfo=0x73) at 
> kernel/xenomai/nucleus/pod.c:2907
> #2  0xc0043ee8 in xnarch_trap_fault (event=115, domid=0, data=0xc01a9435) at 
> include/asm/xenomai/bits/init.h:46
> #3  0xc012dc38 in exception_event (event=3223286668, ipd=0x0, data=0xc01a9435) 
> at arch/ppc/xenomai/hal.c:385
> #4  0xc003fe18 in __ipipe_dispatch_event (event=0, data=0xc1489f50) at 
> kernel/ipipe/core.c:665
> #5  0xc000aecc in do_page_fault (regs=0xc1489f50, address=268448708, 
> error_code=0) at include/linux/ipipe.h:445
> #6  0xc0003258 in handle_page_fault ()

The function parameters look weird, but the backtrace seems ok. This
tells us that it's not related to FPU emulation, but rather to an
invalid memory access.

> Previous frame inner to this frame (corrupt stack?)
> (gdb) 
> 
> Hope it helps you
-- 
Philippe.