irq handler to thread execution time

QNX Newsgroups (Archives) qdn.public.qnxrtp.os
1

Hello!

In order to be able to divide code between irq handler
and thread efficiently I was playing a bit with QNX RTP.

I tried to follow this rules:
thread “scheduled from handler” is high priority… 63
measure ellapsed time with ClockCycles
print data in other normal priority thread
use bare CPU board (no network, sound, SMM, …)
run program from boot-image (no filesystem, …)

My program does sth like this:

irq_handler () {
remember value of ClockCycles
return event to wake thread
}

thread() {
while(1){
InterruptWait()
remember value of ClockCycles
count min, max, average difference
}
}

main(){
while(1){
print counted values
}
}

And my findings are that sometimes it takes
almost !!! 1ms !!! from interrupt handler to thread.
(I measured it on 266MHz AMD K6)

The easiest way to make the difference large is to
start pidin on other console.

I am attaching my src code and also build file.

Thanks for any comment.

Pavol

Pavol Kycina
Microstep-HDO, s.r.o.
Bratislava, Slovakia







begin 600 irq_diff.c
M(VEN8VQU9&4@/’-T9&EO+F@^#0HC:6YC;‘5D92\<WES+VYE=71R:6YO+F@^ M#0HC:6YC;'5D92<WES+W-I9VEN9F\N:#X-“B-I;F-L=61E(#QI;G1T>7!E
M<RYH/@T*#0H-“G-T<G5C=”!S:6=E=F5N=”!E=F5N=#L-“FEN=EG;R](#$[
M#0H-“G-T871I8R!I;G0)“0D)“0D)9FQA9U]A=F<@/2P.PT*=6YS:6=N960@ M:6YT"0D)"6-?9&EF9E]M87@@/2P+”!C7V1I9F9?;6EN(#T@+3$L(&-?9&EF
M9E]A=F<@/2P.PT*=F]L871I;&4@=6EN=#8T7W0)"0EC7VYO=U]I:2](#[ M#0IS=&%T:6,@=6EN=#8T7W0)"0D)8U]N;W<@/2P+”!C7V]L9"](#L(&-?
M=&UP+”!S=6U?879G.PT*#0IC;VYS=”!S=’)U8W0@<VEG979E;G0J(&ES<E]H
M86YD;&5R*‘9O:60@F%R9RP@:6YT(&ED0T*>PT*“0T*“6-?;F]W7VEI(#T@
M0VQO8VM#>6-L97,H3L-"@D-"@ER971U<FXH)F5V96YT3L-“GT-”@T*=F]I
M9"H@:6YT7W1H<F5A9”@@=F]I9”J87)G*0T*>PT*"6EN="@("@("@("@ M("@("@("@("!R970[#0H)<W1R=6-T(’-C:&5D7W!A<F%M"7!A<F%M.PT*
M#0H)+R@:6YI8VEA;&EZ=6H@979E;G0-"@E324=%5E])3E127TE.250H(“9E
M=F5N=“D[#0H-”@DO+V5N86)L92!I+V@<’)I=FEL96=E#0H)<F5T(#T@5&AR
M96%D0W1L7W(H7TY43U]40U1,7TE/+”!.54Q,3L-"@EI9BAR970@/"P*7L- M"@D)<')I;G1F*").96UA;2!P<F%V82!N82!)3R!O<&5R86-I95QN(BD[#0H) M"6=O(#T@,#L-"@D)<F5T=7)N.PT*"7T-"@D-"@EP87)A;2YS8VAE9%]P<FEO M<FET>2](#8S.PT"7)E="](%-C:&5D4V5T7W(H,"P@,"P@4T-(141?3D]# M2$%.1T4L("9P87)A;2D[#0H):68H<F5T(#P@,"E[#0H)"7!R:6YT9B@B3F5P M;V1A<FEL;R!S82!Z;65N:70@<')I;W)I='5<;B(I.PT*"0EG;R](#[#0H) M"7)E='5R;CL-"@E]#0H-"@ER970@/2!);G1E<G)U<'1!='1A8V@H,"P@:7-R M7VAA;F1L97(L($Y53$PL(#L(#I.PT*"6EF*')E="(#I>PT*"0EP<FEN M=&8H(DYE;6]Z96T@<V$@<')I<&]J:70@;F$@<')E<G5S96YI95QN(BD[#0H) M"6=O(#T@,#L-"@D)<F5T=7)N.PT*"7T-"@T*"7=H:6QE*#$I>PT*"0E);G1E M<G)U<'1786ET*#L($Y53$PI.PT*“0D-”@D)8U]O;&0@/2!C7VYO=U]I:3L-
M"@D)8U]N;W<@/2!#;&]C:T-Y8VQE<R@I.PT"0EI9BAC7VYO=RF)B!C7V]L M9"E[#0H)"0EC7W1M<"](&-?;F]W("T@8U]O;&0[#0H)“0EI9BAC7W1M<”^ M(&-?9&EF9E]M87@I>PT*"0D)"69L86=?879G(#T@,#L-"@D)"0EC7V1I9F9? M;6%X(#T@8U]T;7[#0H)"0E](&5L<V4@:68H(&-?=&UP(#P@8U]D:69F7VUI
M;BE[#0H)"0D)8U]D:69F7VUI;B](&-?=&UP.PT*"0D)"69L86=?879G("]
M(#[#0H)"0E](&5L<V4@>PT*"0D)"6EF*&9L86=?879G(#T](#I>PT"0D)
M"0ES=6U?879G(#T@,#L-"@D)"0E]#0H)"0D)9FQA9U]A=F<KSL-"@D)"0ES
M=6U?879G("L](&-?=&UP.PT"0D)"6EF*&9L86=?879G(#T](#$P,#I>PT* M"0D)"0EC7V1I9F9?879G(#T@<W5M7V%V9RO(&9L86=?879G.PT*"0D)“0EF
M;&%G7V%V9R](#[#0H)“0D)?0T*“0D)?0T*“0E]#0H)?0T*?0T*#0H-“FUA
M:6XH0T>PT*“6EN=D)=&ED.PT*"7!T:')E861?8W)E871E*"F=&ED+”!.
M54Q,+”!I;G1?=&AR96%D+”!.54Q,*3L-”@EP<FEN=&8H(E1H<F5A9”!M82!I
M9”E9%QN(BP@=&ED*3L-"@T*"7=H:6QE*&=O*7L-"@D)<')I;G1F*")D:69F M(&IE(&UI;BXN+B5D(&%V9RXN+B5D(&UA>"XN+B5D(%QN(BP@8U]D:69F7VUI M;BP@8U]D:69F7V%V9RP@8U]D:69F7VUA>"D[#0H)"7-L965P*#(I.PT*"7T- M"@T*"7!R:6YT9B@B4')E<G5S96YI92!S:V]N8VEL;RP@87-I(&YE:F%K82!C 2:'EB85QN(BD[#0I]#0H-"@T*
end

begin 600 qnx5.build
M6W-E87)C:#TN.B]S8FEN.B]U<W(O<V)I;CHO8FEN.B]U<W(O8FEN.B]L:6(Z
M+VQI8B]D;&PZ+V)O;W0O<WES70T6W9I<G1U86P]>#@V+&)I;W,@V-O;7!R
M97-S72!B;V]T(#T@>PT"7-T87)T=7M8FEO<RM<RV-&L@+78-"@E0051( M/2]P<F]C+V)O;W0Z+V)I;CHO=7-R+V)I;B!,1%],24)205)97U!!5$@]+W!R M;V,O8F]O=#HO;&EB.B]U<W(O;&EB.B]L:6(O9&QL('!R;V-N=&\-"GT-"@T* M6RMS8W)I<'1=("YS8W)I<'0@/2![#0H)9&5V8RUC;VX@+6XT("8-"B,)9&5V M8RUS97(X,C4P("U&("UE("8-"@ED979C+7-E<C@R-3@+64@)@T"0T*“7)E
M;W!E;BO9&5V+V-O;C$-"B@(”!;W-E<W-I;VY=(%!!5$@]+W!R;V,O8F]O
M="!E<V@@)@T"7)E;W!E;BO9&5V+V-O;C(-"B@("!;W-E<W-I;VY=(%!!
M5$@]+W!R;V,O8F]O="!E<V@@)@T"7)E;W!E;BO9&5V+W-E<C$-"B@("!;
MW-E<W-I;VY=(%!!5$@]+W!R;V,O8F]O="!E<V@@)@T?0T*#0I;=‘EP93UL
M:6YK72O9&5V+V-O;G-O;&4]+V1E=B]C;VXQ#0I;='EP93UL:6YK72O=7-R
M+VQI8B]L9’%N>"YS;RXQ/2]P<F]C+V)O;W0O;&EB8RYS;PT*#0IL:6)C+G-O
M(T*#0I;9&%T83UC;W!Y70T*9&5V8RUC;VX-"F1E=F,M<V5R.#(U,T97-H
M#0HC(’-P96-I9GD@97AE8W5T86)L97,@=&AA="!Y;W4@=V%N="!T;R!B92!A
M8FQE#0HC(‘1O(’)U;B!F<F]M('1H92!S:&5L;#H@(&5C:&\L(&QS+"!P:61I
M;BP@971C+BXN#0IE8VAO#0IL<PT<&ED:6X-"F-A=T*8W-"FER<5]T:6UE
E<@T*:7)Q7V1I9F8-"G1I;65R#0IS:'5T9&]W;@T*2-"@==
end

2

See my previous post

Pavol Kycina

3

Pavol Kycina <kycina@microstep-hdo.sk> wrote:

See my previous post

Pavol Kycina

Pavol,

One of our tech support guys is looking at your issue right now,
more information to come out shortly …

Thomas

4

Hi Pavol

I am the tech support guy mentioned below. I have tried your
code on my machine and gotten the same or worse results. In
our Neutrino System Architecture book:

http://qdn.qnx.com/support/docs/neutrino_qrp/sys_arch/kernel.html

We refer to this time, the time from when the ISR returns to
when the driver thread begins, as scheduling latecy. On a P200
we list a typical time for this as 2.93 us.

I’ll have a look at your code and see if I can figure out why it’s
taking so long in your case. Also I’ll try and send you some
code which demonstrates a time more consistent with the 2.93 us.
I won’t be able to get this to you today though.



Previously, Thomas Fletcher wrote in qdn.public.qnxrtp.os:

Pavol Kycina <> kycina@microstep-hdo.sk> > wrote:
See my previous post

Pavol Kycina

Pavol,

One of our tech support guys is looking at your issue right now,
more information to come out shortly …

Thomas
\

5

“Chris Foran” <cforan@qnx.com> wrote in message
news:Voyager.010118125513.1087Z@funnel.qnx.com…

Hi Pavol

I am the tech support guy mentioned below. I have tried your
code on my machine and gotten the same or worse results. In
our Neutrino System Architecture book:

Hum curious I tried it and DIDN’T get the same result.

The largest number I have seen was

“diff je min…800 avg… 1160 max…7698”

Since these number express clock cycles, on my machine
they correspond to

1.7 us, 2.57 us and 17us. The max value was obtain by
doing heavy disk activy. Using gcc would raise it more
but I beleive that’s because of the VM issue.

One think I like to point out about the program which
made me want to give it a try is the uint64_t type. Unlike
most operation performed on a int, operation performed
on uint64_t are NOT atomic. That means if:

uint64_t val;

and inside the interrupt you do

++val;

If you read the value without protecting it outside
the interrupt you may be reading a faulty value.

However in the original program since accessing the value
read at interrupt time is synchronous with the thread it shouldn’t
be a problem unless the thread couldn’t run between two
interrupts.




http://qdn.qnx.com/support/docs/neutrino_qrp/sys_arch/kernel.html

We refer to this time, the time from when the ISR returns to
when the driver thread begins, as scheduling latecy. On a P200
we list a typical time for this as 2.93 us.

I’ll have a look at your code and see if I can figure out why it’s
taking so long in your case. Also I’ll try and send you some
code which demonstrates a time more consistent with the 2.93 us.
I won’t be able to get this to you today though.



Previously, Thomas Fletcher wrote in qdn.public.qnxrtp.os:
Pavol Kycina <> kycina@microstep-hdo.sk> > wrote:
See my previous post

Pavol Kycina

Pavol,

One of our tech support guys is looking at your issue right now,
more information to come out shortly …

Thomas

\

6

Hi Pavol

I think Mario is correct. The biggest problem with your
code is that the numbers you print are in clock ticks,
not any meaningful time unit.

If you divide the clock ticks by this number (cyc_per_sec)
you get a time in seconds:

cyc_per_sec = SYSPAGE_ENTRY(qtime)->cycles_per_sec;

You can check out my version here:

http://staff.qnx.com/~cforan/sched_laten.c

I got times around 2 us for a P3 550. When I moved the window
around it shot up by a factor of 10-100.

Is this helpful?






Previously, Mario Charest wrote in qdn.public.qnxrtp.os:

“Chris Foran” <> cforan@qnx.com> > wrote in message
news:> Voyager.010118125513.1087Z@funnel.qnx.com> …
Hi Pavol

I am the tech support guy mentioned below. I have tried your
code on my machine and gotten the same or worse results. In
our Neutrino System Architecture book:


Hum curious I tried it and DIDN’T get the same result.

The largest number I have seen was

“diff je min…800 avg… 1160 max…7698”

Since these number express clock cycles, on my machine
they correspond to

1.7 us, 2.57 us and 17us. The max value was obtain by
doing heavy disk activy. Using gcc would raise it more
but I beleive that’s because of the VM issue.

One think I like to point out about the program which
made me want to give it a try is the uint64_t type. Unlike
most operation performed on a int, operation performed
on uint64_t are NOT atomic. That means if:

uint64_t val;

and inside the interrupt you do

++val;

If you read the value without protecting it outside
the interrupt you may be reading a faulty value.

However in the original program since accessing the value
read at interrupt time is synchronous with the thread it shouldn’t
be a problem unless the thread couldn’t run between two
interrupts.




http://qdn.qnx.com/support/docs/neutrino_qrp/sys_arch/kernel.html

We refer to this time, the time from when the ISR returns to
when the driver thread begins, as scheduling latecy. On a P200
we list a typical time for this as 2.93 us.

I’ll have a look at your code and see if I can figure out why it’s
taking so long in your case. Also I’ll try and send you some
code which demonstrates a time more consistent with the 2.93 us.
I won’t be able to get this to you today though.



Previously, Thomas Fletcher wrote in qdn.public.qnxrtp.os:
Pavol Kycina <> kycina@microstep-hdo.sk> > wrote:
See my previous post

Pavol Kycina

Pavol,

One of our tech support guys is looking at your issue right now,
more information to come out shortly …

Thomas




\

7

Hello!

“Chris Foran” <cforan@qnx.com> wrote in message
news:Voyager.010122103454.1818F@funnel.qnx.com…

Hi Pavol

I think Mario is correct. The biggest problem with your
code is that the numbers you print are in clock ticks,
not any meaningful time unit.
You can check out my version here:

I was aware of it.

Program output (in clock cycles) is following:
min … 1008, avg … 1100, max … 9300

On the other console I type “pidin”, then I switch back
to the irq_diff console and the output is:
min … 870, avg … 1100, max … 175000

175000 on 266MHZ K6 processor is more than half of milisecond.

Pavol Kycina

PS: I will try your code. As far as I can read well, difference between
my code and your code is that I calculate diff on every tick and you
on every 100th tick.

8

“Pavol Kycina” <kycina@microstep-hdo.sk> wrote in message
news:64502DBEFA7ED311B4A0006008610AB63DB7C3@mail.mshdo…

Hello!

“Chris Foran” <> cforan@qnx.com> > wrote in message
news:> Voyager.010122103454.1818F@funnel.qnx.com> …
Hi Pavol

I think Mario is correct. The biggest problem with your
code is that the numbers you print are in clock ticks,
not any meaningful time unit.
You can check out my version here:

I was aware of it.

Program output (in clock cycles) is following:
min … 1008, avg … 1100, max … 9300

On the other console I type “pidin”, then I switch back
to the irq_diff console and the output is:
min … 870, avg … 1100, max … 175000

Console is in text or graphic mode?

175000 is equal to 650us. It is possible if you are
in graphic mode that depending on the type of graphics
card that you have, the bus be held for that period of time.
Try to same test in text mode (assuming you were in
graphics modes). Try it on a different machine as well.

My gut feeling tells me something in the hardware is holding
the CPU back.


175000 on 266MHZ K6 processor is more than half of milisecond.

Pavol Kycina

PS: I will try your code. As far as I can read well, difference between
my code and your code is that I calculate diff on every tick and you
on every 100th tick.

\

9

[snip]

Console is in text or graphic mode?
Console. I have built special boot, you can check it.

There is nothing running, just proc-nto, devc-con
and test program.

I repeated my test on different computers, I will state
just max values in clock cycles. (before and after typing
into first console … pidin; ls -lR / )

P-75: 3400 - 26892 … max 0.35ms
P3-500: 2750 - 17314 … max 0.034ms
K6-300: 3049 - 118406 !!! … max 0.395ms
K7-750: 3720 - 7511… max 0.010ms

Pavol

PS: I got all that values with summer/autumn version of QNXRTP,
I am trying to get my hands on PatchA.




begin 600 qnx_test.build.txt
M6W-E87)C:#TN.B]S8FEN.B]U<W(O<V)I;CHO8FEN.B]U<W(O8FEN.B]L:6(Z
M+VQI8B]D;&PZ+V)O;W0O<WES70T6W9I<G1U86P]>#@V+&)I;W,@V-O;7!R
M97-S72!B;V]T(#T@>PT"7-T87)T=7M8FEO<RM<RV-&L@+78-"@E0051( M/2]P<F]C+V)O;W0Z+V)I;CHO=7-R+V)I;B!,1%],24)205)97U!!5$@]+W!R M;V,O8F]O=#HO;&EB.B]U<W(O;&EB.B]L:6(O9&QL('!R;V-N=&\-"GT-"@T* M6RMS8W)I<'1=("YS8W)I<'0@/2![#0H)9&5V8RUC;VX@+6XT("8-"@ED979C M+7-E<C@R-3@+64@)@T"0T*“7)E;W!E;BO9&5V+V-O;C$-"B@(”!;W-E
M<W-I;VY=(%!!5$@]+W!R;V,O8F]O="!E<V@@)@T"7)E;W!E;BO9&5V+V-O M;C(-"B@("!;W-E<W-I;VY=(%!!5$@]+W!R;V,O8F]O="!E<V@@)@T"7)E
M;W!E;BO9&5V+W-E<C$-"B@("!;W-E<W-I;VY=(%!!5$@]+W!R;V,O8F]O
M="!E<V@@)@T?0T*#0I;=‘EP93UL:6YK72O9&5V+V-O;G-O;&4]+V1E=B]C M;VXQ#0I;='EP93UL:6YK72O=7-R+VQI8B]L9’%N>"YS;RXQ/2]P<F]C+V)O
M;W0O;&EB8RYS;PT*#0IL:6)C+G-O(T*#0I;9&%T83UC;W!Y70T*9&5V8RUC M;VX-"F1E=F,M<V5R.#(U,T97-H#0HC(’-P96-I9GD@97AE8W5T86)L97,@
M=&AA="!Y;W4@=V%N="!T;R!B92!A8FQE#0HC(‘1O(’)U;B!F<F]M('1H92!S
M:&5L;#H@(&5C:&\L(&QS+"!P:61I;BP@971C+BXN#0IE8VAO#0IL<PT<&ED
M:6X-"F-A=T*8W-"FER<5]D:69F#0IT:6UE<@T*<VAU=&1O=VX-"G-T='D@
"#0H=
`
end

10

“Pavol Kycina” <kycina@microstep-hdo.sk> wrote in message
news:64502DBEFA7ED311B4A0006008610AB63DC169@mail.mshdo…

[snip]

Console is in text or graphic mode?
Console. I have built special boot, you can check it.
There is nothing running, just proc-nto, devc-con
and test program.

I repeated my test on different computers, I will state
just max values in clock cycles. (before and after typing
into first console … pidin; ls -lR / )

P-75: 3400 - 26892 … max 0.35ms
P3-500: 2750 - 17314 … max 0.034ms
K6-300: 3049 - 118406 !!! … max 0.395ms
K7-750: 3720 - 7511… max 0.010ms

Can you trying reproducing this WITHOUT using pidin.
I get the impression pidin is not very real-time friendly.
On my machine it brings the max to 16427 (comparable to
you P3-500).


Pavol

PS: I got all that values with summer/autumn version of QNXRTP,
I am trying to get my hands on PatchA.

\

11

Hello!

Can you trying reproducing this WITHOUT using pidin.
I get the impression pidin is not very real-time friendly.
On my machine it brings the max to 16427 (comparable to
you P3-500).

I tried it on k6-300, I used these commands:

ls (in various directories :slight_smile: dev and proc)
stty </dev/ser1

and I got maximum of 119000 … 390us
I got that maximum several times.

Once (maybe twice) I got that maximum
without touching keyboard… just watching
output from irq_diff.

The only program running was irq_diff.

Pavol