* [Xenomai-help] Beginner's question / testsuite / latency @ 2006-07-20 21:17 Julien Heyman 2006-07-20 21:58 ` Jan Kiszka 2006-07-21 13:25 ` [Xenomai-help] Beginner's question / testsuite / latency Gilles Chanteperdrix 0 siblings, 2 replies; 29+ messages in thread From: Julien Heyman @ 2006-07-20 21:17 UTC (permalink / raw) To: xenomai [-- Attachment #1: Type: text/plain, Size: 5454 bytes --] Hi, I am currently trying to evaluate Xenomai, and my current setup is : VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. When I run the latency part of the testsuite (in a console under KDE), I get results that I cannot understand, so I probably did something wrong (execution trace included below). I get reasonable values during the first seconds, then all of a sudden latencies begin to rise, continuously, to very large values. - I did check that DMA transfer is activated on my HD. - I did select "Enable SMI workaround" + "Globally disable SMI" in the Xenomai options while configuring the kernel. - I have disabled power management at BIOS level and disabled ACPI support and CPU frequency scaling during kernel configuration. - I checked that I don't have anything called "legacy USB" in my BIOS. I do have an "OnChip USB" option enable in the BIOS though. Any advice would be appreciated ! Thanks Julien Heyman * * Type ^C to stop this application. * * == Sampling period: 100 us == Test mode: periodic user-mode task == All results in microseconds warming up... RTT| 00:00:01 (periodic user-mode task, 100 us period) RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst RTD| 6.209| 8.110| 17.561| 0| 6.209| 17.561 RTD| 6.348| 8.131| 17.861| 0| 6.209| 17.861 RTD| 6.625| 8.121| 17.154| 0| 6.209| 17.861 RTD| 4.170| 8.033| 15.746| 0| 4.170| 17.861 RTD| 5.984| 8.341| 16.936| 0| 4.170| 17.861 RTD| 6.292| 8.142| 18.502| 0| 4.170| 18.502 RTD| 6.359| 8.117| 17.467| 0| 4.170| 18.502 RTD| 6.326| 8.125| 16.633| 0| 4.170| 18.502 RTD| 6.277| 8.121| 17.071| 0| 4.170| 18.502 RTD| 6.228| 8.123| 16.869| 0| 4.170| 18.502 RTD| 6.543| 8.129| 15.752| 0| 4.170| 18.502 RTD| 3.975| 8.016| 20.269| 0| 3.975| 20.269 RTD| 6.489| 8.344| 17.735| 0| 3.975| 20.269 RTD| 6.359| 8.123| 19.026| 0| 3.975| 20.269 RTD| 6.470| 8.119| 16.908| 0| 3.975| 20.269 RTD| 6.517| 8.114| 16.339| 0| 3.975| 20.269 RTD| 6.498| 8.125| 17.992| 0| 3.975| 20.269 RTD| 6.341| 8.129| 15.409| 0| 3.975| 20.269 RTD| 4.222| 8.076| 15.973| 0| 3.975| 20.269 RTD| 3.846| 8.144| 16.597| 0| 3.846| 20.269 RTD| 6.537| 8.269| 17.257| 0| 3.846| 20.269 RTT| 00:00:22 (periodic user-mode task, 100 us period) RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst RTD| 6.507| 8.127| 17.570| 0| 3.846| 20.269 RTD| 6.425| 8.117| 16.685| 0| 3.846| 20.269 RTD| 6.468| 8.123| 16.136| 0| 3.846| 20.269 RTD| 6.539| 8.116| 15.332| 0| 3.846| 20.269 RTD| 6.288| 8.123| 16.475| 0| 3.846| 20.269 RTD| 3.956| 8.003| 16.638| 0| 3.846| 20.269 RTD| 6.369| 8.348| 23.399| 0| 3.846| 23.399 RTD| 6.717| 8.078| 20.682| 0| 3.846| 23.399 RTD| 6.476| 8.074| 15.698| 0| 3.846| 23.399 RTD| 6.684| 98.523| 197.536| 1| 3.846| 197.536 RTD| 106.358| 108.116| 195.011| 1| 3.846| 197.536 RTD| 106.977| 379.307| 425.585| 4| 3.846| 425.585 RTD| 407.091| -125.220| 719.171| 7| 3.846| 719.171 RTD| 704.716| 174.537| 1039.347| 10| 3.846| 1039.347 RTD| 1006.644| 383.889| 1264.521| 12| 3.846| 1264.521 RTD| 1206.574| -131.780| 1524.619| 15| 3.846| 1524.619 RTD| 1506.889| 347.804| 2016.462| 20| 3.846| 2016.462 RTD| 2006.521| -227.764| 2289.891| 22| 3.846| 2289.891 RTD| 2207.046| 61.305| 2584.121| 25| 3.846| 2584.121 RTD| 2506.565| 361.086| 2812.531| 28| 3.846| 2812.531 RTD| 2807.104| -233.460| 3108.830| 30| 3.846| 3108.830 RTT| 00:00:43 (periodic user-mode task, 100 us period) RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst RTD| 3004.451| 55.669| 3335.249| 33| 3.846| 3335.249 RTD| 3306.822| -365.740| 3778.314| 37| 3.846| 3778.314 RTD| 3706.558| -50.325| 4051.165| 40| 3.846| 4051.165 RTD| 4006.912| 249.305| 4374.872| 43| 3.846| 4374.872 RTD| 4306.933| -256.007| 4646.662| 46| 3.846| 4646.662 RTD| 4607.066| 43.525| 4948.757| 49| 3.846| 4948.757 RTD| 4906.711| -373.215| 5318.661| 53| 3.846| 5318.661 RTD| 5306.813| 25.979| 5796.758| 57| 3.846| 5796.758 RTD| 5706.867| 337.037| 6031.390| 60| 3.846| 6031.390 ---|------------|------------|------------|--------|------------------------- RTS| 3.846| 21.697| 6031.390| 60| 00:00:51/00:00:51 [-- Attachment #2: Type: text/html, Size: 10407 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-20 21:17 [Xenomai-help] Beginner's question / testsuite / latency Julien Heyman @ 2006-07-20 21:58 ` Jan Kiszka 2006-07-22 9:52 ` Julien Heyman 2006-07-21 13:25 ` [Xenomai-help] Beginner's question / testsuite / latency Gilles Chanteperdrix 1 sibling, 1 reply; 29+ messages in thread From: Jan Kiszka @ 2006-07-20 21:58 UTC (permalink / raw) To: Julien Heyman; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 2137 bytes --] Julien Heyman wrote: > Hi, > > I am currently trying to evaluate Xenomai, and my current setup is : > VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. > I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. General advice: especially when starting new, try to pick the latest version, at least the latest from the preferred series (here 2.1.2). But 2.2 is even better. :) > When I run the latency part of the testsuite (in a console under KDE), I > get > results that I cannot understand, so I probably did something wrong > (execution trace included below). > I get reasonable values during the first seconds, then all of a sudden > latencies begin to rise, continuously, to very large values. > - I did check that DMA transfer is activated on my HD. > - I did select "Enable SMI workaround" + "Globally disable SMI" in the > Xenomai > options while configuring the kernel. > - I have disabled power management at BIOS level and disabled ACPI support > and > CPU frequency scaling during kernel configuration. > - I checked that I don't have anything called "legacy USB" in my BIOS. I do > have an "OnChip USB" option enable in the BIOS though. > > Any advice would be appreciated ! Maybe it's related to some other weird on-chip hardware. At work we run Xenomai only on a head-less VIA C3 box, i.e. without X. No problems so far. I would suggest to try stopping X and run the test from the text mode. A further tool to analyse such effects in details is the I-pipe tracer. It's an additional patch you have to apply to your kernel (see http://download.gna.org/adeos/patches/v2.6/i386/tracer). Enable this I-pipe option, rebuild your kernel, and start the latency test with -f. The test will then capture on every new worst-case delay a backtrace to /proc/ipipe/trace/frozen. You may want to play with the number of back-trace points or the verbose mode (see /proc/ipipe/trace/*) even after the capturing. Unless you find something obvious immediately, feel free to post a backtrace that includes the problematic delay period before the freeze (compress when too large). Jan [-- Attachment #2: OpenPGP digital signature --] [-- Type: application/pgp-signature, Size: 249 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-20 21:58 ` Jan Kiszka @ 2006-07-22 9:52 ` Julien Heyman 2006-07-22 17:17 ` Jan Kiszka 0 siblings, 1 reply; 29+ messages in thread From: Julien Heyman @ 2006-07-22 9:52 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai Hi, On Thursday 20 July 2006 23:58, Jan Kiszka wrote: > Julien Heyman wrote: > > Hi, > > > > I am currently trying to evaluate Xenomai, and my current setup is : > > VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. > > I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. > > General advice: especially when starting new, try to pick the latest > version, at least the latest from the preferred series (here 2.1.2). But > 2.2 is even better. :) > OK. Actually started with Xenomai-2.1.0 then switched to 2.1.1 to fix a kernel build error. But anyway, I will start with a fresh install of 2.2 as soon as I have figured out the other points :) > > When I run the latency part of the testsuite (in a console under KDE), I > > get > > results that I cannot understand, so I probably did something wrong > > (execution trace included below). > > I get reasonable values during the first seconds, then all of a sudden > > latencies begin to rise, continuously, to very large values. > > - I did check that DMA transfer is activated on my HD. > > - I did select "Enable SMI workaround" + "Globally disable SMI" in the > > Xenomai > > options while configuring the kernel. > > - I have disabled power management at BIOS level and disabled ACPI > > support and > > CPU frequency scaling during kernel configuration. > > - I checked that I don't have anything called "legacy USB" in my BIOS. I > > do have an "OnChip USB" option enable in the BIOS though. > > > > Any advice would be appreciated ! > > Maybe it's related to some other weird on-chip hardware. At work we run > Xenomai only on a head-less VIA C3 box, i.e. without X. No problems so > far. I would suggest to try stopping X and run the test from the text mode. This is interesting : indeed when I switch to console mode (Ctrl+Atl+F1) and run the test, the latency values stay right on track. If I let the test run, switch to X, and switch back to the original console, the values have gone wild in the meantime. So there seems to be a strong link with X. What does that say about potential causes of my issue ? > > A further tool to analyse such effects in details is the I-pipe tracer. > It's an additional patch you have to apply to your kernel (see > http://download.gna.org/adeos/patches/v2.6/i386/tracer). Enable this > I-pipe option, rebuild your kernel, and start the latency test with -f. > The test will then capture on every new worst-case delay a backtrace to > /proc/ipipe/trace/frozen. You may want to play with the number of > back-trace points or the verbose mode (see /proc/ipipe/trace/*) even > after the capturing. > I had already used an adeos patch during my initial kernel-patching (adeos-ipipe-2.6.17-i386-1.3-07.patch) I tried running the latency test using /usr/xenomai/bin/xeno-load latency -f but I get this error : == Sampling period: 100 us == Test mode: periodic user-mode task == All results in microseconds latency: failed to open benchmark device, code -19 (modprobe xeno_timerbench?) What am I doing wrong ? Thanks, Julien Heyman > Unless you find something obvious immediately, feel free to post a > backtrace that includes the problematic delay period before the freeze > (compress when too large). > > Jan ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-22 9:52 ` Julien Heyman @ 2006-07-22 17:17 ` Jan Kiszka 2006-07-28 21:17 ` Julien Heyman 0 siblings, 1 reply; 29+ messages in thread From: Jan Kiszka @ 2006-07-22 17:17 UTC (permalink / raw) To: Julien Heyman; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 3592 bytes --] Julien Heyman wrote: > Hi, > > On Thursday 20 July 2006 23:58, Jan Kiszka wrote: >> Julien Heyman wrote: >>> Hi, >>> >>> I am currently trying to evaluate Xenomai, and my current setup is : >>> VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. >>> I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. >> General advice: especially when starting new, try to pick the latest >> version, at least the latest from the preferred series (here 2.1.2). But >> 2.2 is even better. :) >> > > OK. Actually started with Xenomai-2.1.0 then switched to 2.1.1 to fix a kernel > build error. But anyway, I will start with a fresh install of 2.2 as soon as > I have figured out the other points :) > >>> When I run the latency part of the testsuite (in a console under KDE), I >>> get >>> results that I cannot understand, so I probably did something wrong >>> (execution trace included below). >>> I get reasonable values during the first seconds, then all of a sudden >>> latencies begin to rise, continuously, to very large values. >>> - I did check that DMA transfer is activated on my HD. >>> - I did select "Enable SMI workaround" + "Globally disable SMI" in the >>> Xenomai >>> options while configuring the kernel. >>> - I have disabled power management at BIOS level and disabled ACPI >>> support and >>> CPU frequency scaling during kernel configuration. >>> - I checked that I don't have anything called "legacy USB" in my BIOS. I >>> do have an "OnChip USB" option enable in the BIOS though. >>> >>> Any advice would be appreciated ! >> Maybe it's related to some other weird on-chip hardware. At work we run >> Xenomai only on a head-less VIA C3 box, i.e. without X. No problems so >> far. I would suggest to try stopping X and run the test from the text mode. > > This is interesting : indeed when I switch to console mode (Ctrl+Atl+F1) and > run the test, the latency values stay right on track. > If I let the test run, switch to X, and switch back to the original console, > the values have gone wild in the meantime. > So there seems to be a strong link with X. > What does that say about potential causes of my issue ? Don't know. Might be a weird hardware design (wrt bus latencies) - or do you use any binary-only driver for X? > >> A further tool to analyse such effects in details is the I-pipe tracer. >> It's an additional patch you have to apply to your kernel (see >> http://download.gna.org/adeos/patches/v2.6/i386/tracer). Enable this >> I-pipe option, rebuild your kernel, and start the latency test with -f. >> The test will then capture on every new worst-case delay a backtrace to >> /proc/ipipe/trace/frozen. You may want to play with the number of >> back-trace points or the verbose mode (see /proc/ipipe/trace/*) even >> after the capturing. >> > > I had already used an adeos patch during my initial kernel-patching > (adeos-ipipe-2.6.17-i386-1.3-07.patch) The tracer is an additional patch on top of I-pipe, see link above. > I tried running the latency test using /usr/xenomai/bin/xeno-load latency -f > but I get this error : > > == Sampling period: 100 us > == Test mode: periodic user-mode task > == All results in microseconds > latency: failed to open benchmark device, code -19 > (modprobe xeno_timerbench?) > > What am I doing wrong ? For < 2.2: check if CONFIG_XENO_DRIVERS_TIMERBENCH is y or m. If it's a module, follow the suggestion latency printed. In 2.2 the required tracing interface was moved to the nucleus, no need for these steps then. Jan [-- Attachment #2: OpenPGP digital signature --] [-- Type: application/pgp-signature, Size: 249 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-22 17:17 ` Jan Kiszka @ 2006-07-28 21:17 ` Julien Heyman 2006-07-28 21:32 ` Gilles Chanteperdrix 2006-07-29 14:20 ` Jan Kiszka 0 siblings, 2 replies; 29+ messages in thread From: Julien Heyman @ 2006-07-28 21:17 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 5254 bytes --] Hi, here's a quick follow-up on my issue, thanks for your time ! Julien Heyman On Saturday 22 July 2006 19:17, Jan Kiszka wrote: > Julien Heyman wrote: > > Hi, > > > > On Thursday 20 July 2006 23:58, Jan Kiszka wrote: > >> Julien Heyman wrote: > >>> Hi, > >>> > >>> I am currently trying to evaluate Xenomai, and my current setup is : > >>> VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. > >>> I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. > >> > >> General advice: especially when starting new, try to pick the latest > >> version, at least the latest from the preferred series (here 2.1.2). But > >> 2.2 is even better. :) > > > > OK. Actually started with Xenomai-2.1.0 then switched to 2.1.1 to fix a > > kernel build error. But anyway, I will start with a fresh install of 2.2 > > as soon as I have figured out the other points :) > > > >>> When I run the latency part of the testsuite (in a console under KDE), > >>> I get > >>> results that I cannot understand, so I probably did something wrong > >>> (execution trace included below). > >>> I get reasonable values during the first seconds, then all of a sudden > >>> latencies begin to rise, continuously, to very large values. > >>> - I did check that DMA transfer is activated on my HD. > >>> - I did select "Enable SMI workaround" + "Globally disable SMI" in the > >>> Xenomai > >>> options while configuring the kernel. > >>> - I have disabled power management at BIOS level and disabled ACPI > >>> support and > >>> CPU frequency scaling during kernel configuration. > >>> - I checked that I don't have anything called "legacy USB" in my BIOS. > >>> I do have an "OnChip USB" option enable in the BIOS though. > >>> > >>> Any advice would be appreciated ! > >> > >> Maybe it's related to some other weird on-chip hardware. At work we run > >> Xenomai only on a head-less VIA C3 box, i.e. without X. No problems so > >> far. I would suggest to try stopping X and run the test from the text > >> mode. > > > > This is interesting : indeed when I switch to console mode (Ctrl+Atl+F1) > > and run the test, the latency values stay right on track. > > If I let the test run, switch to X, and switch back to the original > > console, the values have gone wild in the meantime. > > So there seems to be a strong link with X. > > What does that say about potential causes of my issue ? > > Don't know. Might be a weird hardware design (wrt bus latencies) - or do > you > use any binary-only driver for X? I did not install any specific driver, I probably use the standard Trident driver that came with the Kubuntu distribution. > > >> A further tool to analyse such effects in details is the I-pipe tracer. > >> It's an additional patch you have to apply to your kernel (see > >> http://download.gna.org/adeos/patches/v2.6/i386/tracer). Enable this > >> I-pipe option, rebuild your kernel, and start the latency test with -f. > >> The test will then capture on every new worst-case delay a backtrace to > >> /proc/ipipe/trace/frozen. You may want to play with the number of > >> back-trace points or the verbose mode (see /proc/ipipe/trace/*) even > >> after the capturing. > > > > I had already used an adeos patch during my initial kernel-patching > > (adeos-ipipe-2.6.17-i386-1.3-07.patch) > > The tracer is an additional patch on top of I-pipe, see link above. > > > I tried running the latency test using /usr/xenomai/bin/xeno-load latency > > -f but I get this error : > > > > == Sampling period: 100 us > > == Test mode: periodic user-mode task > > == All results in microseconds > > latency: failed to open benchmark device, code -19 > > (modprobe xeno_timerbench?) > > > > What am I doing wrong ? > > For < 2.2: check if CONFIG_XENO_DRIVERS_TIMERBENCH is y or m. If it's a > module, follow the suggestion latency printed. > > In 2.2 the required tracing interface was moved to the nucleus, no need > for these steps then. Ok, I installed Xenomai 2.2 from scratch over a freshly extracted kernel source tree, used the tracer patch ipipe-tracer-2.6.17-i386-1.3-08.patch, rebuilt the kernel and relaunch the test : I still get increasing latencies. I attach a copy of the latency test run, and the associated traces in files "max" and "frozen" from /proc/ipipe/trace I have no clue how to interpret theses traces, is there a documentation/user's guide available for the ipipe tracer ? Regarding Gilles' comments on this topic : > Losing too many ticks! > TSC cannot be used as a timesource. > Possible reasons for this are: > You're running with Speedstep, > You don't have DMA enabled for your hard disk (see hdparm), > Incorrect TSC synchronization on an SMP system (see dmesg). > Falling back to a sane timesource now. > Do you see such message in kernel logs ? No, I don't get any of these. > If this is the issue you are having, then you may try passing idle=poll > on kernel boot line. Or recompile the kernel selecting a processor that > has no tsc (for example 486), xenomai will then use the 8254 counter to > emulate the tsc. I tried to rebuild with CPU=486, but it gives the same result. > > Jan [-- Attachment #2: ipipe_trace_xen2.2.txt --] [-- Type: text/plain, Size: 21594 bytes --] bids@domain.hid$ sudo /usr/xenomai/bin/xeno-load latency -f Password: * * * Type ^C to stop this application. * * == Sampling period: 100 us == Test mode: periodic user-mode task == All results in microseconds warming up... RTT| 00:00:01 (periodic user-mode task, 100 us period, priority 99) RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst RTD| 21.428| 23.956| 38.249| 0| 21.428| 38.249 RTD| 22.419| 24.491| 31.760| 0| 21.428| 38.249 RTD| 21.833| 23.731| 52.247| 0| 21.428| 52.247 RTD| 21.776| 23.733| 45.060| 0| 21.428| 52.247 RTD| 21.467| 24.434| 40.813| 0| 21.428| 52.247 RTD| 21.613| 24.684| 40.517| 0| 21.428| 52.247 RTD| 21.585| 25.503| 51.990| 0| 21.428| 52.247 RTD| 21.212| 25.497| 44.028| 0| 21.212| 52.247 RTD| 21.587| 25.535| 119.516| 1| 21.212| 119.516 RTD| 21.604| 26.543| 225.722| 3| 21.212| 225.722 RTD| 21.958| 26.575| 48.329| 3| 21.212| 225.722 RTD| 22.247| 25.216| 57.580| 3| 21.212| 225.722 RTD| 22.253| 25.017| 53.521| 3| 21.212| 225.722 RTD| 22.376| 24.824| 54.095| 3| 21.212| 225.722 RTD| 22.256| 24.655| 55.816| 3| 21.212| 225.722 RTD| 22.324| 24.682| 48.350| 3| 21.212| 225.722 RTD| 21.454| 24.519| 342.492| 9| 21.212| 342.492 RTD| 21.578| 23.617| 49.107| 9| 21.212| 342.492 RTD| 21.621| 23.611| 38.444| 9| 21.212| 342.492 RTD| 21.625| 23.958| 192.672| 10| 21.212| 342.492 RTD| 21.656| 23.675| 34.820| 10| 21.212| 342.492 RTT| 00:00:22 (periodic user-mode task, 100 us period, priority 99) RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst RTD| 21.688| 23.626| 36.496| 10| 21.212| 342.492 RTD| 21.527| 23.720| 49.283| 10| 21.212| 342.492 RTD| 21.643| 23.711| 43.028| 10| 21.212| 342.492 ---|------------|------------|------------|--------|------------------------- RTS| 21.212| 24.562| 342.492| 10| 00:00:24/00:00:24 cat frozen : Freeze: 4770308881064 cycles, Trace Points: 30 (+10) +--------------- Hard IRQs ('|': locked) | +- Delay flag ('+': > 1 us, '!': > 10 us) | | Type Time Function (Parent) :|func -35 xnpod_schedule (xnintr_irq_handler) :|[ 3096] -34+ xnpod_schedule (xnintr_irq_handler) :|func -32+ __switch_to (xnpod_schedule) :|[21768] -30+ xnpod_schedule (xnpod_suspend_thread) :|func -28 __ipipe_restore_pipeline_head (xnpod_wait_thread_period) :|end -28+ __ipipe_restore_pipeline_head (xnpod_wait_thread_period) :|begin -26 __ipipe_dispatch_event (__ipipe_syscall_root) :|end -25+ __ipipe_dispatch_event (__ipipe_syscall_root) : func -22 __ipipe_syscall_root (system_call) : func -21 __ipipe_dispatch_event (__ipipe_syscall_root) :|begin -21 __ipipe_dispatch_event (__ipipe_syscall_root) :|end -20 __ipipe_dispatch_event (__ipipe_syscall_root) : func -19+ hisyscall_event (__ipipe_dispatch_event) : func -18 __rt_timer_tsc2ns (hisyscall_event) : func -17 __copy_from_user_ll (__rt_timer_tsc2ns) : func -16+ rt_timer_tsc2ns (__rt_timer_tsc2ns) : func -15 __copy_to_user_ll (__rt_timer_tsc2ns) :|begin -14+ __ipipe_dispatch_event (__ipipe_syscall_root) :|end -13+ __ipipe_dispatch_event (__ipipe_syscall_root) : func -11 __ipipe_syscall_root (system_call) : func -11 __ipipe_dispatch_event (__ipipe_syscall_root) :|begin -10+ __ipipe_dispatch_event (__ipipe_syscall_root) :|end -9 __ipipe_dispatch_event (__ipipe_syscall_root) : func -8+ hisyscall_event (__ipipe_dispatch_event) : func -7+ xnshadow_sys_trace (hisyscall_event) : func -5 ipipe_trace_frozen_reset (xnshadow_sys_trace) : func -4 __ipipe_global_path_lock (ipipe_trace_frozen_reset) :|begin -3+ __ipipe_global_path_lock (ipipe_trace_frozen_reset) :|end 0 __ipipe_global_path_unlock (ipipe_trace_frozen_reset) < freeze 0 xnshadow_sys_trace (hisyscall_event) |begin 1 __ipipe_dispatch_event (__ipipe_syscall_root) |end 1 __ipipe_dispatch_event (__ipipe_syscall_root) func 3 __ipipe_syscall_root (system_call) func 3 __ipipe_dispatch_event (__ipipe_syscall_root) |begin 4 __ipipe_dispatch_event (__ipipe_syscall_root) |end 5 __ipipe_dispatch_event (__ipipe_syscall_root) func 5 hisyscall_event (__ipipe_dispatch_event) func 6 __rt_task_wait_period (hisyscall_event) func 7 rt_task_wait_period (__rt_task_wait_period) func 8 xnpod_wait_thread_period (rt_task_wait_period) cat max : Begin: 943575374801 cycles, Trace Points: 218 (-10/+1), Length: 376 us +--------------- Hard IRQs ('|': locked) | +- Delay flag ('+': > 1 us, '!': > 10 us) | | Type Time Function (Parent) |func -19650 xnpod_schedule (xnpod_suspend_thread) |[21559] -19649 xnpod_schedule (xnpod_suspend_thread) |func -19647 __switch_to (xnpod_schedule) |[ 3096] -19646 xnpod_schedule (xnintr_irq_handler) |func -19644 __ipipe_walk_pipeline (__ipipe_handle_irq) |end -19643 common_interrupt (<b7a31ed5>) |func -19643 __ipipe_stall_root (resume_userspace) func -19642 __ipipe_unstall_iret_root (restore_raw) |begin -19641 __ipipe_unstall_iret_root (restore_raw) |end -19640 __ipipe_unstall_iret_root (restore_raw) >|begin 0+ common_interrupt (<080c4fce>) :|func 1 __ipipe_handle_irq (common_interrupt) :|func 1 __ipipe_ack_common_irq (__ipipe_handle_irq) :|func 2 ipipe_test_and_stall_pipeline_from (__ipipe_ack_common_irq) :|func 3+ mask_and_ack_8259A (__ipipe_ack_common_irq) :|func 5 __ipipe_dispatch_wired (__ipipe_handle_irq) :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) :|func 6 xnintr_irq_handler (xnintr_clock_handler) :|func 7 xnpod_announce_tick (xnintr_irq_handler) :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 10 xnpod_resume_thread (xnthread_periodic_handler) :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 15+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 17+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 19+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 20+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 22+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 24+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 25+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 27+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 29+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 30+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 32+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 34+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 36+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 38+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 39+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 41+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 43+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 44+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 46+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 48+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 49+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 52+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 53+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 55+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 57+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 58+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 60+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 62+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 63+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 65+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 67+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 69+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 71+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 73+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 75+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 77+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 78+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 80+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 81+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 83+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 85+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 87+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 89+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 91+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 92+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 94+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 95+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 97+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 99+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 100+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 102+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 105+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 106+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 108+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 109+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 111+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 113+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 114+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 116+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 118+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 119+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 122+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 123+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 125+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 127+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 128+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 131+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 133+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 135+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 137+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 138+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 141+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 142+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 144+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 146+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 147+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 149+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 151+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 152+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 154+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 155+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 158+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 160+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 162+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 163+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 165+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 167+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 169+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 170+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 172+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 173+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 176+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 178+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 179+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 181+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 183+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 184+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 186+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 187+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 189+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 191+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 194+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 195+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 198+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 199+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 201+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 202+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 204+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 206+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 208+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 210+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 213+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 214+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 216+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 218+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 219+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 221+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 223+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 224+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 226+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 227+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 230+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 232+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 233+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 235+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 237+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 238+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 240+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 242+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 243+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 245+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 248+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 249+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 251+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 253+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 255+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 256+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 258+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 260+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 262+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 264+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 266+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 268+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 270+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 271+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 273+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 275+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 276+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 278+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 280+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 281+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 284+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 285+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 287+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 289+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 290+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 292+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 293+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 295+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 297+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 298+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 301+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 303+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 305+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 306+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 308+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 309+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 311+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 313+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 314+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 316+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 319+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 320+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 322+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 324+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 325+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 327+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 328+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 330+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 332+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 333+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 336+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 338+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 339+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 341+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 343+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 344+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 346+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 347+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 349+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 351+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 353+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 355+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 357+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 358+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 360+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 361+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) :|func 369+ xnpod_schedule (xnintr_irq_handler) :|[ 3096] 370+ xnpod_schedule (xnintr_irq_handler) :|func 372+ __switch_to (xnpod_schedule) :|[21559] 374+ xnpod_schedule (xnpod_suspend_thread) :|func 375 __ipipe_restore_pipeline_head (xnpod_wait_thread_period) <|end 376 __ipipe_restore_pipeline_head (xnpod_wait_thread_period) |begin 377 __ipipe_dispatch_event (__ipipe_syscall_root) ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-28 21:17 ` Julien Heyman @ 2006-07-28 21:32 ` Gilles Chanteperdrix 2006-07-30 17:29 ` Julien Heyman 2006-07-29 14:20 ` Jan Kiszka 1 sibling, 1 reply; 29+ messages in thread From: Gilles Chanteperdrix @ 2006-07-28 21:32 UTC (permalink / raw) To: Julien Heyman; +Cc: xenomai, Jan Kiszka Julien Heyman wrote: > > Losing too many ticks! > > TSC cannot be used as a timesource. ~ > > Possible reasons for this are: > > ~ You're running with Speedstep, > > ~ You don't have DMA enabled for your hard disk (see hdparm), > > ~ Incorrect TSC synchronization on an SMP system (see dmesg). > > Falling back to a sane timesource now. > > > Do you see such message in kernel logs ? > > No, I don't get any of these. > > > If this is the issue you are having, then you may try passing idle=poll > > on kernel boot line. Or recompile the kernel selecting a processor that > > has no tsc (for example 486), xenomai will then use the 8254 counter to > > emulate the tsc. > > I tried to rebuild with CPU=486, but it gives the same result. Did you try booting with the idle=poll option ? Also, could you try re-enabling ACPI, except the "processor" module ? -- Gilles Chanteperdrix. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-28 21:32 ` Gilles Chanteperdrix @ 2006-07-30 17:29 ` Julien Heyman 2006-07-30 17:49 ` Philippe Gerum 2006-07-30 20:39 ` Gilles Chanteperdrix 0 siblings, 2 replies; 29+ messages in thread From: Julien Heyman @ 2006-07-30 17:29 UTC (permalink / raw) To: Gilles Chanteperdrix; +Cc: xenomai, Jan Kiszka On Friday 28 July 2006 23:32, Gilles Chanteperdrix wrote: > Julien Heyman wrote: > > > Losing too many ticks! > > > TSC cannot be used as a timesource. ~ > > > Possible reasons for this are: > > > ~ You're running with Speedstep, > > > ~ You don't have DMA enabled for your hard disk (see hdparm), > > > ~ Incorrect TSC synchronization on an SMP system (see dmesg). > > > Falling back to a sane timesource now. > > > > > > Do you see such message in kernel logs ? > > > > No, I don't get any of these. > > > > > If this is the issue you are having, then you may try passing > > > idle=poll on kernel boot line. Or recompile the kernel selecting a > > > processor that has no tsc (for example 486), xenomai will then use the > > > 8254 counter to emulate the tsc. > > > > I tried to rebuild with CPU=486, but it gives the same result. > > Did you try booting with the idle=poll option ? Also, could you try > re-enabling ACPI, except the "processor" module ? I tried both, without success. My quest goes on... :/ By the way, there is something I don't understand : I get the following error message at boot time : Incompatible timer mode found (aperiodic, need periodic) VxWorks skin init failed, code -16 whereas I do have periodic timer enabled, I think : bids@domain.hid$ cat .config | grep PERIO CONFIG_XENO_OPT_TIMING_PERIODIC=y CONFIG_XENO_OPT_TIMING_PERIOD=0 (or am I checking the wrong setting ? Also, it "0" a legitimate value for the timing period ?) Julien Heyman ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 17:29 ` Julien Heyman @ 2006-07-30 17:49 ` Philippe Gerum 2006-07-30 20:39 ` Gilles Chanteperdrix 1 sibling, 0 replies; 29+ messages in thread From: Philippe Gerum @ 2006-07-30 17:49 UTC (permalink / raw) To: Julien Heyman; +Cc: xenomai, Jan Kiszka On Sun, 2006-07-30 at 19:29 +0200, Julien Heyman wrote: > On Friday 28 July 2006 23:32, Gilles Chanteperdrix wrote: > > Julien Heyman wrote: > > > > Losing too many ticks! > > > > TSC cannot be used as a timesource. ~ > > > > Possible reasons for this are: > > > > ~ You're running with Speedstep, > > > > ~ You don't have DMA enabled for your hard disk (see hdparm), > > > > ~ Incorrect TSC synchronization on an SMP system (see dmesg). > > > > Falling back to a sane timesource now. > > > > > > > > Do you see such message in kernel logs ? > > > > > > No, I don't get any of these. > > > > > > > If this is the issue you are having, then you may try passing > > > > idle=poll on kernel boot line. Or recompile the kernel selecting a > > > > processor that has no tsc (for example 486), xenomai will then use the > > > > 8254 counter to emulate the tsc. > > > > > > I tried to rebuild with CPU=486, but it gives the same result. > > > > Did you try booting with the idle=poll option ? Also, could you try > > re-enabling ACPI, except the "processor" module ? > > I tried both, without success. > My quest goes on... :/ > > By the way, there is something I don't understand : I get the following error > message at boot time : > Incompatible timer mode found (aperiodic, need periodic) > VxWorks skin init failed, code -16 > It's because the VxWorks skin requires periodic timing whilst the native/POSIX ones require aperiodic setup. This error is raised whenever multiple skins with conflicting timing requirements are built statically into the kernel. The best way to handle this is to enable skins as modules. > whereas I do have periodic timer enabled, I think : > bids@domain.hid$ cat .config | grep PERIO > CONFIG_XENO_OPT_TIMING_PERIODIC=y > CONFIG_XENO_OPT_TIMING_PERIOD=0 > > (or am I checking the wrong setting ? Also, it "0" a legitimate value for the > > timing period ?) Yes. The skins requiring periodic timing will substitute their own default values. > > Julien Heyman > > > > > _______________________________________________ > Xenomai-help mailing list > Xenomai-help@domain.hid > https://mail.gna.org/listinfo/xenomai-help -- Philippe. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 17:29 ` Julien Heyman 2006-07-30 17:49 ` Philippe Gerum @ 2006-07-30 20:39 ` Gilles Chanteperdrix 1 sibling, 0 replies; 29+ messages in thread From: Gilles Chanteperdrix @ 2006-07-30 20:39 UTC (permalink / raw) To: Julien Heyman; +Cc: xenomai Julien Heyman wrote: > On Friday 28 July 2006 23:32, Gilles Chanteperdrix wrote: > > Julien Heyman wrote: > > > > Losing too many ticks! > > > > TSC cannot be used as a timesource. ~ > > > > Possible reasons for this are: > > > > ~ You're running with Speedstep, > > > > ~ You don't have DMA enabled for your hard disk (see hdparm), > > > > ~ Incorrect TSC synchronization on an SMP system (see dmesg). > > > > Falling back to a sane timesource now. > > > > > > > > Do you see such message in kernel logs ? > > > > > > No, I don't get any of these. > > > > > > > If this is the issue you are having, then you may try passing > > > > idle=poll on kernel boot line. Or recompile the kernel selecting a > > > > processor that has no tsc (for example 486), xenomai will then use the > > > > 8254 counter to emulate the tsc. > > > > > > I tried to rebuild with CPU=486, but it gives the same result. > > > > Did you try booting with the idle=poll option ? Also, could you try > > re-enabling ACPI, except the "processor" module ? > > I tried both, without success. > My quest goes on... :/ You should look, if possible, for the way of disabling SMIs on the chipset you are using, xenomai built-in smi workaround works only for intel chipsets. -- Gilles Chanteperdrix. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-28 21:17 ` Julien Heyman 2006-07-28 21:32 ` Gilles Chanteperdrix @ 2006-07-29 14:20 ` Jan Kiszka 2006-07-30 17:36 ` Julien Heyman 2006-07-30 18:03 ` Philippe Gerum 1 sibling, 2 replies; 29+ messages in thread From: Jan Kiszka @ 2006-07-29 14:20 UTC (permalink / raw) To: Julien Heyman; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 15375 bytes --] Julien Heyman wrote: > Hi, > > here's a quick follow-up on my issue, thanks for your time ! > > Julien Heyman > > > On Saturday 22 July 2006 19:17, Jan Kiszka wrote: >> Julien Heyman wrote: >>> Hi, >>> >>> On Thursday 20 July 2006 23:58, Jan Kiszka wrote: >>>> Julien Heyman wrote: >>>>> Hi, >>>>> >>>>> I am currently trying to evaluate Xenomai, and my current setup is : >>>>> VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. >>>>> I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. >>>> General advice: especially when starting new, try to pick the latest >>>> version, at least the latest from the preferred series (here 2.1.2). But >>>> 2.2 is even better. :) >>> OK. Actually started with Xenomai-2.1.0 then switched to 2.1.1 to fix a >>> kernel build error. But anyway, I will start with a fresh install of 2.2 >>> as soon as I have figured out the other points :) >>> >>>>> When I run the latency part of the testsuite (in a console under KDE), >>>>> I get >>>>> results that I cannot understand, so I probably did something wrong >>>>> (execution trace included below). >>>>> I get reasonable values during the first seconds, then all of a sudden >>>>> latencies begin to rise, continuously, to very large values. >>>>> - I did check that DMA transfer is activated on my HD. >>>>> - I did select "Enable SMI workaround" + "Globally disable SMI" in the >>>>> Xenomai >>>>> options while configuring the kernel. >>>>> - I have disabled power management at BIOS level and disabled ACPI >>>>> support and >>>>> CPU frequency scaling during kernel configuration. >>>>> - I checked that I don't have anything called "legacy USB" in my BIOS. >>>>> I do have an "OnChip USB" option enable in the BIOS though. >>>>> >>>>> Any advice would be appreciated ! >>>> Maybe it's related to some other weird on-chip hardware. At work we run >>>> Xenomai only on a head-less VIA C3 box, i.e. without X. No problems so >>>> far. I would suggest to try stopping X and run the test from the text >>>> mode. >>> This is interesting : indeed when I switch to console mode (Ctrl+Atl+F1) >>> and run the test, the latency values stay right on track. >>> If I let the test run, switch to X, and switch back to the original >>> console, the values have gone wild in the meantime. >>> So there seems to be a strong link with X. >>> What does that say about potential causes of my issue ? >> Don't know. Might be a weird hardware design (wrt bus latencies) - or do >> you >> use any binary-only driver for X? > > > I did not install any specific driver, I probably use the standard Trident > driver that came with the Kubuntu distribution. > > >>>> A further tool to analyse such effects in details is the I-pipe tracer. >>>> It's an additional patch you have to apply to your kernel (see >>>> http://download.gna.org/adeos/patches/v2.6/i386/tracer). Enable this >>>> I-pipe option, rebuild your kernel, and start the latency test with -f. >>>> The test will then capture on every new worst-case delay a backtrace to >>>> /proc/ipipe/trace/frozen. You may want to play with the number of >>>> back-trace points or the verbose mode (see /proc/ipipe/trace/*) even >>>> after the capturing. >>> I had already used an adeos patch during my initial kernel-patching >>> (adeos-ipipe-2.6.17-i386-1.3-07.patch) >> The tracer is an additional patch on top of I-pipe, see link above. >> >>> I tried running the latency test using /usr/xenomai/bin/xeno-load latency >>> -f but I get this error : >>> >>> == Sampling period: 100 us >>> == Test mode: periodic user-mode task >>> == All results in microseconds >>> latency: failed to open benchmark device, code -19 >>> (modprobe xeno_timerbench?) >>> >>> What am I doing wrong ? >> For < 2.2: check if CONFIG_XENO_DRIVERS_TIMERBENCH is y or m. If it's a >> module, follow the suggestion latency printed. >> >> In 2.2 the required tracing interface was moved to the nucleus, no need >> for these steps then. > > > Ok, I installed Xenomai 2.2 from scratch over a freshly extracted kernel > source tree, used the tracer patch ipipe-tracer-2.6.17-i386-1.3-08.patch, > rebuilt the kernel and relaunch the test : I still get increasing latencies. > > I attach a copy of the latency test run, and the associated traces in > files "max" and "frozen" from /proc/ipipe/trace > > I have no clue how to interpret theses traces, is there a documentation/user's > guide available for the ipipe tracer ? Nope, I skipped this "boring" part so far. But I will provide some explanations below. > > Regarding Gilles' comments on this topic : > >> Losing too many ticks! >> TSC cannot be used as a timesource. Â >> Possible reasons for this are: >> Â You're running with Speedstep, >> Â You don't have DMA enabled for your hard disk (see hdparm), >> Â Incorrect TSC synchronization on an SMP system (see dmesg). >> Falling back to a sane timesource now. > >> Do you see such message in kernel logs ? > > No, I don't get any of these. > >> If this is the issue you are having, then you may try passing idle=poll >> on kernel boot line. Or recompile the kernel selecting a processor that >> has no tsc (for example 486), xenomai will then use the 8254 counter to >> emulate the tsc. > > I tried to rebuild with CPU=486, but it gives the same result. > >> Jan >> >> ------------------------------------------------------------------------ >> >> bids@domain.hid$ sudo /usr/xenomai/bin/xeno-load latency -f >> Password: >> * >> * >> * Type ^C to stop this application. >> * >> * >> == Sampling period: 100 us >> == Test mode: periodic user-mode task >> == All results in microseconds >> warming up... >> RTT| 00:00:01 (periodic user-mode task, 100 us period, priority 99) >> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst >> RTD| 21.428| 23.956| 38.249| 0| 21.428| 38.249 >> RTD| 22.419| 24.491| 31.760| 0| 21.428| 38.249 >> RTD| 21.833| 23.731| 52.247| 0| 21.428| 52.247 >> RTD| 21.776| 23.733| 45.060| 0| 21.428| 52.247 >> RTD| 21.467| 24.434| 40.813| 0| 21.428| 52.247 >> RTD| 21.613| 24.684| 40.517| 0| 21.428| 52.247 >> RTD| 21.585| 25.503| 51.990| 0| 21.428| 52.247 >> RTD| 21.212| 25.497| 44.028| 0| 21.212| 52.247 >> RTD| 21.587| 25.535| 119.516| 1| 21.212| 119.516 >> RTD| 21.604| 26.543| 225.722| 3| 21.212| 225.722 >> RTD| 21.958| 26.575| 48.329| 3| 21.212| 225.722 >> RTD| 22.247| 25.216| 57.580| 3| 21.212| 225.722 >> RTD| 22.253| 25.017| 53.521| 3| 21.212| 225.722 >> RTD| 22.376| 24.824| 54.095| 3| 21.212| 225.722 >> RTD| 22.256| 24.655| 55.816| 3| 21.212| 225.722 >> RTD| 22.324| 24.682| 48.350| 3| 21.212| 225.722 >> RTD| 21.454| 24.519| 342.492| 9| 21.212| 342.492 >> RTD| 21.578| 23.617| 49.107| 9| 21.212| 342.492 >> RTD| 21.621| 23.611| 38.444| 9| 21.212| 342.492 >> RTD| 21.625| 23.958| 192.672| 10| 21.212| 342.492 >> RTD| 21.656| 23.675| 34.820| 10| 21.212| 342.492 >> RTT| 00:00:22 (periodic user-mode task, 100 us period, priority 99) >> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst >> RTD| 21.688| 23.626| 36.496| 10| 21.212| 342.492 >> RTD| 21.527| 23.720| 49.283| 10| 21.212| 342.492 >> RTD| 21.643| 23.711| 43.028| 10| 21.212| 342.492 >> ---|------------|------------|------------|--------|------------------------- >> RTS| 21.212| 24.562| 342.492| 10| 00:00:24/00:00:24 >> >> >> cat frozen : This is the trace the latency application triggered on the maximum delay (342.492 us). You should extend the back-trace period to cover at least the observed latency (say up to -400 us). Try "echo 500 > /proc/ipipe/trace/back_trace_points" for this. You can furthermore switch on more verbosity with echo 1 > /proc/ipipe/trace/verbose". >> >> Freeze: 4770308881064 cycles, Trace Points: 30 (+10) >> >> +--------------- Hard IRQs ('|': locked) >> | +- Delay flag ('+': > 1 us, '!': > 10 us) >> | | >> Type Time Function (Parent) >> :|func -35 xnpod_schedule (xnintr_irq_handler) >> :|[ 3096] -34+ xnpod_schedule (xnintr_irq_handler) This traces the process (pid) being switched out. >> :|func -32+ __switch_to (xnpod_schedule) >> :|[21768] -30+ xnpod_schedule (xnpod_suspend_thread) This pid gets switched in, the latency test (more precisely the sampling thread). >> :|func -28 __ipipe_restore_pipeline_head (xnpod_wait_thread_period) >> :|end -28+ __ipipe_restore_pipeline_head (xnpod_wait_thread_period) >> :|begin -26 __ipipe_dispatch_event (__ipipe_syscall_root) >> :|end -25+ __ipipe_dispatch_event (__ipipe_syscall_root) >> : func -22 __ipipe_syscall_root (system_call) This is roughly the point when the latency test takes its timestamp to calculate the delay. This syscall here is then issued to convert TSCs into nanoseconds. >> : func -21 __ipipe_dispatch_event (__ipipe_syscall_root) >> :|begin -21 __ipipe_dispatch_event (__ipipe_syscall_root) >> :|end -20 __ipipe_dispatch_event (__ipipe_syscall_root) >> : func -19+ hisyscall_event (__ipipe_dispatch_event) >> : func -18 __rt_timer_tsc2ns (hisyscall_event) >> : func -17 __copy_from_user_ll (__rt_timer_tsc2ns) >> : func -16+ rt_timer_tsc2ns (__rt_timer_tsc2ns) >> : func -15 __copy_to_user_ll (__rt_timer_tsc2ns) >> :|begin -14+ __ipipe_dispatch_event (__ipipe_syscall_root) >> :|end -13+ __ipipe_dispatch_event (__ipipe_syscall_root) >> : func -11 __ipipe_syscall_root (system_call) >> : func -11 __ipipe_dispatch_event (__ipipe_syscall_root) >> :|begin -10+ __ipipe_dispatch_event (__ipipe_syscall_root) >> :|end -9 __ipipe_dispatch_event (__ipipe_syscall_root) >> : func -8+ hisyscall_event (__ipipe_dispatch_event) >> : func -7+ xnshadow_sys_trace (hisyscall_event) >> : func -5 ipipe_trace_frozen_reset (xnshadow_sys_trace) >> : func -4 __ipipe_global_path_lock (ipipe_trace_frozen_reset) >> :|begin -3+ __ipipe_global_path_lock (ipipe_trace_frozen_reset) >> :|end 0 __ipipe_global_path_unlock (ipipe_trace_frozen_reset) >> < freeze 0 xnshadow_sys_trace (hisyscall_event) And here we freeze after detecting a new worst-case (also issued as a syscall). >> |begin 1 __ipipe_dispatch_event (__ipipe_syscall_root) >> |end 1 __ipipe_dispatch_event (__ipipe_syscall_root) >> func 3 __ipipe_syscall_root (system_call) >> func 3 __ipipe_dispatch_event (__ipipe_syscall_root) >> |begin 4 __ipipe_dispatch_event (__ipipe_syscall_root) >> |end 5 __ipipe_dispatch_event (__ipipe_syscall_root) >> func 5 hisyscall_event (__ipipe_dispatch_event) >> func 6 __rt_task_wait_period (hisyscall_event) >> func 7 rt_task_wait_period (__rt_task_wait_period) >> func 8 xnpod_wait_thread_period (rt_task_wait_period) >> >> >> cat max : This trace captured the maximum time the system spent in IRQs-off context. >> Begin: 943575374801 cycles, Trace Points: 218 (-10/+1), Length: 376 us And that period took 376 us, a pathological result. It's a bit more than what latency observed, but that's normal for a short test cycle. >> >> +--------------- Hard IRQs ('|': locked) >> | +- Delay flag ('+': > 1 us, '!': > 10 us) >> | | >> Type Time Function (Parent) >> |func -19650 xnpod_schedule (xnpod_suspend_thread) >> |[21559] -19649 xnpod_schedule (xnpod_suspend_thread) >> |func -19647 __switch_to (xnpod_schedule) >> |[ 3096] -19646 xnpod_schedule (xnintr_irq_handler) >> |func -19644 __ipipe_walk_pipeline (__ipipe_handle_irq) >> |end -19643 common_interrupt (<b7a31ed5>) >> |func -19643 __ipipe_stall_root (resume_userspace) >> func -19642 __ipipe_unstall_iret_root (restore_raw) >> |begin -19641 __ipipe_unstall_iret_root (restore_raw) >> |end -19640 __ipipe_unstall_iret_root (restore_raw) >>> |begin 0+ common_interrupt (<080c4fce>) Here we start our critical region. The interesting thing is that there are almost 20 ms(!) between the last kernel activity and the interrupt entry. Likely a sign for hardware-related IRQ delays (unless some privileged user-space program does dirty dancing with cli, i.e. hard IRQ blocking). >> :|func 1 __ipipe_handle_irq (common_interrupt) >> :|func 1 __ipipe_ack_common_irq (__ipipe_handle_irq) >> :|func 2 ipipe_test_and_stall_pipeline_from (__ipipe_ack_common_irq) >> :|func 3+ mask_and_ack_8259A (__ipipe_ack_common_irq) >> :|func 5 __ipipe_dispatch_wired (__ipipe_handle_irq) >> :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) >> :|func 6 xnintr_irq_handler (xnintr_clock_handler) >> :|func 7 xnpod_announce_tick (xnintr_irq_handler) >> :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) >> :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) >> :|func 10 xnpod_resume_thread (xnthread_periodic_handler) >> :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) >> :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) ... >> :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) That are a lot of overruns. Haven't counted, but it should be one xnthread_periodic_handler per missed 100 us period (20000 / 100 = 200!). [BTW, I think we should handle even this failure scenario without looping. And there is another loop in xnpod_wait_thread_period.] >> :|func 369+ xnpod_schedule (xnintr_irq_handler) >> :|[ 3096] 370+ xnpod_schedule (xnintr_irq_handler) >> :|func 372+ __switch_to (xnpod_schedule) >> :|[21559] 374+ xnpod_schedule (xnpod_suspend_thread) >> :|func 375 __ipipe_restore_pipeline_head (xnpod_wait_thread_period) >> <|end 376 __ipipe_restore_pipeline_head (xnpod_wait_thread_period) >> |begin 377 __ipipe_dispatch_event (__ipipe_syscall_root) >> No final judgement yet, but it looks to me like your hardware doesn't want to play with us. To exclude the possibility that the timer events get programmed wrongly as TSCs are skewed up, you could also try the irqbench test case. All you need is a nullmodem cable and a second PC with RS232 port, see doc/txt/irqbench.txt. And that test can also take back-traces. Jan [-- Attachment #2: OpenPGP digital signature --] [-- Type: application/pgp-signature, Size: 249 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-29 14:20 ` Jan Kiszka @ 2006-07-30 17:36 ` Julien Heyman 2006-07-30 18:03 ` Philippe Gerum 1 sibling, 0 replies; 29+ messages in thread From: Julien Heyman @ 2006-07-30 17:36 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 16542 bytes --] On Saturday 29 July 2006 16:20, Jan Kiszka wrote: > Julien Heyman wrote: > > Hi, > > > > here's a quick follow-up on my issue, thanks for your time ! > > > > Julien Heyman > > > > On Saturday 22 July 2006 19:17, Jan Kiszka wrote: > >> Julien Heyman wrote: > >>> Hi, > >>> > >>> On Thursday 20 July 2006 23:58, Jan Kiszka wrote: > >>>> Julien Heyman wrote: > >>>>> Hi, > >>>>> > >>>>> I am currently trying to evaluate Xenomai, and my current setup is : > >>>>> VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. > >>>>> I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. > >>>> > >>>> General advice: especially when starting new, try to pick the latest > >>>> version, at least the latest from the preferred series (here 2.1.2). > >>>> But 2.2 is even better. :) > >>> > >>> OK. Actually started with Xenomai-2.1.0 then switched to 2.1.1 to fix a > >>> kernel build error. But anyway, I will start with a fresh install of > >>> 2.2 as soon as I have figured out the other points :) > >>> > >>>>> When I run the latency part of the testsuite (in a console under > >>>>> KDE), I get > >>>>> results that I cannot understand, so I probably did something wrong > >>>>> (execution trace included below). > >>>>> I get reasonable values during the first seconds, then all of a > >>>>> sudden latencies begin to rise, continuously, to very large values. - > >>>>> I did check that DMA transfer is activated on my HD. > >>>>> - I did select "Enable SMI workaround" + "Globally disable SMI" in > >>>>> the Xenomai > >>>>> options while configuring the kernel. > >>>>> - I have disabled power management at BIOS level and disabled ACPI > >>>>> support and > >>>>> CPU frequency scaling during kernel configuration. > >>>>> - I checked that I don't have anything called "legacy USB" in my > >>>>> BIOS. I do have an "OnChip USB" option enable in the BIOS though. > >>>>> > >>>>> Any advice would be appreciated ! > >>>> > >>>> Maybe it's related to some other weird on-chip hardware. At work we > >>>> run Xenomai only on a head-less VIA C3 box, i.e. without X. No > >>>> problems so far. I would suggest to try stopping X and run the test > >>>> from the text mode. > >>> > >>> This is interesting : indeed when I switch to console mode > >>> (Ctrl+Atl+F1) and run the test, the latency values stay right on track. > >>> If I let the test run, switch to X, and switch back to the original > >>> console, the values have gone wild in the meantime. > >>> So there seems to be a strong link with X. > >>> What does that say about potential causes of my issue ? > >> > >> Don't know. Might be a weird hardware design (wrt bus latencies) - or do > >> you > >> use any binary-only driver for X? > > > > I did not install any specific driver, I probably use the standard > > Trident driver that came with the Kubuntu distribution. > > > >>>> A further tool to analyse such effects in details is the I-pipe > >>>> tracer. It's an additional patch you have to apply to your kernel (see > >>>> http://download.gna.org/adeos/patches/v2.6/i386/tracer). Enable this > >>>> I-pipe option, rebuild your kernel, and start the latency test with > >>>> -f. The test will then capture on every new worst-case delay a > >>>> backtrace to /proc/ipipe/trace/frozen. You may want to play with the > >>>> number of back-trace points or the verbose mode (see > >>>> /proc/ipipe/trace/*) even after the capturing. > >>> > >>> I had already used an adeos patch during my initial kernel-patching > >>> (adeos-ipipe-2.6.17-i386-1.3-07.patch) > >> > >> The tracer is an additional patch on top of I-pipe, see link above. > >> > >>> I tried running the latency test using /usr/xenomai/bin/xeno-load > >>> latency -f but I get this error : > >>> > >>> == Sampling period: 100 us > >>> == Test mode: periodic user-mode task > >>> == All results in microseconds > >>> latency: failed to open benchmark device, code -19 > >>> (modprobe xeno_timerbench?) > >>> > >>> What am I doing wrong ? > >> > >> For < 2.2: check if CONFIG_XENO_DRIVERS_TIMERBENCH is y or m. If it's a > >> module, follow the suggestion latency printed. > >> > >> In 2.2 the required tracing interface was moved to the nucleus, no need > >> for these steps then. > > > > Ok, I installed Xenomai 2.2 from scratch over a freshly extracted kernel > > source tree, used the tracer patch ipipe-tracer-2.6.17-i386-1.3-08.patch, > > rebuilt the kernel and relaunch the test : I still get increasing > > latencies. > > > > I attach a copy of the latency test run, and the associated traces in > > files "max" and "frozen" from /proc/ipipe/trace > > > > I have no clue how to interpret theses traces, is there a > > documentation/user's guide available for the ipipe tracer ? > > Nope, I skipped this "boring" part so far. But I will provide some > explanations below. > > > Regarding Gilles' comments on this topic : > >> Losing too many ticks! > >> TSC cannot be used as a timesource. Â > >> Possible reasons for this are: > >> Â You're running with Speedstep, > >> Â You don't have DMA enabled for your hard disk (see hdparm), > >> Â Incorrect TSC synchronization on an SMP system (see dmesg). > >> Falling back to a sane timesource now. > >> > >> Do you see such message in kernel logs ? > > > > No, I don't get any of these. > > > >> If this is the issue you are having, then you may try passing idle=poll > >> on kernel boot line. Or recompile the kernel selecting a processor that > >> has no tsc (for example 486), xenomai will then use the 8254 counter to > >> emulate the tsc. > > > > I tried to rebuild with CPU=486, but it gives the same result. > > > >> Jan > >> > >> ------------------------------------------------------------------------ > >> > >> bids@domain.hid$ sudo > >> /usr/xenomai/bin/xeno-load latency -f Password: > >> * > >> * > >> * Type ^C to stop this application. > >> * > >> * > >> == Sampling period: 100 us > >> == Test mode: periodic user-mode task > >> == All results in microseconds > >> warming up... > >> RTT| 00:00:01 (periodic user-mode task, 100 us period, priority 99) > >> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat > >> worst RTD| 21.428| 23.956| 38.249| 0| 21.428| > >> 38.249 RTD| 22.419| 24.491| 31.760| 0| > >> 21.428| 38.249 RTD| 21.833| 23.731| 52.247| 0| > >> 21.428| 52.247 RTD| 21.776| 23.733| 45.060| > >> 0| 21.428| 52.247 RTD| 21.467| 24.434| > >> 40.813| 0| 21.428| 52.247 RTD| 21.613| 24.684| > >> 40.517| 0| 21.428| 52.247 RTD| 21.585| > >> 25.503| 51.990| 0| 21.428| 52.247 RTD| 21.212| > >> 25.497| 44.028| 0| 21.212| 52.247 RTD| > >> 21.587| 25.535| 119.516| 1| 21.212| 119.516 RTD| > >> 21.604| 26.543| 225.722| 3| 21.212| 225.722 > >> RTD| 21.958| 26.575| 48.329| 3| 21.212| > >> 225.722 RTD| 22.247| 25.216| 57.580| 3| > >> 21.212| 225.722 RTD| 22.253| 25.017| 53.521| 3| > >> 21.212| 225.722 RTD| 22.376| 24.824| 54.095| > >> 3| 21.212| 225.722 RTD| 22.256| 24.655| > >> 55.816| 3| 21.212| 225.722 RTD| 22.324| 24.682| > >> 48.350| 3| 21.212| 225.722 RTD| 21.454| > >> 24.519| 342.492| 9| 21.212| 342.492 RTD| 21.578| > >> 23.617| 49.107| 9| 21.212| 342.492 RTD| > >> 21.621| 23.611| 38.444| 9| 21.212| 342.492 RTD| > >> 21.625| 23.958| 192.672| 10| 21.212| 342.492 > >> RTD| 21.656| 23.675| 34.820| 10| 21.212| > >> 342.492 RTT| 00:00:22 (periodic user-mode task, 100 us period, > >> priority 99) RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat > >> best|---lat worst RTD| 21.688| 23.626| 36.496| 10| > >> 21.212| 342.492 RTD| 21.527| 23.720| 49.283| > >> 10| 21.212| 342.492 RTD| 21.643| 23.711| 43.028| > >> 10| 21.212| 342.492 > >> ---|------------|------------|------------|--------|-------------------- > >>----- RTS| 21.212| 24.562| 342.492| 10| > >> 00:00:24/00:00:24 > >> > >> > >> cat frozen : > > This is the trace the latency application triggered on the maximum delay > (342.492 us). You should extend the back-trace period to cover at least > the observed latency (say up to -400 us). Try "echo 500 > > /proc/ipipe/trace/back_trace_points" for this. You can furthermore > switch on more verbosity with echo 1 > /proc/ipipe/trace/verbose". Attached is a backtrace with 500 points and verbosity turned on. There is a big time gap at time -799, but I have no clue as to interpret the related traces to figure out where this time is spend. > > >> Freeze: 4770308881064 cycles, Trace Points: 30 (+10) > >> > >> +--------------- Hard IRQs ('|': locked) > >> > >> | +- Delay flag ('+': > 1 us, '!': > 10 us) > >> > >> Type Time Function (Parent) > >> > >> :|func -35 xnpod_schedule (xnintr_irq_handler) > >> :|[ 3096] -34+ xnpod_schedule (xnintr_irq_handler) > > This traces the process (pid) being switched out. > > >> :|func -32+ __switch_to (xnpod_schedule) > >> :|[21768] -30+ xnpod_schedule (xnpod_suspend_thread) > > This pid gets switched in, the latency test (more precisely the sampling > thread). > > >> :|func -28 __ipipe_restore_pipeline_head > >> :| (xnpod_wait_thread_period) end -28+ > >> :| __ipipe_restore_pipeline_head (xnpod_wait_thread_period) begin > >> :| -26 __ipipe_dispatch_event (__ipipe_syscall_root) end -25+ > >> :| __ipipe_dispatch_event (__ipipe_syscall_root) > >> : > >> : func -22 __ipipe_syscall_root (system_call) > > This is roughly the point when the latency test takes its timestamp to > calculate the delay. This syscall here is then issued to convert TSCs > into nanoseconds. > > >> : func -21 __ipipe_dispatch_event (__ipipe_syscall_root) > >> : > >> :|begin -21 __ipipe_dispatch_event (__ipipe_syscall_root) > >> :|end -20 __ipipe_dispatch_event (__ipipe_syscall_root) > >> : > >> : func -19+ hisyscall_event (__ipipe_dispatch_event) > >> : func -18 __rt_timer_tsc2ns (hisyscall_event) > >> : func -17 __copy_from_user_ll (__rt_timer_tsc2ns) > >> : func -16+ rt_timer_tsc2ns (__rt_timer_tsc2ns) > >> : func -15 __copy_to_user_ll (__rt_timer_tsc2ns) > >> : > >> :|begin -14+ __ipipe_dispatch_event (__ipipe_syscall_root) > >> :|end -13+ __ipipe_dispatch_event (__ipipe_syscall_root) > >> : > >> : func -11 __ipipe_syscall_root (system_call) > >> : func -11 __ipipe_dispatch_event (__ipipe_syscall_root) > >> : > >> :|begin -10+ __ipipe_dispatch_event (__ipipe_syscall_root) > >> :|end -9 __ipipe_dispatch_event (__ipipe_syscall_root) > >> : > >> : func -8+ hisyscall_event (__ipipe_dispatch_event) > >> : func -7+ xnshadow_sys_trace (hisyscall_event) > >> : func -5 ipipe_trace_frozen_reset (xnshadow_sys_trace) > >> : func -4 __ipipe_global_path_lock (ipipe_trace_frozen_reset) > >> : > >> :|begin -3+ __ipipe_global_path_lock (ipipe_trace_frozen_reset) > >> :|end 0 __ipipe_global_path_unlock (ipipe_trace_frozen_reset) > >> > >> < freeze 0 xnshadow_sys_trace (hisyscall_event) > > And here we freeze after detecting a new worst-case (also issued as a > syscall). > > >> |begin 1 __ipipe_dispatch_event (__ipipe_syscall_root) > >> |end 1 __ipipe_dispatch_event (__ipipe_syscall_root) > >> > >> func 3 __ipipe_syscall_root (system_call) > >> func 3 __ipipe_dispatch_event (__ipipe_syscall_root) > >> > >> |begin 4 __ipipe_dispatch_event (__ipipe_syscall_root) > >> |end 5 __ipipe_dispatch_event (__ipipe_syscall_root) > >> > >> func 5 hisyscall_event (__ipipe_dispatch_event) > >> func 6 __rt_task_wait_period (hisyscall_event) > >> func 7 rt_task_wait_period (__rt_task_wait_period) > >> func 8 xnpod_wait_thread_period (rt_task_wait_period) > >> > >> > >> cat max : > > This trace captured the maximum time the system spent in IRQs-off context. > > >> Begin: 943575374801 cycles, Trace Points: 218 (-10/+1), Length: 376 us > > And that period took 376 us, a pathological result. It's a bit more than > what latency observed, but that's normal for a short test cycle. > > >> +--------------- Hard IRQs ('|': locked) > >> > >> | +- Delay flag ('+': > 1 us, '!': > 10 us) > >> > >> Type Time Function (Parent) > >> > >> |func -19650 xnpod_schedule (xnpod_suspend_thread) > >> |[21559] -19649 xnpod_schedule (xnpod_suspend_thread) > >> |func -19647 __switch_to (xnpod_schedule) > >> |[ 3096] -19646 xnpod_schedule (xnintr_irq_handler) > >> |func -19644 __ipipe_walk_pipeline (__ipipe_handle_irq) > >> |end -19643 common_interrupt (<b7a31ed5>) > >> |func -19643 __ipipe_stall_root (resume_userspace) > >> > >> func -19642 __ipipe_unstall_iret_root (restore_raw) > >> > >> |begin -19641 __ipipe_unstall_iret_root (restore_raw) > >> |end -19640 __ipipe_unstall_iret_root (restore_raw) > >> | > >>> |begin 0+ common_interrupt (<080c4fce>) > > Here we start our critical region. The interesting thing is that there > are almost 20 ms(!) between the last kernel activity and the interrupt > entry. Likely a sign for hardware-related IRQ delays (unless some > privileged user-space program does dirty dancing with cli, i.e. hard IRQ > blocking). > > >> :|func 1 __ipipe_handle_irq (common_interrupt) > >> :|func 1 __ipipe_ack_common_irq (__ipipe_handle_irq) > >> :|func 2 ipipe_test_and_stall_pipeline_from > >> :| (__ipipe_ack_common_irq) func 3+ mask_and_ack_8259A > >> :| (__ipipe_ack_common_irq) > >> :|func 5 __ipipe_dispatch_wired (__ipipe_handle_irq) > >> :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) > >> :|func 6 xnintr_irq_handler (xnintr_clock_handler) > >> :|func 7 xnpod_announce_tick (xnintr_irq_handler) > >> :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) > >> :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) > >> :|func 10 xnpod_resume_thread (xnthread_periodic_handler) > >> :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) > >> :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > > ... > > >> :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > > That are a lot of overruns. Haven't counted, but it should be one > xnthread_periodic_handler per missed 100 us period (20000 / 100 = 200!). > > [BTW, I think we should handle even this failure scenario without > looping. And there is another loop in xnpod_wait_thread_period.] > > >> :|func 369+ xnpod_schedule (xnintr_irq_handler) > >> :|[ 3096] 370+ xnpod_schedule (xnintr_irq_handler) > >> :|func 372+ __switch_to (xnpod_schedule) > >> :|[21559] 374+ xnpod_schedule (xnpod_suspend_thread) > >> :|func 375 __ipipe_restore_pipeline_head > >> :| (xnpod_wait_thread_period) > >> > >> <|end 376 __ipipe_restore_pipeline_head > >> (xnpod_wait_thread_period) > >> > >> |begin 377 __ipipe_dispatch_event (__ipipe_syscall_root) > > No final judgement yet, but it looks to me like your hardware doesn't > want to play with us. > > To exclude the possibility that the timer events get programmed wrongly > as TSCs are skewed up, you could also try the irqbench test case. All > you need is a nullmodem cable and a second PC with RS232 port, see > doc/txt/irqbench.txt. And that test can also take back-traces. > > Jan Ok, thanks. Unfortunately I don't have another Linux PC on hand right now. I will try this as soon as I can. Julien Heyman [-- Attachment #2: latency_pb_trace500points_acpi_enabled_except_CPU.txt --] [-- Type: text/plain, Size: 49296 bytes --] bids@domain.hid$ sudo /usr/xenomai/bin/xeno-load latency -f * * * Type ^C to stop this application. * * == Sampling period: 100 us == Test mode: periodic user-mode task == All results in microseconds warming up... RTT| 00:00:01 (periodic user-mode task, 100 us period, priority 99) RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst RTD| 13.326| 23.257| 40.380| 0| 13.326| 40.380 RTD| 12.837| 22.680| 324.986| 5| 12.837| 324.986 RTD| 21.047| 23.158| 215.680| 7| 12.837| 324.986 RTD| 21.193| 25.083| 723.495| 15| 12.837| 723.495 RTD| 21.527| 24.250| 155.760| 16| 12.837| 723.495 RTD| 21.656| 23.979| 250.887| 18| 12.837| 723.495 vRTD| 21.859| 24.115| 226.351| 20| 12.837| 723.495 RTD| 21.604| 23.932| 355.300| 23| 12.837| 723.495 cRTD| 21.709| 24.130| 225.133| 24| 12.837| 723.495 ---|------------|------------|------------|--------|------------------------- RTS| 12.837| 23.842| 723.495| 24| 00:00:10/00:00:10 bids@domain.hid$ cat /proc/ipipe/trace/frozen I-pipe frozen back-tracing service on 2.6.17.4GEXenomai/ipipe-1.3-07 ------------------------------------------------------------ Freeze: 562608224481 cycles, Trace Points: 500 (+10) +----- Hard IRQs ('|': locked) |+---- <unused> ||+--- Xenomai |||+-- IShield ||||+- Linux ('*': domain stalled, '+': current, '#': current+stalled) ||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us) ||||| | +- NMI noise ('N') ||||| | | Type User Val. Time Delay Function (Parent) :| # [ 3718] -<?>- 99 -1609+ 1.280 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # func -1608+ 1.580 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3201] Xorg -1 -1606+ 1.870 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| +func -1604 0.797 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| +end 0xffffff00 -1603 0.720 common_interrupt+0x34 (memcpy_toiovec+0x1) :| +func -1603 0.880 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| +end 0x8000000d -1602 0.822 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) : +func -1601 0.689 memcpy_toiovec+0xb (unix_stream_recvmsg+0x15e) : +func -1600 0.994 copy_to_user+0xa (memcpy_toiovec+0x46) : +func -1599! 51.588 __copy_to_user_ll+0xa (copy_to_user+0x36) :| +begin 0xffffff00 -1548+ 1.767 common_interrupt+0x21 (__copy_to_user_ll+0x46) :| +func -1546 0.906 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| +func -1545 0.595 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| +func -1544 0.792 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -1544+ 2.114 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| +func -1542 0.659 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -1541 0.588 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -1540 0.676 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -1540 0.694 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -1539 0.775 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -1538 0.906 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -1537 0.870 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # [ 3718] -<?>- 99 -1536+ 4.185 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # func -1532 0.666 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # [ 3201] Xorg -1 -1532+ 1.368 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # func -1530+ 2.258 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3718] -<?>- 99 -1528+ 1.054 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # func -1527 0.861 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # func -1526 0.662 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + end 0x80000000 -1525+ 1.204 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + begin 0x80000001 -1524 0.889 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1523+ 1.567 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -1522 0.653 __ipipe_syscall_root+0xa (system_call+0x20) : + func -1521 0.880 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -1520 0.964 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1519 0.885 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -1518 0.769 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -1517+ 1.067 __rt_task_wait_period+0xb (hisyscall_event+0x19e) : + func -1516+ 1.104 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) : + func -1515 0.816 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) :| + begin 0x80000001 -1515 0.870 xnpod_wait_thread_period+0x133 (rt_task_wait_period+0x3f) :| # func -1514+ 1.949 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0x56) :| # func -1512+ 1.029 xnpod_suspend_thread+0xc (xnpod_wait_thread_period+0x86) :| # func -1511 0.803 xnpod_schedule+0xe (xnpod_suspend_thread+0x16b) :| # [ 3718] -<?>- 99 -1510+ 1.295 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # func -1509+ 1.432 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3201] Xorg -1 -1507+ 1.456 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| +func -1506 0.940 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| +end 0xffffff00 -1505 0.692 common_interrupt+0x34 (__copy_to_user_ll+0x46) :| +func -1504 0.882 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| +end 0x8000000d -1503! 17.353 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) : +func -1486 0.676 skb_queue_head+0xa (unix_stream_recvmsg+0x23b) : +func -1485+ 1.299 __ipipe_test_and_stall_root+0x8 (skb_queue_head+0x15) : #func -1484+ 1.552 __ipipe_restore_root+0x8 (skb_queue_head+0x48) : #func -1482+ 1.052 __ipipe_unstall_root+0x8 (__ipipe_restore_root+0x18) :| #begin 0x80000000 -1481+ 1.264 __ipipe_unstall_root+0x5b (__ipipe_restore_root+0x18) :| +end 0x80000000 -1480+ 1.352 __ipipe_unstall_root+0x3a (__ipipe_restore_root+0x18) : +func -1479+ 2.376 mutex_unlock+0x8 (unix_stream_recvmsg+0x245) : +func -1476+ 3.936 dnotify_parent+0xa (vfs_read+0xd0) : +func -1472+ 1.777 inotify_dentry_parent_queue_event+0xa (vfs_read+0xf0) : +func -1471+ 3.067 inotify_inode_queue_event+0xe (vfs_read+0xfe) : +func -1467 0.917 __ipipe_stall_root+0x8 (syscall_exit+0x5) : #func -1467 0.906 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| #begin 0x80000000 -1466+ 1.220 __ipipe_unstall_iret_root+0x6f (restore_raw+0x0) :| +end 0x8000000d -1464! 16.292 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) :| +begin 0xffffff00 -1448+ 1.043 common_interrupt+0x21 (<b7954ed1>) :| +func -1447 0.857 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| +func -1446 0.604 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| +func -1446 0.674 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -1445+ 2.305 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| +func -1443 0.994 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -1442 0.722 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -1441 0.586 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -1440+ 1.162 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -1439 0.818 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -1438 0.687 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -1438 0.719 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # [ 3718] -<?>- 99 -1437+ 4.086 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # func -1433 0.958 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # [ 3201] Xorg -1 -1432+ 1.831 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # func -1430+ 2.089 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3718] -<?>- 99 -1428+ 1.310 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # func -1427 0.985 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # func -1426 0.820 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + end 0x80000000 -1425 0.981 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + begin 0x80000001 -1424+ 1.310 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1423+ 1.794 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -1421 0.775 __ipipe_syscall_root+0xa (system_call+0x20) : + func -1420 0.619 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -1419+ 1.050 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1418 0.685 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -1418 0.807 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -1417 0.638 __rt_task_wait_period+0xb (hisyscall_event+0x19e) : + func -1416+ 1.065 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) : + func -1415 0.629 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) :| + begin 0x80000001 -1414 0.868 xnpod_wait_thread_period+0x133 (rt_task_wait_period+0x3f) :| # func -1414 0.792 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0x56) :| # func -1413 0.867 xnpod_suspend_thread+0xc (xnpod_wait_thread_period+0x86) :| # func -1412 0.820 xnpod_schedule+0xe (xnpod_suspend_thread+0x16b) :| # [ 3718] -<?>- 99 -1411+ 1.423 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # func -1410+ 1.335 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3201] Xorg -1 -1408+ 1.878 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| +func -1407+ 1.294 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| +end 0xffffff00 -1405 0.672 common_interrupt+0x34 (<b7954ed1>) :| +func -1405 0.709 __ipipe_stall_root+0x8 (resume_userspace+0x5) : #func -1404+ 1.172 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| #begin 0x80000000 -1403+ 1.183 __ipipe_unstall_iret_root+0x6f (restore_raw+0x0) :| +end 0x8000000d -1401! 54.043 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) :| +begin 0xffffff00 -1347 0.840 common_interrupt+0x21 (<b79a709f>) :| +func -1347+ 1.230 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| +func -1345 0.722 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| +func -1345+ 1.361 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -1343+ 1.953 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| +func -1341 0.904 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -1340+ 1.026 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -1339+ 1.086 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -1338 0.677 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -1338 0.837 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -1337 0.642 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -1336 0.646 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # [ 3718] -<?>- 99 -1336+ 3.730 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # func -1332 0.857 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # [ 3201] Xorg -1 -1331+ 1.456 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # func -1329+ 3.219 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3718] -<?>- 99 -1326 1.000 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # func -1325+ 1.529 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # func -1324 0.750 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + end 0x80000000 -1323+ 1.001 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + begin 0x80000001 -1322 0.880 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1321+ 1.735 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -1319 0.724 __ipipe_syscall_root+0xa (system_call+0x20) : + func -1319 0.814 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -1318 0.882 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1317 0.795 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -1316 0.840 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -1315 0.825 __rt_task_wait_period+0xb (hisyscall_event+0x19e) : + func -1314 0.616 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) : + func -1314 0.846 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) :| + begin 0x80000001 -1313 0.941 xnpod_wait_thread_period+0x133 (rt_task_wait_period+0x3f) :| # func -1312 0.818 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0x56) :| # func -1311 0.747 xnpod_suspend_thread+0xc (xnpod_wait_thread_period+0x86) :| # func -1310+ 1.039 xnpod_schedule+0xe (xnpod_suspend_thread+0x16b) :| # [ 3718] -<?>- 99 -1309+ 1.365 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # func -1308+ 1.333 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3201] Xorg -1 -1307+ 1.494 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| +func -1305 0.872 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| +end 0xffffff00 -1304 0.735 common_interrupt+0x34 (<b79a709f>) :| +func -1304 0.790 __ipipe_stall_root+0x8 (resume_userspace+0x5) : #func -1303 0.662 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| #begin 0x80000000 -1302+ 1.013 __ipipe_unstall_iret_root+0x6f (restore_raw+0x0) :| +end 0x8000000d -1301! 53.312 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) :| +begin 0xffffff00 -1248+ 1.071 common_interrupt+0x21 (<0806ff70>) :| +func -1247 0.724 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| +func -1246 0.975 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| +func -1245 0.838 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -1244+ 2.050 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| +func -1242 0.670 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -1242 0.726 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -1241 0.704 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -1240 0.923 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -1239 0.720 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -1238 0.928 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -1238 0.777 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # [ 3718] -<?>- 99 -1237+ 1.380 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # func -1235 0.771 ipipe_trigger_irq+0xe (xntimer_do_tick_aperiodic+0x1c7) :| # func -1235+ 1.423 __ipipe_handle_irq+0xe (ipipe_trigger_irq+0x50) :| # func -1233+ 1.121 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -1232 0.840 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # [ 3201] Xorg -1 -1231+ 1.419 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # func -1230+ 2.312 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3718] -<?>- 99 -1227 0.986 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # func -1226 0.719 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # func -1226 0.689 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + func -1225+ 1.340 __ipipe_sync_stage+0xe (__ipipe_restore_pipeline_head+0x94) :| # func -1224 0.850 xnintr_clock_handler+0x8 (__ipipe_sync_stage+0xd8) :| # func -1223 0.820 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -1222 0.762 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -1221+ 3.831 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -1217 0.908 rthal_irq_host_pend+0x8 (xnintr_irq_handler+0x75) :| # func -1217+ 1.129 __ipipe_schedule_irq+0xc (rthal_irq_host_pend+0x18) :| + end 0x80000000 -1215+ 1.455 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + begin 0x80000001 -1214+ 1.054 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1213+ 1.668 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -1211 0.728 __ipipe_syscall_root+0xa (system_call+0x20) : + func -1211 0.619 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -1210+ 1.144 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1209+ 1.016 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -1208 0.979 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -1207 0.619 __rt_task_wait_period+0xb (hisyscall_event+0x19e) : + func -1206+ 1.631 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) : + func -1205 0.734 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) :| + begin 0x80000001 -1204+ 1.078 xnpod_wait_thread_period+0x133 (rt_task_wait_period+0x3f) :| # func -1203 0.807 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0x56) :| # func -1202+ 1.116 xnpod_suspend_thread+0xc (xnpod_wait_thread_period+0x86) :| # func -1201 0.908 xnpod_schedule+0xe (xnpod_suspend_thread+0x16b) :| # [ 3718] -<?>- 99 -1200+ 1.453 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # func -1198+ 1.327 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3201] Xorg -1 -1197+ 1.653 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| +func -1195 0.779 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| + func -1195+ 1.125 ipipe_suspend_domain+0xc (__ipipe_walk_pipeline+0x85) :| + func -1194+ 1.159 __ipipe_sync_stage+0xe (ipipe_suspend_domain+0x58) :| # end 0x80000000 -1192 0.889 __ipipe_sync_stage+0x100 (ipipe_suspend_domain+0x58) : # func -1191 0.754 shield_handler+0x8 (__ipipe_sync_stage+0xd8) : # func -1191 0.820 __ipipe_schedule_irq+0xc (shield_handler+0x18) :| # begin 0x80000001 -1190+ 1.035 __ipipe_schedule_irq+0xfb (shield_handler+0x18) :| # end 0x80000001 -1189 0.900 __ipipe_schedule_irq+0x12c (shield_handler+0x18) :| # begin 0x80000000 -1188+ 1.123 __ipipe_sync_stage+0x14b (ipipe_suspend_domain+0x58) :| +func -1187+ 1.127 __ipipe_sync_stage+0xe (ipipe_suspend_domain+0x58) :| #end 0x80000000 -1186 0.810 __ipipe_sync_stage+0x100 (ipipe_suspend_domain+0x58) : #func -1185 0.936 do_IRQ+0x8 (__ipipe_sync_stage+0x135) : #func -1184+ 1.602 __do_IRQ+0xd (do_IRQ+0x22) : #func -1182+ 1.219 handle_IRQ_event+0xd (__do_IRQ+0x9b) : #func -1181 0.717 timer_interrupt+0x9 (handle_IRQ_event+0x44) : #func -1180+ 1.694 mark_offset_pmtmr+0xc (timer_interrupt+0x2c) : #func -1179+ 1.039 do_timer+0xb (timer_interrupt+0x32) : #func -1178+ 1.151 adjtime_adjustment+0x8 (do_timer+0x3d) : #func -1177 0.582 update_process_times+0xa (timer_interrupt+0x50) : #func -1176+ 1.074 account_user_time+0x8 (update_process_times+0x22) : #func -1175+ 1.411 run_local_timers+0x8 (update_process_times+0x29) : #func -1173 0.767 raise_softirq+0xa (run_local_timers+0x12) : #func -1173 0.631 __ipipe_test_and_stall_root+0x8 (raise_softirq+0x11) : #func -1172 1.000 __ipipe_restore_root+0x8 (raise_softirq+0x5e) : #func -1171 0.810 __ipipe_stall_root+0x8 (__ipipe_restore_root+0x11) : #func -1170 0.805 softlockup_tick+0x9 (run_local_timers+0x17) : #func -1169 0.584 rcu_pending+0x8 (update_process_times+0x30) : #func -1169 0.857 __rcu_pending+0x8 (rcu_pending+0x17) : #func -1168+ 1.329 __rcu_pending+0x8 (rcu_pending+0x35) : #func -1167+ 1.252 scheduler_tick+0xe (update_process_times+0x44) : #func -1165+ 1.934 sched_clock+0xd (scheduler_tick+0x1f) : #func -1164+ 1.904 task_timeslice+0x8 (scheduler_tick+0x251) : #func -1162+ 1.282 run_posix_cpu_timers+0xe (update_process_times+0x4a) : #func -1160 0.891 __ipipe_test_root+0x8 (run_posix_cpu_timers+0x1c) : #func -1159 0.749 profile_tick+0xa (timer_interrupt+0x58) : #func -1159 0.852 __ipipe_stall_root+0x8 (handle_IRQ_event+0x75) : #func -1158+ 1.146 note_interrupt+0xe (__do_IRQ+0xfe) : #func -1157 0.756 end_8259A_irq+0x8 (__do_IRQ+0xca) : #func -1156 0.657 enable_8259A_irq+0xc (end_8259A_irq+0x1e) :| #begin 0x80000001 -1155+ 2.232 enable_8259A_irq+0xcb (end_8259A_irq+0x1e) :| #end 0x80000001 -1153 0.930 enable_8259A_irq+0x83 (end_8259A_irq+0x1e) : #func -1152 0.722 irq_exit+0x8 (do_IRQ+0x27) : #func -1151 0.640 do_softirq+0x9 (irq_exit+0x55) : #func -1151+ 1.099 __ipipe_test_and_stall_root+0x8 (do_softirq+0x25) : #func -1150+ 1.252 __do_softirq+0xb (do_softirq+0x4a) :| #begin 0xffffff00 -1148 0.921 common_interrupt+0x21 (__ipipe_trace+0x246) :| #func -1147 0.788 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| #func -1147+ 1.475 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| #func -1145 0.960 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -1144+ 2.445 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| #func -1142 0.676 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # *func -1141+ 1.095 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # *func -1140+ 2.513 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # *func -1138 0.822 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # *func -1137 0.827 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # *func -1136 0.780 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # *func -1135 0.979 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # *[ 3718] -<?>- 99 -1134+ 3.810 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # *func -1130 0.758 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # *[ 3201] Xorg -1 -1130+ 1.614 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # *func -1128+ 2.271 __switch_to+0xc (xnpod_schedule+0x597) :| # *[ 3718] -<?>- 99 -1126+ 1.061 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # *func -1125 0.771 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # *func -1124+ 1.014 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + *end 0x80000000 -1123+ 1.252 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + *begin 0x80000001 -1122 0.971 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + *end 0x80000001 -1121+ 1.629 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + *func -1119 0.852 __ipipe_syscall_root+0xa (system_call+0x20) : + *func -1118 0.822 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + *begin 0x80000001 -1117 0.898 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + *end 0x80000001 -1116 0.696 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + *func -1116+ 1.174 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + *func -1115 0.844 __rt_task_wait_period+0xb (hisyscall_event+0x19e) : + *func -1114 0.775 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) : + *func -1113 0.649 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) :| + *begin 0x80000001 -1112+ 1.234 xnpod_wait_thread_period+0x133 (rt_task_wait_period+0x3f) :| # *func -1111+ 1.181 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0x56) :| # *func -1110 0.921 xnpod_suspend_thread+0xc (xnpod_wait_thread_period+0x86) :| # *func -1109 0.737 xnpod_schedule+0xe (xnpod_suspend_thread+0x16b) :| # *[ 3718] -<?>- 99 -1108+ 1.805 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # *func -1106+ 1.707 __switch_to+0xc (xnpod_schedule+0x597) :| # *[ 3201] Xorg -1 -1105+ 1.528 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| #func -1103 0.876 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| #end 0xffffff00 -1102 0.975 common_interrupt+0x34 (__ipipe_trace+0x246) : #func -1101 0.741 __ipipe_unstall_root+0x8 (__do_softirq+0x3f) :| #begin 0x80000000 -1101+ 1.016 __ipipe_unstall_root+0x5b (__do_softirq+0x3f) :| +end 0x80000000 -1100 0.735 __ipipe_unstall_root+0x3a (__do_softirq+0x3f) : +func -1099+ 1.061 run_timer_softirq+0xe (__do_softirq+0x55) : +func -1098+ 1.367 hrtimer_run_queues+0xe (run_timer_softirq+0x1b) : +func -1096 0.732 __ipipe_stall_root+0x8 (hrtimer_run_queues+0xc5) : #func -1096 0.642 __ipipe_unstall_root+0x8 (hrtimer_run_queues+0xf8) :| #begin 0x80000000 -1095+ 1.245 __ipipe_unstall_root+0x5b (hrtimer_run_queues+0xf8) :| +end 0x80000000 -1094 0.844 __ipipe_unstall_root+0x3a (hrtimer_run_queues+0xf8) : +func -1093 0.932 __ipipe_stall_root+0x8 (run_timer_softirq+0x31) : #func -1092 0.589 __ipipe_unstall_root+0x8 (run_timer_softirq+0x191) :| #begin 0x80000000 -1091+ 1.026 __ipipe_unstall_root+0x5b (run_timer_softirq+0x191) :| +end 0x80000000 -1090+ 1.196 __ipipe_unstall_root+0x3a (run_timer_softirq+0x191) : +func -1089 0.867 __ipipe_stall_root+0x8 (__do_softirq+0x6c) : #func -1088 0.662 __ipipe_restore_root+0x8 (do_softirq+0x42) : #func -1088 0.960 __ipipe_stall_root+0x8 (__ipipe_restore_root+0x11) :| #func -1087 0.889 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| +end 0x8000000d -1086 0.844 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) :| +begin 0x80000000 -1085+ 1.243 __ipipe_sync_stage+0x14b (ipipe_suspend_domain+0x58) :| +end 0xffffff00 -1084+ 1.179 common_interrupt+0x34 (<0806ff70>) :| +func -1082+ 1.056 __ipipe_stall_root+0x8 (resume_userspace+0x5) : #func -1081 0.960 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| #begin 0x80000000 -1080 0.921 __ipipe_unstall_iret_root+0x6f (restore_raw+0x0) :| +end 0x8000000d -1080! 31.586 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) :| +begin 0xffffff00 -1048+ 3.477 common_interrupt+0x21 (<b79522ee>) :| +func -1044 0.908 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| +func -1044 0.593 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| +func -1043 0.900 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -1042+ 2.035 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| +func -1040 0.662 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -1039 0.617 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -1039 0.745 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -1038 0.876 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -1037+ 1.073 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -1036 0.631 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -1035+ 1.028 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # [ 3718] -<?>- 99 -1034+ 3.788 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # func -1031 0.794 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # [ 3201] Xorg -1 -1030+ 1.404 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # func -1028+ 2.387 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3718] -<?>- 99 -1026+ 1.488 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # func -1025 0.754 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # func -1024 0.717 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + end 0x80000000 -1023+ 1.132 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + begin 0x80000001 -1022 0.971 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1021+ 1.647 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -1019 0.670 __ipipe_syscall_root+0xa (system_call+0x20) : + func -1019+ 1.415 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -1017 0.977 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -1016 0.752 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -1016 0.769 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -1015+ 1.097 __rt_task_wait_period+0xb (hisyscall_event+0x19e) : + func -1014 0.872 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) : + func -1013 0.756 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) :| + begin 0x80000001 -1012 0.867 xnpod_wait_thread_period+0x133 (rt_task_wait_period+0x3f) :| # func -1011+ 1.211 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0x56) :| # func -1010 0.970 xnpod_suspend_thread+0xc (xnpod_wait_thread_period+0x86) :| # func -1009 0.720 xnpod_schedule+0xe (xnpod_suspend_thread+0x16b) :| # [ 3718] -<?>- 99 -1008+ 1.277 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # func -1007+ 1.651 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3201] Xorg -1 -1005+ 1.807 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| +func -1004+ 1.035 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| +end 0xffffff00 -1002 0.638 common_interrupt+0x34 (<b79522ee>) :| +func -1002+ 1.146 __ipipe_stall_root+0x8 (resume_userspace+0x5) : #func -1001+ 1.649 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| #begin 0x80000000 -999+ 1.014 __ipipe_unstall_iret_root+0x6f (restore_raw+0x0) :| +end 0x8000000d -998! 49.636 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) :| +begin 0xffffff00 -948+ 1.013 common_interrupt+0x21 (<b795413b>) :| +func -947 0.782 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| +func -947 0.606 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| +func -946 0.691 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -945+ 2.102 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| +func -943 0.741 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -942 0.672 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -942 0.586 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -941+ 1.043 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -940 0.788 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -939 0.614 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -939 0.664 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # [ 3718] -<?>- 99 -938+ 3.966 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # func -934 0.825 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # [ 3201] Xorg -1 -933+ 1.498 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # func -932+ 2.260 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3718] -<?>- 99 -930+ 1.108 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # func -928 0.779 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # func -928 0.842 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + end 0x80000000 -927 0.977 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + begin 0x80000001 -926+ 1.704 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -924+ 1.775 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -922 0.788 __ipipe_syscall_root+0xa (system_call+0x20) : + func -922 0.631 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -921+ 1.086 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -920 0.966 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -919 0.882 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -918 0.634 __rt_task_wait_period+0xb (hisyscall_event+0x19e) : + func -917 0.758 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) : + func -917 0.985 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) :| + begin 0x80000001 -916 0.867 xnpod_wait_thread_period+0x133 (rt_task_wait_period+0x3f) :| # func -915 0.797 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0x56) :| # func -914 0.880 xnpod_suspend_thread+0xc (xnpod_wait_thread_period+0x86) :| # func -913 0.735 xnpod_schedule+0xe (xnpod_suspend_thread+0x16b) :| # [ 3718] -<?>- 99 -912+ 1.543 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # func -911+ 1.327 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3201] Xorg -1 -909+ 1.833 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| +func -908+ 1.162 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| +end 0xffffff00 -906 0.807 common_interrupt+0x34 (<b795413b>) :| +func -906 0.709 __ipipe_stall_root+0x8 (resume_userspace+0x5) : #func -905 0.962 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| #begin 0x80000000 -904+ 1.279 __ipipe_unstall_iret_root+0x6f (restore_raw+0x0) :| +end 0x8000000d -903! 54.747 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) :| +begin 0xffffff00 -848 0.825 common_interrupt+0x21 (<0806f198>) :| +func -847+ 1.198 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| +func -846 0.917 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| +func -845 0.973 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -844+ 2.001 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| +func -842 0.868 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -841+ 1.026 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -840+ 1.460 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -839 0.691 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -838 0.853 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -837 0.612 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -837 0.705 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # [ 3718] -<?>- 99 -836+ 3.852 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # func -832 0.947 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # [ 3201] Xorg -1 -831+ 2.091 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # func -829+ 2.320 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3718] -<?>- 99 -827+ 1.014 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # func -826+ 1.191 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # func -824 0.707 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + end 0x80000000 -824 0.990 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + begin 0x80000001 -823 0.945 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -822+ 1.852 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -820 0.749 __ipipe_syscall_root+0xa (system_call+0x20) : + func -819 0.822 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -818 0.880 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -817 0.797 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -817 0.780 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -816 0.698 __rt_task_wait_period+0xb (hisyscall_event+0x19e) : + func -815 0.616 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) : + func -815 0.853 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) :| + begin 0x80000001 -814 0.996 xnpod_wait_thread_period+0x133 (rt_task_wait_period+0x3f) :| # func -813 0.846 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0x56) :| # func -812 0.747 xnpod_suspend_thread+0xc (xnpod_wait_thread_period+0x86) :| # func -811+ 2.380 xnpod_schedule+0xe (xnpod_suspend_thread+0x16b) :| # [ 3718] -<?>- 99 -809+ 1.634 xnpod_schedule+0x8f (xnpod_suspend_thread+0x16b) :| # func -807+ 1.466 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3201] Xorg -1 -806+ 1.462 xnpod_schedule+0x5e3 (xnintr_irq_handler+0xa5) :| +func -804+ 1.370 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| +end 0xffffff00 -803 0.735 common_interrupt+0x34 (<0806f198>) :| +func -802 0.910 __ipipe_stall_root+0x8 (resume_userspace+0x5) : #func -801 0.685 __ipipe_unstall_iret_root+0x9 (restore_raw+0x0) :| #begin 0x80000000 -800+ 1.314 __ipipe_unstall_iret_root+0x6f (restore_raw+0x0) :| +end 0x8000000d -799! 727.050 __ipipe_unstall_iret_root+0x2c (restore_raw+0x0) :| +begin 0xffffff00 -72 0.848 common_interrupt+0x21 (<b7966c54>) :| +func -71 0.735 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| +func -71 0.683 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| +func -70 0.734 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| #func -69+ 2.037 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x8a) :| +func -67 0.670 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -66 0.799 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -66 0.679 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -65 0.685 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -64 0.735 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -64 0.698 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -63 0.670 xnpod_resume_thread+0xc (xnthread_periodic_handler+0x1e) :| # [ 3718] -<?>- 99 -62+ 1.114 xnpod_resume_thread+0x50 (xnthread_periodic_handler+0x1e) :| # func -61 0.938 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -60+ 1.009 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -59 0.895 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -58+ 1.417 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -57+ 1.209 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -56+ 3.715 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -52 0.801 xnpod_schedule+0xe (xnintr_irq_handler+0xa5) :| # [ 3201] Xorg -1 -51+ 1.486 xnpod_schedule+0x8f (xnintr_irq_handler+0xa5) :| # func -50+ 2.131 __switch_to+0xc (xnpod_schedule+0x597) :| # [ 3718] -<?>- 99 -47+ 1.084 xnpod_schedule+0x5e3 (xnpod_suspend_thread+0x16b) :| # func -46 0.932 xntimer_get_raw_clock_aperiodic+0x8 (xnpod_wait_thread_period+0xa2) :| # func -45 0.823 __ipipe_restore_pipeline_head+0xa (xnpod_wait_thread_period+0x11e) :| + end 0x80000000 -45+ 1.205 __ipipe_restore_pipeline_head+0x6d (xnpod_wait_thread_period+0x11e) :| + begin 0xffffff00 -43+ 1.001 common_interrupt+0x21 (__ipipe_restore_pipeline_head+0x6f) :| + func -42+ 1.131 __ipipe_handle_irq+0xe (common_interrupt+0x29) :| + func -41 0.569 __ipipe_ack_common_irq+0xb (__ipipe_handle_irq+0x1ea) :| + func -41 0.704 ipipe_test_and_stall_pipeline_from+0x9 (__ipipe_ack_common_irq+0x18) :| # func -40+ 1.981 mask_and_ack_8259A+0xc (__ipipe_ack_common_irq+0x36) :| + func -38 0.713 __ipipe_dispatch_wired+0xb (__ipipe_handle_irq+0x18a) :| # func -37 0.644 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0xa0) :| # func -37 0.797 xnintr_irq_handler+0xb (xnintr_clock_handler+0x18) :| # func -36+ 1.013 xnpod_announce_tick+0xb (xnintr_irq_handler+0x2a) :| # func -35 0.816 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xa1) :| # func -34+ 3.535 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x1f0) :| # func -30 0.580 rthal_irq_host_pend+0x8 (xnintr_irq_handler+0x75) :| # func -30+ 1.204 __ipipe_schedule_irq+0xc (rthal_irq_host_pend+0x18) :| + func -29 0.646 __ipipe_walk_pipeline+0xb (__ipipe_handle_irq+0x108) :| + end 0xffffff00 -28+ 1.243 common_interrupt+0x34 (__ipipe_restore_pipeline_head+0x6f) :| + begin 0x80000001 -27 0.971 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -26+ 3.011 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -23 0.702 __ipipe_syscall_root+0xa (system_call+0x20) : + func -22 0.642 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -21 0.880 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -21 0.775 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -20+ 1.513 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -18 0.792 __rt_timer_tsc2ns+0xc (hisyscall_event+0x19e) : + func -17+ 1.498 __copy_from_user_ll+0xa (__rt_timer_tsc2ns+0x1e) : + func -16+ 1.468 rt_timer_tsc2ns+0xe (__rt_timer_tsc2ns+0x2b) : + func -15 0.923 __copy_to_user_ll+0xa (__rt_timer_tsc2ns+0x3f) :| + begin 0x80000001 -14 0.923 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -13+ 1.264 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) : + func -11 0.698 __ipipe_syscall_root+0xa (system_call+0x20) : + func -11 0.627 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) :| + begin 0x80000001 -10 0.876 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) :| + end 0x80000001 -9 0.655 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) : + func -9+ 1.470 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) : + func -7+ 1.853 xnshadow_sys_trace+0xb (hisyscall_event+0x19e) : + func -5 0.619 ipipe_trace_frozen_reset+0xa (xnshadow_sys_trace+0xd7) : + func -5 0.629 __ipipe_global_path_lock+0x9 (ipipe_trace_frozen_reset+0xf) :| + begin 0x80000001 -4+ 3.421 __ipipe_global_path_lock+0x4c (ipipe_trace_frozen_reset+0xf) :| + end 0x80000001 -1+ 1.065 __ipipe_global_path_unlock+0x52 (ipipe_trace_frozen_reset+0x63) < + freeze 0x000b0a27 0 0.906 xnshadow_sys_trace+0xa1 (hisyscall_event+0x19e) | + begin 0x80000001 0 0.689 __ipipe_dispatch_event+0x131 (__ipipe_syscall_root+0x32) | + end 0x80000001 1 1.488 __ipipe_dispatch_event+0x10e (__ipipe_syscall_root+0x32) + func 3 0.713 __ipipe_syscall_root+0xa (system_call+0x20) + func 3 1.146 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x32) | + begin 0x80000001 4 0.700 __ipipe_dispatch_event+0x152 (__ipipe_syscall_root+0x32) | + end 0x80000001 5 0.814 __ipipe_dispatch_event+0x141 (__ipipe_syscall_root+0x32) + func 6 0.831 hisyscall_event+0xe (__ipipe_dispatch_event+0x86) + func 7 0.668 __rt_task_wait_period+0xb (hisyscall_event+0x19e) + func 7 0.616 rt_task_wait_period+0x8 (__rt_task_wait_period+0x1d) + func 8 0.000 xnpod_wait_thread_period+0xe (rt_task_wait_period+0x3f) bids@domain.hid$ ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-29 14:20 ` Jan Kiszka 2006-07-30 17:36 ` Julien Heyman @ 2006-07-30 18:03 ` Philippe Gerum 2006-07-30 19:33 ` Jan Kiszka 1 sibling, 1 reply; 29+ messages in thread From: Philippe Gerum @ 2006-07-30 18:03 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai On Sat, 2006-07-29 at 16:20 +0200, Jan Kiszka wrote: > >> :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) > >> :|func 6 xnintr_irq_handler (xnintr_clock_handler) > >> :|func 7 xnpod_announce_tick (xnintr_irq_handler) > >> :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) > >> :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) > >> :|func 10 xnpod_resume_thread (xnthread_periodic_handler) > >> :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) > >> :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > > ... > > >> :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > > That are a lot of overruns. Haven't counted, but it should be one > xnthread_periodic_handler per missed 100 us period (20000 / 100 = 200!). > [BTW, I think we should handle even this failure scenario without > looping. We need to loop in the aperiodic handler in order to catch timers that could have elapsed while processing the current tick. However, xnpod_wait_thread_period() - over which rt_task_wait_period() is based - does not loop, but rather computes the actual count of overruns by substracting the current time from the deadline. Which brings us an interesting question: why does the aperiodic handler loop frenetically in the first place? I would be pretty interested in checking the TSC values returned by xnarch_get_cpu_tsc() while spinning inside this deadly loop... > And there is another loop in xnpod_wait_thread_period.] > >> :|func 369+ xnpod_schedule (xnintr_irq_handler) > >> :|[ 3096] 370+ xnpod_schedule (xnintr_irq_handler) > >> :|func 372+ __switch_to (xnpod_schedule) > >> :|[21559] 374+ xnpod_schedule (xnpod_suspend_thread) > >> :|func 375 __ipipe_restore_pipeline_head (xnpod_wait_thread_period) > >> <|end 376 __ipipe_restore_pipeline_head (xnpod_wait_thread_period) > >> |begin 377 __ipipe_dispatch_event (__ipipe_syscall_root) > >> > > No final judgement yet, but it looks to me like your hardware doesn't > want to play with us. > > To exclude the possibility that the timer events get programmed wrongly > as TSCs are skewed up, you could also try the irqbench test case. All > you need is a nullmodem cable and a second PC with RS232 port, see > doc/txt/irqbench.txt. And that test can also take back-traces. > > Jan > > _______________________________________________ > Xenomai-help mailing list > Xenomai-help@domain.hid > https://mail.gna.org/listinfo/xenomai-help -- Philippe. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 18:03 ` Philippe Gerum @ 2006-07-30 19:33 ` Jan Kiszka 2006-07-30 20:03 ` Gilles Chanteperdrix 2006-07-30 21:23 ` Philippe Gerum 0 siblings, 2 replies; 29+ messages in thread From: Jan Kiszka @ 2006-07-30 19:33 UTC (permalink / raw) To: rpm; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 2352 bytes --] Philippe Gerum wrote: > On Sat, 2006-07-29 at 16:20 +0200, Jan Kiszka wrote: >>>> :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) >>>> :|func 6 xnintr_irq_handler (xnintr_clock_handler) >>>> :|func 7 xnpod_announce_tick (xnintr_irq_handler) >>>> :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) >>>> :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) >>>> :|func 10 xnpod_resume_thread (xnthread_periodic_handler) >>>> :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) >>>> :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) >> ... >> >>>> :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) >> That are a lot of overruns. Haven't counted, but it should be one >> xnthread_periodic_handler per missed 100 us period (20000 / 100 = 200!). >> [BTW, I think we should handle even this failure scenario without >> looping. > > We need to loop in the aperiodic handler in order to catch timers that > could have elapsed while processing the current tick. However, No, that was not what I meant. I know that we need the timer loop. But I was thinking of something like this for the tick handler's error path: if (unlikely((timer.date += timer.interval) < now)) timer.date = now + timer.interval - (now - timer.date) % timer.interval; > xnpod_wait_thread_period() - over which rt_task_wait_period() is based - > does not loop, but rather computes the actual count of overruns by > substracting the current time from the deadline. ...but by looping for some scenarios instead of dividing for all. Why optimising the slow path here? > > Which brings us an interesting question: why does the aperiodic handler > loop frenetically in the first place? I would be pretty interested in > checking the TSC values returned by xnarch_get_cpu_tsc() while spinning > inside this deadly loop... You can already read those TSCs: each trace point got recorded with the current TSC value, fresh from the hardware. I rather think, also when looking at Julien's second trace, that we have some issue with X in user-space here, probably in combination with weird VIA hardware stalling IRQ delivery for a "few" microseconds. Let's see if the irqbench gives similar results. Jan [-- Attachment #2: OpenPGP digital signature --] [-- Type: application/pgp-signature, Size: 250 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 19:33 ` Jan Kiszka @ 2006-07-30 20:03 ` Gilles Chanteperdrix 2006-07-30 22:00 ` Jan Kiszka 2006-07-30 21:23 ` Philippe Gerum 1 sibling, 1 reply; 29+ messages in thread From: Gilles Chanteperdrix @ 2006-07-30 20:03 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai Jan Kiszka wrote: > Philippe Gerum wrote: > > On Sat, 2006-07-29 at 16:20 +0200, Jan Kiszka wrote: > >>>> :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) > >>>> :|func 6 xnintr_irq_handler (xnintr_clock_handler) > >>>> :|func 7 xnpod_announce_tick (xnintr_irq_handler) > >>>> :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) > >>>> :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) > >>>> :|func 10 xnpod_resume_thread (xnthread_periodic_handler) > >>>> :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) > >>>> :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > >> ... > >> > >>>> :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > >> That are a lot of overruns. Haven't counted, but it should be one > >> xnthread_periodic_handler per missed 100 us period (20000 / 100 = 200!). > >> [BTW, I think we should handle even this failure scenario without > >> looping. > > > > We need to loop in the aperiodic handler in order to catch timers that > > could have elapsed while processing the current tick. However, > > No, that was not what I meant. I know that we need the timer loop. But I > was thinking of something like this for the tick handler's error path: > > if (unlikely((timer.date += timer.interval) < now)) > timer.date = now + timer.interval - > (now - timer.date) % timer.interval; Actually, while (timer.date < now) timer.date += timer.interval cost much less cycles in the normal/fast case than going through a division... -- Gilles Chanteperdrix. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 20:03 ` Gilles Chanteperdrix @ 2006-07-30 22:00 ` Jan Kiszka 0 siblings, 0 replies; 29+ messages in thread From: Jan Kiszka @ 2006-07-30 22:00 UTC (permalink / raw) To: Gilles Chanteperdrix; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 1951 bytes --] Gilles Chanteperdrix wrote: > Jan Kiszka wrote: > > Philippe Gerum wrote: > > > On Sat, 2006-07-29 at 16:20 +0200, Jan Kiszka wrote: > > >>>> :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) > > >>>> :|func 6 xnintr_irq_handler (xnintr_clock_handler) > > >>>> :|func 7 xnpod_announce_tick (xnintr_irq_handler) > > >>>> :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) > > >>>> :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) > > >>>> :|func 10 xnpod_resume_thread (xnthread_periodic_handler) > > >>>> :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) > > >>>> :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > > >> ... > > >> > > >>>> :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > > >> That are a lot of overruns. Haven't counted, but it should be one > > >> xnthread_periodic_handler per missed 100 us period (20000 / 100 = 200!). > > >> [BTW, I think we should handle even this failure scenario without > > >> looping. > > > > > > We need to loop in the aperiodic handler in order to catch timers that > > > could have elapsed while processing the current tick. However, > > > > No, that was not what I meant. I know that we need the timer loop. But I > > was thinking of something like this for the tick handler's error path: > > > > if (unlikely((timer.date += timer.interval) < now)) > > timer.date = now + timer.interval - > > (now - timer.date) % timer.interval; > > Actually, > > while (timer.date < now) > timer.date += timer.interval > > cost much less cycles in the normal/fast case than going through a > division... > Yeah, most probably the right way for the timer IRQ. If we have to loop here significantly often, then we already had a much too long IRQ-off period and are toasted anyway. Jan [-- Attachment #2: OpenPGP digital signature --] [-- Type: application/pgp-signature, Size: 250 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 19:33 ` Jan Kiszka 2006-07-30 20:03 ` Gilles Chanteperdrix @ 2006-07-30 21:23 ` Philippe Gerum 2006-07-30 22:00 ` Jan Kiszka 2006-07-31 11:39 ` Gilles Chanteperdrix 1 sibling, 2 replies; 29+ messages in thread From: Philippe Gerum @ 2006-07-30 21:23 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai On Sun, 2006-07-30 at 21:33 +0200, Jan Kiszka wrote: > Philippe Gerum wrote: > > On Sat, 2006-07-29 at 16:20 +0200, Jan Kiszka wrote: > >>>> :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) > >>>> :|func 6 xnintr_irq_handler (xnintr_clock_handler) > >>>> :|func 7 xnpod_announce_tick (xnintr_irq_handler) > >>>> :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) > >>>> :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) > >>>> :|func 10 xnpod_resume_thread (xnthread_periodic_handler) > >>>> :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) > >>>> :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > >> ... > >> > >>>> :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) > >> That are a lot of overruns. Haven't counted, but it should be one > >> xnthread_periodic_handler per missed 100 us period (20000 / 100 = 200!). > >> [BTW, I think we should handle even this failure scenario without > >> looping. > > > > We need to loop in the aperiodic handler in order to catch timers that > > could have elapsed while processing the current tick. However, > > No, that was not what I meant. I know that we need the timer loop. But I > was thinking of something like this for the tick handler's error path: > > if (unlikely((timer.date += timer.interval) < now)) > timer.date = now + timer.interval - > (now - timer.date) % timer.interval; > > > xnpod_wait_thread_period() - over which rt_task_wait_period() is based - > > does not loop, but rather computes the actual count of overruns by > > substracting the current time from the deadline. > > ...but by looping for some scenarios instead of dividing for all. Why > optimising the slow path here? Division is utterly expensive and having a jitter that would not fit in 32bit is seldom (and the definitive sign of serious brokenness anyway), so this is actually the fast error path which gets optimized. > > > > > Which brings us an interesting question: why does the aperiodic handler > > loop frenetically in the first place? I would be pretty interested in > > checking the TSC values returned by xnarch_get_cpu_tsc() while spinning > > inside this deadly loop... > > You can already read those TSCs: each trace point got recorded with the > current TSC value, fresh from the hardware. > I'd like to explain why we don't we see any other routines than xnthread_aperiodic_handler called from xntimer_do_tick_aperiodic in the call frame? Even in case of massive jittery (e.g. > 300 us late) in one shot, we should not spin in this code, due to the resync done in xnpod_wait_thread_timeout - assuming we only have a single outstanding timer (+ the host tick, but this should not be an issue). > I rather think, also when looking at Julien's second trace, that we have > some issue with X in user-space here, probably in combination with weird > VIA hardware stalling IRQ delivery for a "few" microseconds. Let's see > if the irqbench gives similar results. > The problem is that I can reproduce X-related jittery (> 2 ms in a row) on one of my test boxen when dragging windows over the screen, without triggering the NMI watchdog set to 100 us (and guess what, the chipset in question is from VIA). > Jan > -- Philippe. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 21:23 ` Philippe Gerum @ 2006-07-30 22:00 ` Jan Kiszka 2006-07-31 9:57 ` Philippe Gerum 2006-07-31 11:39 ` Gilles Chanteperdrix 1 sibling, 1 reply; 29+ messages in thread From: Jan Kiszka @ 2006-07-30 22:00 UTC (permalink / raw) To: rpm; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 3735 bytes --] Philippe Gerum wrote: > On Sun, 2006-07-30 at 21:33 +0200, Jan Kiszka wrote: >> Philippe Gerum wrote: >>> On Sat, 2006-07-29 at 16:20 +0200, Jan Kiszka wrote: >>>>>> :|func 6 xnintr_clock_handler (__ipipe_dispatch_wired) >>>>>> :|func 6 xnintr_irq_handler (xnintr_clock_handler) >>>>>> :|func 7 xnpod_announce_tick (xnintr_irq_handler) >>>>>> :|func 8+ xntimer_do_tick_aperiodic (xnpod_announce_tick) >>>>>> :|func 9 xnthread_periodic_handler (xntimer_do_tick_aperiodic) >>>>>> :|func 10 xnpod_resume_thread (xnthread_periodic_handler) >>>>>> :|[21559] 11+ xnpod_resume_thread (xnthread_periodic_handler) >>>>>> :|func 13+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) >>>> ... >>>> >>>>>> :|func 363+ xnthread_periodic_handler (xntimer_do_tick_aperiodic) >>>> That are a lot of overruns. Haven't counted, but it should be one >>>> xnthread_periodic_handler per missed 100 us period (20000 / 100 = 200!). >>>> [BTW, I think we should handle even this failure scenario without >>>> looping. >>> We need to loop in the aperiodic handler in order to catch timers that >>> could have elapsed while processing the current tick. However, >> No, that was not what I meant. I know that we need the timer loop. But I >> was thinking of something like this for the tick handler's error path: >> >> if (unlikely((timer.date += timer.interval) < now)) >> timer.date = now + timer.interval - >> (now - timer.date) % timer.interval; >> >>> xnpod_wait_thread_period() - over which rt_task_wait_period() is based - >>> does not loop, but rather computes the actual count of overruns by >>> substracting the current time from the deadline. >> ...but by looping for some scenarios instead of dividing for all. Why >> optimising the slow path here? > > Division is utterly expensive and having a jitter that would not fit > in 32bit is seldom (and the definitive sign of serious brokenness anyway), > so this is actually the fast error path which gets optimized. > >>> Which brings us an interesting question: why does the aperiodic handler >>> loop frenetically in the first place? I would be pretty interested in >>> checking the TSC values returned by xnarch_get_cpu_tsc() while spinning >>> inside this deadly loop... >> You can already read those TSCs: each trace point got recorded with the >> current TSC value, fresh from the hardware. >> > > I'd like to explain why we don't we see any other routines than > xnthread_aperiodic_handler called from xntimer_do_tick_aperiodic in the > call frame? Even in case of massive jittery (e.g. > 300 us late) in one > shot, we should not spin in this code, due to the resync done in > xnpod_wait_thread_timeout - assuming we only have a single outstanding > timer (+ the host tick, but this should not be an issue). xnpod_wait_thread_timeout? Do you mean xnpod_wait_thread_period? How should it help us as long as we are in the tick handler? > >> I rather think, also when looking at Julien's second trace, that we have >> some issue with X in user-space here, probably in combination with weird >> VIA hardware stalling IRQ delivery for a "few" microseconds. Let's see >> if the irqbench gives similar results. >> > > The problem is that I can reproduce X-related jittery (> 2 ms in a row) > on one of my test boxen when dragging windows over the screen, without > triggering the NMI watchdog set to 100 us (and guess what, the chipset > in question is from VIA). Does NMI management happen in the CPU or has the chipset any influence as well? If yes, I could imagine what VIA does here... Have you already checked what irqbench records? Jan [-- Attachment #2: OpenPGP digital signature --] [-- Type: application/pgp-signature, Size: 250 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 22:00 ` Jan Kiszka @ 2006-07-31 9:57 ` Philippe Gerum 0 siblings, 0 replies; 29+ messages in thread From: Philippe Gerum @ 2006-07-31 9:57 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai On Mon, 2006-07-31 at 00:00 +0200, Jan Kiszka wrote: <snip> > > I'd like to explain why we don't we see any other routines than > > xnthread_aperiodic_handler called from xntimer_do_tick_aperiodic in the > > call frame? Even in case of massive jittery (e.g. > 300 us late) in one > > shot, we should not spin in this code, due to the resync done in > > xnpod_wait_thread_timeout - assuming we only have a single outstanding > > timer (+ the host tick, but this should not be an issue). > > xnpod_wait_thread_timeout? Do you mean xnpod_wait_thread_period? How > should it help us as long as we are in the tick handler? > Yes, I meant xnpod_wait_thread_period; forget about this, brain is missing ECC feature. I misread the tracer output. > > > >> I rather think, also when looking at Julien's second trace, that we have > >> some issue with X in user-space here, probably in combination with weird > >> VIA hardware stalling IRQ delivery for a "few" microseconds. Let's see > >> if the irqbench gives similar results. > >> > > > > The problem is that I can reproduce X-related jittery (> 2 ms in a row) > > on one of my test boxen when dragging windows over the screen, without > > triggering the NMI watchdog set to 100 us (and guess what, the chipset > > in question is from VIA). > > Does NMI management happen in the CPU or has the chipset any influence > as well? I was referring to something like SMI# -> SMM which disables IRQs _and_ the NMI# and INIT# lines, in which case, the chipset would be at the root of the problem. Since we cannot guarantee that our existing SMI work-around blocks all potential SMI sources/events (hence the name), we cannot exclude such possibility. > If yes, I could imagine what VIA does here... Have you already > checked what irqbench records? > Not yet. > Jan > -- Philippe. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-30 21:23 ` Philippe Gerum 2006-07-30 22:00 ` Jan Kiszka @ 2006-07-31 11:39 ` Gilles Chanteperdrix 2006-07-31 14:19 ` Philippe Gerum 1 sibling, 1 reply; 29+ messages in thread From: Gilles Chanteperdrix @ 2006-07-31 11:39 UTC (permalink / raw) To: rpm; +Cc: xenomai, Jan Kiszka Philippe Gerum wrote: > > I rather think, also when looking at Julien's second trace, that we have > > some issue with X in user-space here, probably in combination with weird > > VIA hardware stalling IRQ delivery for a "few" microseconds. Let's see > > if the irqbench gives similar results. > > > > The problem is that I can reproduce X-related jittery (> 2 ms in a row) > on one of my test boxen when dragging windows over the screen, without > triggering the NMI watchdog set to 100 us (and guess what, the chipset > in question is from VIA). IMHO there are two reasons why the NMI watchdog may not trig: - its code is broken (we already have an unsolved bug that shows us that maybe it does not work as we believe) - the NMI watchdog only counts busy cycles, so maybe the CPU is not busy during these 2 ms, it is spinning, waiting for the GPU to finish the work using the rep; nop instruction in order to allow power saving. But with interrupts off. Maybe disabling hardware acceleration in your X server configuration would help ? -- Gilles Chanteperdrix. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-31 11:39 ` Gilles Chanteperdrix @ 2006-07-31 14:19 ` Philippe Gerum 2006-07-31 20:49 ` Julien Heyman 2006-08-01 14:30 ` Philippe Gerum 0 siblings, 2 replies; 29+ messages in thread From: Philippe Gerum @ 2006-07-31 14:19 UTC (permalink / raw) To: Gilles Chanteperdrix; +Cc: xenomai, Jan Kiszka On Mon, 2006-07-31 at 13:39 +0200, Gilles Chanteperdrix wrote: > Philippe Gerum wrote: > > > I rather think, also when looking at Julien's second trace, that we have > > > some issue with X in user-space here, probably in combination with weird > > > VIA hardware stalling IRQ delivery for a "few" microseconds. Let's see > > > if the irqbench gives similar results. > > > > > > > The problem is that I can reproduce X-related jittery (> 2 ms in a row) > > on one of my test boxen when dragging windows over the screen, without > > triggering the NMI watchdog set to 100 us (and guess what, the chipset > > in question is from VIA). > > IMHO there are two reasons why the NMI watchdog may not trig: > - its code is broken (we already have an unsolved bug that shows us that > maybe it does not work as we believe) > - the NMI watchdog only counts busy cycles, so maybe the CPU is not busy > during these 2 ms, it is spinning, waiting for the GPU to finish the > work using the rep; nop instruction in order to allow power > saving. But with interrupts off. > Maybe disabling hardware acceleration in your X server configuration > would help ? > Yes it does. Option "NoAccel" in the Screen section fixes the latency on the test box. Still, reinitializing X while the latency test runs causes the latter to hang, albeit LOC is still flowing properly and the box keeps going normally. OTOH, switching from text mode to graphic mode does not perturbate the test anymore. -- Philippe. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-31 14:19 ` Philippe Gerum @ 2006-07-31 20:49 ` Julien Heyman 2006-08-01 13:13 ` Gilles Chanteperdrix 2006-08-01 14:30 ` Philippe Gerum 1 sibling, 1 reply; 29+ messages in thread From: Julien Heyman @ 2006-07-31 20:49 UTC (permalink / raw) To: xenomai, rpm; +Cc: Jan Kiszka On Monday 31 July 2006 16:19, Philippe Gerum wrote: > On Mon, 2006-07-31 at 13:39 +0200, Gilles Chanteperdrix wrote: > > Philippe Gerum wrote: > > > > I rather think, also when looking at Julien's second trace, that we > > > > have some issue with X in user-space here, probably in combination > > > > with weird VIA hardware stalling IRQ delivery for a "few" > > > > microseconds. Let's see if the irqbench gives similar results. > > > > > > The problem is that I can reproduce X-related jittery (> 2 ms in a > > > row) on one of my test boxen when dragging windows over the screen, > > > without triggering the NMI watchdog set to 100 us (and guess what, the > > > chipset in question is from VIA). > > > > IMHO there are two reasons why the NMI watchdog may not trig: > > - its code is broken (we already have an unsolved bug that shows us that > > maybe it does not work as we believe) > > - the NMI watchdog only counts busy cycles, so maybe the CPU is not busy > > during these 2 ms, it is spinning, waiting for the GPU to finish the > > work using the rep; nop instruction in order to allow power > > saving. But with interrupts off. > > > > Maybe disabling hardware acceleration in your X server configuration > > would help ? > > Yes it does. Option "NoAccel" in the Screen section fixes the latency on > the test box. Still, reinitializing X while the latency test runs causes > the latter to hang, albeit LOC is still flowing properly and the box > keeps going normally. OTOH, switching from text mode to graphic mode > does not perturbate the test anymore. Some good news from my side : I did the same on my EPIA box (added Option "NoAccel" in the Device section referring to the Trident video driver) and since then the latency test works like a charm. Zero overrun, and a stable max value (around 50 microseconds), even when I launch multiple heavy applications at the same time. Display performance has obviously taken a bit hit, but this is not my main concern for now. Thanks for the tip, there is no way I would have figured that one out by myself ;) (Jan, Gilles, thx for all of your good advice too !) It's time for me to play with Xenomai now. Regards, Julien Heyman ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-31 20:49 ` Julien Heyman @ 2006-08-01 13:13 ` Gilles Chanteperdrix 2006-08-01 13:38 ` Philippe Gerum 0 siblings, 1 reply; 29+ messages in thread From: Gilles Chanteperdrix @ 2006-08-01 13:13 UTC (permalink / raw) To: Julien Heyman; +Cc: xenomai, Jan Kiszka [-- Attachment #1: message body and .signature --] [-- Type: text/plain, Size: 653 bytes --] Julien Heyman wrote: > Some good news from my side : > I did the same on my EPIA box (added Option "NoAccel" in the Device section > referring to the Trident video driver) and since then the latency test works > like a charm. Zero overrun, and a stable max value (around 50 microseconds), > even when I launch multiple heavy applications at the same time. > Display performance has obviously taken a bit hit, but this is not my main > concern for now. > Thanks for the tip, there is no way I would have figured that one out by > myself ;) Maybe this tip deserves an entry in the TROUBLESHOOTING file? -- Gilles Chanteperdrix. [-- Attachment #2: xeno-x-noaccel.diff --] [-- Type: text/plain, Size: 751 bytes --] Index: TROUBLESHOOTING =================================================================== --- TROUBLESHOOTING (revision 1403) +++ TROUBLESHOOTING (working copy) @@ -218,6 +218,17 @@ ______________________________________________________________________ +Q: I am seeing high latency spots when running under X-window, what + can I do? + +A: Try disabling hardware acceleration in the X-window server + configuration file; in the "Device" section of /etc/X11/XF86Config-4, + add the following line: + + Option "NoAccel" + +______________________________________________________________________ + Q: Xenomai HAL's initialization fails with error: -1 no such device A: Dumping the kernel message log using "dmesg" will likely give you ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-08-01 13:13 ` Gilles Chanteperdrix @ 2006-08-01 13:38 ` Philippe Gerum 0 siblings, 0 replies; 29+ messages in thread From: Philippe Gerum @ 2006-08-01 13:38 UTC (permalink / raw) To: Gilles Chanteperdrix; +Cc: Jan Kiszka, xenomai On Tue, 2006-08-01 at 15:13 +0200, Gilles Chanteperdrix wrote: > Julien Heyman wrote: > > Some good news from my side : > > I did the same on my EPIA box (added Option "NoAccel" in the Device section > > referring to the Trident video driver) and since then the latency test works > > like a charm. Zero overrun, and a stable max value (around 50 microseconds), > > even when I launch multiple heavy applications at the same time. > > Display performance has obviously taken a bit hit, but this is not my main > > concern for now. > > Thanks for the tip, there is no way I would have figured that one out by > > myself ;) > > Maybe this tip deserves an entry in the TROUBLESHOOTING file? Indeed. Please commit. > plain text document attachment (xeno-x-noaccel.diff) > Index: TROUBLESHOOTING > =================================================================== > --- TROUBLESHOOTING (revision 1403) > +++ TROUBLESHOOTING (working copy) > @@ -218,6 +218,17 @@ > > ______________________________________________________________________ > > +Q: I am seeing high latency spots when running under X-window, what > + can I do? > + > +A: Try disabling hardware acceleration in the X-window server > + configuration file; in the "Device" section of /etc/X11/XF86Config-4, > + add the following line: > + > + Option "NoAccel" > + > +______________________________________________________________________ > + > Q: Xenomai HAL's initialization fails with error: -1 no such device > > A: Dumping the kernel message log using "dmesg" will likely give you -- Philippe. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-31 14:19 ` Philippe Gerum 2006-07-31 20:49 ` Julien Heyman @ 2006-08-01 14:30 ` Philippe Gerum 2006-08-01 14:45 ` [Xenomai-core] [RFC] tame the watchdog (was: Beginner's question / testsuite / latency) Jan Kiszka 1 sibling, 1 reply; 29+ messages in thread From: Philippe Gerum @ 2006-08-01 14:30 UTC (permalink / raw) To: Gilles Chanteperdrix; +Cc: xenomai, Jan Kiszka On Mon, 2006-07-31 at 16:19 +0200, Philippe Gerum wrote: > On Mon, 2006-07-31 at 13:39 +0200, Gilles Chanteperdrix wrote: > > Philippe Gerum wrote: > > > > I rather think, also when looking at Julien's second trace, that we have > > > > some issue with X in user-space here, probably in combination with weird > > > > VIA hardware stalling IRQ delivery for a "few" microseconds. Let's see > > > > if the irqbench gives similar results. > > > > > > > > > > The problem is that I can reproduce X-related jittery (> 2 ms in a row) > > > on one of my test boxen when dragging windows over the screen, without > > > triggering the NMI watchdog set to 100 us (and guess what, the chipset > > > in question is from VIA). > > > > IMHO there are two reasons why the NMI watchdog may not trig: > > - its code is broken (we already have an unsolved bug that shows us that > > maybe it does not work as we believe) > > - the NMI watchdog only counts busy cycles, so maybe the CPU is not busy > > during these 2 ms, it is spinning, waiting for the GPU to finish the > > work using the rep; nop instruction in order to allow power > > saving. But with interrupts off. > > > Maybe disabling hardware acceleration in your X server configuration > > would help ? > > > > Still, reinitializing X while the latency test runs causes > the latter to hang, albeit LOC is still flowing properly and the box > keeps going normally. This one was due to the nucleus watchdog which triggered right after the graphic mode was fully initialized, due to the huge amount of unpreemptible time spent doing this; this caused the sampling task to be detected as a runaway thread. So the behaviour is ok, albeit a bit frightening at first. -- Philippe. ^ permalink raw reply [flat|nested] 29+ messages in thread
* [Xenomai-core] [RFC] tame the watchdog (was: Beginner's question / testsuite / latency) 2006-08-01 14:30 ` Philippe Gerum @ 2006-08-01 14:45 ` Jan Kiszka 2006-08-02 8:52 ` [Xenomai-core] " Philippe Gerum 0 siblings, 1 reply; 29+ messages in thread From: Jan Kiszka @ 2006-08-01 14:45 UTC (permalink / raw) To: rpm, xenomai [-- Attachment #1: Type: text/plain, Size: 909 bytes --] Philippe Gerum wrote: >> Still, reinitializing X while the latency test runs causes >> the latter to hang, albeit LOC is still flowing properly and the box >> keeps going normally. > > This one was due to the nucleus watchdog which triggered right after the > graphic mode was fully initialized, due to the huge amount of > unpreemptible time spent doing this; this caused the sampling task to be > detected as a runaway thread. So the behaviour is ok, albeit a bit > frightening at first. > That reminds of the unfortunate characteristics of the 2.6 oom-killer: unless you set your time-critical app's oom_adj to -17, you are never really safe from being killed accidentally on low-mem scenarios. What about introducing some mechanism to protect audited tasks against the watchdog? A simple thread flag settable via existing APIs, ignored if there is no watchdog compiled in? Jan [-- Attachment #2: OpenPGP digital signature --] [-- Type: application/pgp-signature, Size: 250 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* [Xenomai-core] Re: [RFC] tame the watchdog (was: Beginner's question / testsuite / latency) 2006-08-01 14:45 ` [Xenomai-core] [RFC] tame the watchdog (was: Beginner's question / testsuite / latency) Jan Kiszka @ 2006-08-02 8:52 ` Philippe Gerum 2006-08-02 11:04 ` [Xenomai-core] Re: [RFC] tame the watchdog Jan Kiszka 0 siblings, 1 reply; 29+ messages in thread From: Philippe Gerum @ 2006-08-02 8:52 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai On Tue, 2006-08-01 at 16:45 +0200, Jan Kiszka wrote: > Philippe Gerum wrote: > >> Still, reinitializing X while the latency test runs causes > >> the latter to hang, albeit LOC is still flowing properly and the box > >> keeps going normally. > > > > This one was due to the nucleus watchdog which triggered right after the > > graphic mode was fully initialized, due to the huge amount of > > unpreemptible time spent doing this; this caused the sampling task to be > > detected as a runaway thread. So the behaviour is ok, albeit a bit > > frightening at first. > > > > That reminds of the unfortunate characteristics of the 2.6 oom-killer: > unless you set your time-critical app's oom_adj to -17, you are never > really safe from being killed accidentally on low-mem scenarios. > > What about introducing some mechanism to protect audited tasks against > the watchdog? A simple thread flag settable via existing APIs, ignored > if there is no watchdog compiled in? There is a fundamental difference between the OOM killer and the Xenomai watchdog: the latter is merely a debugging tool to prevent the box to hang, and you can disable it completely. The situations reported by the watchdog are pathological ones, which involve more than 4 seconds of continuous real-time activity while the Linux kernel is being totally starved from CPU, and in such a case, you really want someone to pull the brake, regardless of the consequences on the application (which looks like basically toast anyway). IOW, if such weird situation eventually ends up being considered as "normal" under certain circumstances, the best approach is simply to disable the watchdog entirely. Limiting the runtime quantum allotted to threads through a dedicated scheduling policy would be a better way to deal with CPU overconsumption "intelligently", i.e. on a per-thread basis. OTOH, the current watchdog implementation is aiming at being terminally dumb for the sake of debug efficiency. -- Philippe. ^ permalink raw reply [flat|nested] 29+ messages in thread
* [Xenomai-core] Re: [RFC] tame the watchdog 2006-08-02 8:52 ` [Xenomai-core] " Philippe Gerum @ 2006-08-02 11:04 ` Jan Kiszka 0 siblings, 0 replies; 29+ messages in thread From: Jan Kiszka @ 2006-08-02 11:04 UTC (permalink / raw) To: rpm; +Cc: xenomai [-- Attachment #1: Type: text/plain, Size: 2422 bytes --] Philippe Gerum wrote: > On Tue, 2006-08-01 at 16:45 +0200, Jan Kiszka wrote: >> Philippe Gerum wrote: >>>> Still, reinitializing X while the latency test runs causes >>>> the latter to hang, albeit LOC is still flowing properly and the box >>>> keeps going normally. >>> This one was due to the nucleus watchdog which triggered right after the >>> graphic mode was fully initialized, due to the huge amount of >>> unpreemptible time spent doing this; this caused the sampling task to be >>> detected as a runaway thread. So the behaviour is ok, albeit a bit >>> frightening at first. >>> >> That reminds of the unfortunate characteristics of the 2.6 oom-killer: >> unless you set your time-critical app's oom_adj to -17, you are never >> really safe from being killed accidentally on low-mem scenarios. >> >> What about introducing some mechanism to protect audited tasks against >> the watchdog? A simple thread flag settable via existing APIs, ignored >> if there is no watchdog compiled in? > > There is a fundamental difference between the OOM killer and the Xenomai > watchdog: the latter is merely a debugging tool to prevent the box to > hang, and you can disable it completely. > > The situations reported by the watchdog are pathological ones, which > involve more than 4 seconds of continuous real-time activity while the > Linux kernel is being totally starved from CPU, and in such a case, you > really want someone to pull the brake, regardless of the consequences on > the application (which looks like basically toast anyway). IOW, if such > weird situation eventually ends up being considered as "normal" under > certain circumstances, the best approach is simply to disable the > watchdog entirely. > > Limiting the runtime quantum allotted to threads through a dedicated > scheduling policy would be a better way to deal with CPU overconsumption > "intelligently", i.e. on a per-thread basis. For sure, e.g. round-robin scheduling including the root thread, and this also over aperiodic timer mode. > OTOH, the current watchdog > implementation is aiming at being terminally dumb for the sake of debug > efficiency. > Yes, it's simple and it's a debugging mechanism. Nevertheless, I think it can be improved without too much effort or costs. I would love to demonstrate this, but for now I'm afraid this has to remain a (now filed) idea. Jan [-- Attachment #2: OpenPGP digital signature --] [-- Type: application/pgp-signature, Size: 250 bytes --] ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-20 21:17 [Xenomai-help] Beginner's question / testsuite / latency Julien Heyman 2006-07-20 21:58 ` Jan Kiszka @ 2006-07-21 13:25 ` Gilles Chanteperdrix 2006-07-22 9:58 ` Julien Heyman 1 sibling, 1 reply; 29+ messages in thread From: Gilles Chanteperdrix @ 2006-07-21 13:25 UTC (permalink / raw) To: Julien Heyman; +Cc: xenomai Julien Heyman wrote: > Hi, > > I am currently trying to evaluate Xenomai, and my current setup is : > VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. > I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. > When I run the latency part of the testsuite (in a console under KDE), I get > results that I cannot understand, so I probably did something wrong > (execution trace included below). > I get reasonable values during the first seconds, then all of a sudden > latencies begin to rise, continuously, to very large values. > - I did check that DMA transfer is activated on my HD. > - I did select "Enable SMI workaround" + "Globally disable SMI" in the > Xenomai > options while configuring the kernel. > - I have disabled power management at BIOS level and disabled ACPI support > and > CPU frequency scaling during kernel configuration. > - I checked that I don't have anything called "legacy USB" in my BIOS. I do > have an "OnChip USB" option enable in the BIOS though. > > Any advice would be appreciated ! Some platforms stop their tsc when idle, this would cause serious trouble for Xenomai. Linux detect such behaviour and print the message: Losing too many ticks! TSC cannot be used as a timesource. Possible reasons for this are: You're running with Speedstep, You don't have DMA enabled for your hard disk (see hdparm), Incorrect TSC synchronization on an SMP system (see dmesg). Falling back to a sane timesource now. Do you see such message in kernel logs ? If this is the issue you are having, then you may try passing idle=poll on kernel boot line. Or recompile the kernel selecting a processor that has no tsc (for example 486), xenomai will then use the 8254 counter to emulate the tsc. -- Gilles Chanteperdrix. ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [Xenomai-help] Beginner's question / testsuite / latency 2006-07-21 13:25 ` [Xenomai-help] Beginner's question / testsuite / latency Gilles Chanteperdrix @ 2006-07-22 9:58 ` Julien Heyman 0 siblings, 0 replies; 29+ messages in thread From: Julien Heyman @ 2006-07-22 9:58 UTC (permalink / raw) To: Gilles Chanteperdrix; +Cc: xenomai Hi Gilles, On Friday 21 July 2006 15:25, Gilles Chanteperdrix wrote: > Julien Heyman wrote: > > Hi, > > > > I am currently trying to evaluate Xenomai, and my current setup is : > > VIA C3 533Mhz processor, Kubuntu 6.06 Linux distribution. > > I am using Xenomai-2.1.0 over a 2.6.17.4 kernel. > > When I run the latency part of the testsuite (in a console under KDE), I > > get results that I cannot understand, so I probably did something wrong > > (execution trace included below). > > I get reasonable values during the first seconds, then all of a sudden > > latencies begin to rise, continuously, to very large values. > > - I did check that DMA transfer is activated on my HD. > > - I did select "Enable SMI workaround" + "Globally disable SMI" in the > > Xenomai > > options while configuring the kernel. > > - I have disabled power management at BIOS level and disabled ACPI > > support and > > CPU frequency scaling during kernel configuration. > > - I checked that I don't have anything called "legacy USB" in my BIOS. I > > do have an "OnChip USB" option enable in the BIOS though. > > > > Any advice would be appreciated ! > > Some platforms stop their tsc when idle, this would cause serious > trouble for Xenomai. Linux detect such behaviour and print the message: > > Losing too many ticks! > TSC cannot be used as a timesource. > Possible reasons for this are: > You're running with Speedstep, > You don't have DMA enabled for your hard disk (see hdparm), > Incorrect TSC synchronization on an SMP system (see dmesg). > Falling back to a sane timesource now. > > Do you see such message in kernel logs ? No, no trace of such messages in dmesg / kern.log when the pb occurs. (am I checking the "right" logs by the way ? I am a newbie on Linux) > > If this is the issue you are having, then you may try passing idle=poll > on kernel boot line. Or recompile the kernel selecting a processor that > has no tsc (for example 486), xenomai will then use the 8254 counter to > emulate the tsc. Ok, I will try selecting CPU=486, disabling TSC in Xenomai config and using the latest Xenomai release, for the sake of testing. Regards, Julien Heyman ^ permalink raw reply [flat|nested] 29+ messages in thread
end of thread, other threads:[~2006-08-02 11:04 UTC | newest] Thread overview: 29+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2006-07-20 21:17 [Xenomai-help] Beginner's question / testsuite / latency Julien Heyman 2006-07-20 21:58 ` Jan Kiszka 2006-07-22 9:52 ` Julien Heyman 2006-07-22 17:17 ` Jan Kiszka 2006-07-28 21:17 ` Julien Heyman 2006-07-28 21:32 ` Gilles Chanteperdrix 2006-07-30 17:29 ` Julien Heyman 2006-07-30 17:49 ` Philippe Gerum 2006-07-30 20:39 ` Gilles Chanteperdrix 2006-07-29 14:20 ` Jan Kiszka 2006-07-30 17:36 ` Julien Heyman 2006-07-30 18:03 ` Philippe Gerum 2006-07-30 19:33 ` Jan Kiszka 2006-07-30 20:03 ` Gilles Chanteperdrix 2006-07-30 22:00 ` Jan Kiszka 2006-07-30 21:23 ` Philippe Gerum 2006-07-30 22:00 ` Jan Kiszka 2006-07-31 9:57 ` Philippe Gerum 2006-07-31 11:39 ` Gilles Chanteperdrix 2006-07-31 14:19 ` Philippe Gerum 2006-07-31 20:49 ` Julien Heyman 2006-08-01 13:13 ` Gilles Chanteperdrix 2006-08-01 13:38 ` Philippe Gerum 2006-08-01 14:30 ` Philippe Gerum 2006-08-01 14:45 ` [Xenomai-core] [RFC] tame the watchdog (was: Beginner's question / testsuite / latency) Jan Kiszka 2006-08-02 8:52 ` [Xenomai-core] " Philippe Gerum 2006-08-02 11:04 ` [Xenomai-core] Re: [RFC] tame the watchdog Jan Kiszka 2006-07-21 13:25 ` [Xenomai-help] Beginner's question / testsuite / latency Gilles Chanteperdrix 2006-07-22 9:58 ` Julien Heyman
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.