Project Home
Project Home		 Documents
Documents		 Wiki
Wiki		 Discussion Forums
Discussions		 Project Information
Project Info
QNX Operating System/Discussion/OSTech/Expected latency values for MsgSend ?/List of Posts
Forum Topic - Expected latency values for MsgSend ?: (12 Items)
   
Update
Ashwin Patwekar
04/09/2009 6:12 AM
post26505
Expected latency values for MsgSend ?   
Hi,

What are the typical times for a MsgSend to send a message and return after a reply to the caller?   

I used the sample at 
http://support7.qnx.com/download/download/9880/server.c and http://photon.qnx.com/download/download/9881/client.c

I removed unecessary prints and added a while(1) loop to send messages from client and I tried to get timings using 
clock_gettime( ) before the MsgSend and after, The readings varied a lot with a Min in: 0us to and Max in: 3999usec on 
average. Some times the max was even more than 4ms. 

I even tried a usleep of 10 seconds between each message send but it did not affect the timings observed. 

What are the standard latency values for MsgSend ?
Robert Craig
04/09/2009 9:22 AM
post26527
RE: Expected latency values for MsgSend ?   
I'd look at what else is going on in your system.  Is it possible that
you're running your tests at a realtively low priority, allowing them to
be pre-empted by "something else" in the system? 

  I'm guessing that you're on an x86 platform and those high numbers are
definitely not what we measure.

  R.

-----Original Message-----
From: Ashwin Patwekar [mailto:community-noreply@qnx.com] 
Sent: Thursday, April 09, 2009 6:13 AM
To: ostech-core_os
Subject: Expected latency values for MsgSend ?

Hi,

What are the typical times for a MsgSend to send a message and return
after a reply to the caller?   

I used the sample at
http://support7.qnx.com/download/download/9880/server.c and
http://photon.qnx.com/download/download/9881/client.c

I removed unecessary prints and added a while(1) loop to send messages
from client and I tried to get timings using clock_gettime( ) before the
MsgSend and after, The readings varied a lot with a Min in: 0us to and
Max in: 3999usec on average. Some times the max was even more than 4ms. 

I even tried a usleep of 10 seconds between each message send but it did
not affect the timings observed. 

What are the standard latency values for MsgSend ? 

_______________________________________________
OSTech
http://community.qnx.com/sf/go/post26505
Ashwin Patwekar
04/09/2009 9:43 AM
post26533
Re: RE: Expected latency values for MsgSend ?   
Hi,

Thanks for the reply. 
Strangely these numbers are from our target which is the PQ2FADS board.
There is not much load on the cpu as hogs shows 
# hogs -% 1
PID             NAME  MSEC  PIDS SYSTEM
1                     3008   98%   100%
1                     2997   98%    99%
1                     3001   98%   100%
1                     3001   98%   100%
1                     3014   98%   100%

So there is something else going on. I tried the same program in a vm on x86 also there also the numbers were similar. 

btw I am using qnx 6.3.0 sp1

Thanks and Regards,
Ashwin
Robert Craig
04/09/2009 9:47 AM
post26536
RE: RE: Expected latency values for MsgSend ?   
As an aside, numbers obtained on a vm are really not useful. You have to
use real hardware if you want to do benchmarks.

What else is running on your FADS board (output of pidin would be
useful).  At what priority are you running your test apps?  An idle
board may still have other applications running that very occasionally
grabs the CPU for a few ms.

	R.



-----Original Message-----
From: Ashwin Patwekar [mailto:community-noreply@qnx.com] 
Sent: Thursday, April 09, 2009 9:43 AM
To: ostech-core_os
Subject: Re: RE: Expected latency values for MsgSend ?

Hi,

Thanks for the reply. 
Strangely these numbers are from our target which is the PQ2FADS board.
There is not much load on the cpu as hogs shows # hogs -% 1
PID             NAME  MSEC  PIDS SYSTEM
1                     3008   98%   100%
1                     2997   98%    99%
1                     3001   98%   100%
1                     3001   98%   100%
1                     3014   98%   100%

So there is something else going on. I tried the same program in a vm on
x86 also there also the numbers were similar. 

btw I am using qnx 6.3.0 sp1

Thanks and Regards,
Ashwin

_______________________________________________
OSTech
http://community.qnx.com/sf/go/post26533
Chris Travis
04/09/2009 9:37 AM
post26530
RE: Expected latency values for MsgSend ?   
You can find the QNX kernel benchmarks for more common boards at:
http://www.qnx.com/download/group.html?programid=7963

and the document describing the QNX Neutrino RTOS Kernel Benchmark
Methodology at:
http://www.qnx.com/download/feature.html?programid=8829

Chris

-----Original Message-----
From: Ashwin Patwekar [mailto:community-noreply@qnx.com] 
Sent: Thursday, April 09, 2009 6:13 AM
To: ostech-core_os
Subject: Expected latency values for MsgSend ?

Hi,

What are the typical times for a MsgSend to send a message and return
after a reply to the caller?   

I used the sample at 
http://support7.qnx.com/download/download/9880/server.c and
http://photon.qnx.com/download/download/9881/client.c

I removed unecessary prints and added a while(1) loop to send messages
from client and I tried to get timings using clock_gettime( ) before the
MsgSend and after, The readings varied a lot with a Min in: 0us to and
Max in: 3999usec on average. Some times the max was even more than 4ms. 

I even tried a usleep of 10 seconds between each message send but it did
not affect the timings observed. 

What are the standard latency values for MsgSend ? 

_______________________________________________
OSTech
http://community.qnx.com/sf/go/post26505
Mario Charest
04/09/2009 1:11 PM
post26590
RE: Expected latency values for MsgSend ?   
clock_gettime is precise down the the tick size which is 1ms...  Use ClockCycles instead.

> -----Original Message-----
> From: Ashwin Patwekar [mailto:community-noreply@qnx.com]
> Sent: April-09-09 6:13 AM
> To: ostech-core_os
> Subject: Expected latency values for MsgSend ?
> 
> Hi,
> 
> What are the typical times for a MsgSend to send a message and return
> after a reply to the caller?
> 
> I used the sample at
> http://support7.qnx.com/download/download/9880/server.c and
> http://photon.qnx.com/download/download/9881/client.c
> 
> I removed unecessary prints and added a while(1) loop to send messages
> from client and I tried to get timings using clock_gettime( ) before
> the MsgSend and after, The readings varied a lot with a Min in: 0us to
> and Max in: 3999usec on average. Some times the max was even more than
> 4ms.
> 
> I even tried a usleep of 10 seconds between each message send but it
> did not affect the timings observed.
> 
> What are the standard latency values for MsgSend ?
> 
> _______________________________________________
> OSTech
> http://community.qnx.com/sf/go/post26505
>
Ashwin Patwekar
04/13/2009 3:03 AM
post26733
Re: RE: Expected latency values for MsgSend ?   
Hi,

Here are the new times observed using ClockCycles. The times are averaged for 1000 readings and in between each msgsend 
there is a delay of 2ms.  

Comparing readings 1&3 or 1&4 it is seen that the minimum and maximum and the average times have reduced when the number
 of applications reduced.  
But still there are ocassional peaks even with minimum applications running which cause the peaks of more than 3ms not 
sure what might be causing these.

Thanks and Regards,
Ashwin

1. With full load all applications running
# pidin info
CPU:PPC Release:6.3.0  FreeMem:11Mb/64Mb BootTime:Apr 13 11:17:40 UTC 2009
Processor1: 80822014 8280 266MHz FPU

# ./client
This system has 16666666 cycles/sec.
min : 0.000121 max: 0.003908 avg: 0.000184
min : 0.000121 max: 0.003959 avg: 0.000158
min : 0.000120 max: 0.004039 avg: 0.000179
min : 0.000120 max: 0.001864 avg: 0.000176
min : 0.000120 max: 0.011469 avg: 0.000234
min : 0.000121 max: 0.001059 avg: 0.000146
min : 0.000120 max: 0.003958 avg: 0.000189
min : 0.000121 max: 0.001824 avg: 0.000177
min : 0.000121 max: 0.001973 avg: 0.000177
min : 0.000120 max: 0.003884 avg: 0.000154
min : 0.000120 max: 0.003505 avg: 0.000179
min : 0.000121 max: 0.005044 avg: 0.000183
min : 0.000120 max: 0.003924 avg: 0.000188

2. with applciations not running only drivers loaded.
# pidin info
CPU:PPC Release:6.3.0  FreeMem:30Mb/64Mb BootTime:Apr 13 11:17:40 UTC 2009
Processor1: 80822014 8280 266MHz FPU

# ./client
This system has 16666666 cycles/sec.
min : 0.000117 max: 0.003990 avg: 0.000143
min : 0.000117 max: 0.003912 avg: 0.000141
min : 0.000116 max: 0.000227 avg: 0.000134
min : 0.000116 max: 0.003933 avg: 0.000142
min : 0.000116 max: 0.003940 avg: 0.000138
min : 0.000116 max: 0.003940 avg: 0.000138
min : 0.000116 max: 0.003932 avg: 0.000139
min : 0.000117 max: 0.000596 avg: 0.000135
min : 0.000111 max: 0.000587 avg: 0.000134
min : 0.000116 max: 0.000644 avg: 0.000136
min : 0.000117 max: 0.003578 avg: 0.000140
min : 0.000116 max: 0.002560 avg: 0.000139


3. without any board drivers  
# pidin a
     pid Arguments
       1 procnto
    4099 slogger
    4100 pipe
    4101 devc-pty
    4102 mqueue
    4103 random -i1 -i2
  253981 io-net
  512031 inetd
 1650743 inetd
 1687608 in.telnetd
 1691705 -l
 1724476 sh
 3235899 inetd
 4595714 ./server
 4665352 pidin a

# ./client
This system has 16666666 cycles/sec.
min : 0.000109 max: 0.003473 avg: 0.000115
min : 0.000109 max: 0.000138 avg: 0.000111
min : 0.000108 max: 0.000406 avg: 0.000111
min : 0.000108 max: 0.001553 avg: 0.000114
min : 0.000108 max: 0.003923 avg: 0.000118
min : 0.000108 max: 0.000514 avg: 0.000111
min : 0.000108 max: 0.000371 avg: 0.000111
min : 0.000108 max: 0.000137 avg: 0.000110
min : 0.000108 max: 0.000396 avg: 0.000111
min : 0.000108 max: 0.000512 avg: 0.000111
min : 0.000108 max: 0.003494 avg: 0.000114
min : 0.000108 max: 0.000405 avg: 0.000111
min : 0.000108 max: 0.003473 avg: 0.000115
min : 0.000108 max: 0.001552 avg: 0.000112
min : 0.000108 max: 0.003923 avg: 0.000118
min : 0.000108 max: 0.000514 avg: 0.000111

4. with some more applications removed.

# pidin a
     pid Arguments
       1 procnto
    4101 devc-pty
  253981 io-net
  512031 inetd
 1650743 inetd
 1687608 in.telnetd
 1691705 -l
 1724476 sh
 3235899 inetd
 4923394 ./server
 4935683 pidin a
# ./client
This system has 16666666 cycles/sec.
min : 0.000108 max: 0.000332 avg: 0.000110
min : 0.000108 max: 0.000201 avg: 0.000110
min : 0.000108 max: 0.003475 avg: 0.000113
min : 0.000108 max: 0.000406 avg: 0.000110
min : 0.000108 max: 0.003472 avg: 0.000115
min : 0.000108 max: 0.001554 avg: 0.000113
min : 0.000108 max: 0.003921 avg: 0.000117
min : 0.000108 max: 0.000515 avg: 0.000110
min : 0.000108 max: 0.000138 avg: 0.000110
min : 0.000108 max: 0.000138 avg: 0.000110
min : 0.000108 max: 0.000510 avg: 0.000110
min : 0.000108 max: 0.000199 avg: 0.000110
min : 0.000108 max:...
View Full Message
Robert Craig
04/13/2009 9:51 AM
post26761
RE: RE: Expected latency values for MsgSend ?   
Hi Ashwin:
	Make sure that you have the "on" utility on your target.

# on -p 255 ./server &
# on -p 255 ./client

	R.


-----Original Message-----
From: Ashwin Patwekar [mailto:community-noreply@qnx.com] 
Sent: Monday, April 13, 2009 3:04 AM
To: ostech-core_os
Subject: Re: RE: Expected latency values for MsgSend ?

Hi,

Here are the new times observed using ClockCycles. The times are
averaged for 1000 readings and in between each msgsend there is a delay
of 2ms.  

Comparing readings 1&3 or 1&4 it is seen that the minimum and maximum
and the average times have reduced when the number of applications
reduced.  
But still there are ocassional peaks even with minimum applications
running which cause the peaks of more than 3ms not sure what might be
causing these.

Thanks and Regards,
Ashwin

1. With full load all applications running # pidin info CPU:PPC
Release:6.3.0  FreeMem:11Mb/64Mb BootTime:Apr 13 11:17:40 UTC 2009
Processor1: 80822014 8280 266MHz FPU

# ./client
This system has 16666666 cycles/sec.
min : 0.000121 max: 0.003908 avg: 0.000184 min : 0.000121 max: 0.003959
avg: 0.000158 min : 0.000120 max: 0.004039 avg: 0.000179 min : 0.000120
max: 0.001864 avg: 0.000176 min : 0.000120 max: 0.011469 avg: 0.000234
min : 0.000121 max: 0.001059 avg: 0.000146 min : 0.000120 max: 0.003958
avg: 0.000189 min : 0.000121 max: 0.001824 avg: 0.000177 min : 0.000121
max: 0.001973 avg: 0.000177 min : 0.000120 max: 0.003884 avg: 0.000154
min : 0.000120 max: 0.003505 avg: 0.000179 min : 0.000121 max: 0.005044
avg: 0.000183 min : 0.000120 max: 0.003924 avg: 0.000188

2. with applciations not running only drivers loaded.
# pidin info
CPU:PPC Release:6.3.0  FreeMem:30Mb/64Mb BootTime:Apr 13 11:17:40 UTC
2009
Processor1: 80822014 8280 266MHz FPU

# ./client
This system has 16666666 cycles/sec.
min : 0.000117 max: 0.003990 avg: 0.000143 min : 0.000117 max: 0.003912
avg: 0.000141 min : 0.000116 max: 0.000227 avg: 0.000134 min : 0.000116
max: 0.003933 avg: 0.000142 min : 0.000116 max: 0.003940 avg: 0.000138
min : 0.000116 max: 0.003940 avg: 0.000138 min : 0.000116 max: 0.003932
avg: 0.000139 min : 0.000117 max: 0.000596 avg: 0.000135 min : 0.000111
max: 0.000587 avg: 0.000134 min : 0.000116 max: 0.000644 avg: 0.000136
min : 0.000117 max: 0.003578 avg: 0.000140 min : 0.000116 max: 0.002560
avg: 0.000139


3. without any board drivers
# pidin a
     pid Arguments
       1 procnto
    4099 slogger
    4100 pipe
    4101 devc-pty
    4102 mqueue
    4103 random -i1 -i2
  253981 io-net
  512031 inetd
 1650743 inetd
 1687608 in.telnetd
 1691705 -l
 1724476 sh
 3235899 inetd
 4595714 ./server
 4665352 pidin a

# ./client
This system has 16666666 cycles/sec.
min : 0.000109 max: 0.003473 avg: 0.000115 min : 0.000109 max: 0.000138
avg: 0.000111 min : 0.000108 max: 0.000406 avg: 0.000111 min : 0.000108
max: 0.001553 avg: 0.000114 min : 0.000108 max: 0.003923 avg: 0.000118
min : 0.000108 max: 0.000514 avg: 0.000111 min : 0.000108 max: 0.000371
avg: 0.000111 min : 0.000108 max: 0.000137 avg: 0.000110 min : 0.000108
max: 0.000396 avg: 0.000111 min : 0.000108 max: 0.000512 avg: 0.000111
min : 0.000108 max: 0.003494 avg: 0.000114 min : 0.000108 max: 0.000405
avg: 0.000111 min : 0.000108 max: 0.003473 avg: 0.000115 min : 0.000108
max: 0.001552 avg: 0.000112 min : 0.000108 max: 0.003923 avg: 0.000118
min : 0.000108 max: 0.000514 avg: 0.000111

4. with some more applications removed.

# pidin a
     pid Arguments
       1 procnto
    4101 devc-pty
  253981 io-net
  512031 inetd
 1650743 inetd
 1687608 in.telnetd
 1691705 -l
 1724476 sh
 3235899 inetd
 4923394 ./server
 4935683 pidin a
# ./client
This system has 16666666 cycles/sec.
min : 0.000108 max: 0.000332 avg: 0.000110 min : 0.000108 max: 0.000201
avg: 0.000110 min : 0.000108 max: 0.003475 avg: 0.000113 min : 0.000108
max: 0.000406 avg: 0.000110 min : 0.000108 max: 0.003472 avg: 0.000115
min :...
View Full Message
Ashwin Patwekar
04/16/2009 5:43 AM
post27174
Re: RE: RE: Expected latency values for MsgSend ?   
Hi Robert,

Thanks for the reply. 

The priority changing did give consistent times.
This system has 16666666 cycles/sec.
min : 0.000110 max: 0.000141 avg: 0.000113
min : 0.000109 max: 0.000134 avg: 0.000113
min : 0.000110 max: 0.000144 avg: 0.000113
min : 0.000110 max: 0.000133 avg: 0.000113
min : 0.000110 max: 0.000134 avg: 0.000113
min : 0.000110 max: 0.000134 avg: 0.000113
min : 0.000109 max: 0.000132 avg: 0.000113
min : 0.000109 max: 0.000135 avg: 0.000113
min : 0.000110 max: 0.000133 avg: 0.000113
min : 0.000110 max: 0.000134 avg: 0.000113
min : 0.000110 max: 0.000133 avg: 0.000113
min : 0.000109 max: 0.000134 avg: 0.000113

without the -p option the timinigs w/o devn driver are 
# ./client
This system has 16666666 cycles/sec.
min : 0.000108 max: 0.000183 avg: 0.000111
min : 0.000108 max: 0.000177 avg: 0.000111
min : 0.000108 max: 0.000181 avg: 0.000111
min : 0.000108 max: 0.000191 avg: 0.000111
min : 0.000108 max: 0.000176 avg: 0.000111
min : 0.000108 max: 0.000177 avg: 0.000111
min : 0.000108 max: 0.000183 avg: 0.000112
min : 0.000108 max: 0.000181 avg: 0.000111
min : 0.000108 max: 0.000178 avg: 0.000111
min : 0.000108 max: 0.000184 avg: 0.000111
min : 0.000108 max: 0.000190 avg: 0.000111
min : 0.000108 max: 0.000183 avg: 0.000112

So the issue seems to be in the devn driver for the hardware which is different from the devn driver for FADS.

Thanks and Regards,
Ashwin
Robert Craig
04/16/2009 9:24 AM
post27210
RE: RE: RE: Expected latency values for MsgSend ?   
Hi Ashwin:
  I don't know if I'd call the devn behaviour an "issue".  It's a
network driver that's communicating with the network and uses CPU, so
it's perfectly normal (and, in fact, it's a requirement) for it to take
the CPU away from a process  that is running at a lower priority.

   Those numbers are looking a bit more reasonable though :>.

   Robert.

-----Original Message-----
From: Ashwin Patwekar [mailto:community-noreply@qnx.com] 
Sent: Thursday, April 16, 2009 5:44 AM
To: ostech-core_os
Subject: Re: RE: RE: Expected latency values for MsgSend ?

Hi Robert,

Thanks for the reply. 

The priority changing did give consistent times.
This system has 16666666 cycles/sec.
min : 0.000110 max: 0.000141 avg: 0.000113 min : 0.000109 max: 0.000134
avg: 0.000113 min : 0.000110 max: 0.000144 avg: 0.000113 min : 0.000110
max: 0.000133 avg: 0.000113 min : 0.000110 max: 0.000134 avg: 0.000113
min : 0.000110 max: 0.000134 avg: 0.000113 min : 0.000109 max: 0.000132
avg: 0.000113 min : 0.000109 max: 0.000135 avg: 0.000113 min : 0.000110
max: 0.000133 avg: 0.000113 min : 0.000110 max: 0.000134 avg: 0.000113
min : 0.000110 max: 0.000133 avg: 0.000113 min : 0.000109 max: 0.000134
avg: 0.000113

without the -p option the timinigs w/o devn driver are # ./client This
system has 16666666 cycles/sec.
min : 0.000108 max: 0.000183 avg: 0.000111 min : 0.000108 max: 0.000177
avg: 0.000111 min : 0.000108 max: 0.000181 avg: 0.000111 min : 0.000108
max: 0.000191 avg: 0.000111 min : 0.000108 max: 0.000176 avg: 0.000111
min : 0.000108 max: 0.000177 avg: 0.000111 min : 0.000108 max: 0.000183
avg: 0.000112 min : 0.000108 max: 0.000181 avg: 0.000111 min : 0.000108
max: 0.000178 avg: 0.000111 min : 0.000108 max: 0.000184 avg: 0.000111
min : 0.000108 max: 0.000190 avg: 0.000111 min : 0.000108 max: 0.000183
avg: 0.000112

So the issue seems to be in the devn driver for the hardware which is
different from the devn driver for FADS.

Thanks and Regards,
Ashwin


_______________________________________________
OSTech
http://community.qnx.com/sf/go/post27174
Ashwin Patwekar
04/16/2009 9:41 AM
post27218
Re: RE: RE: RE: Expected latency values for MsgSend ?   
Hi Robert,

I doubt the devn driver because
1. These delays are seen even when the network cable is disconnected when there is nothing to receive from or transmit 
to.
2. With the devn driver from the bsp the delays upto 3msec are absent.

So I guess it should be some hardware modification that is done on this board or the driver. 

Thanks and Regards,
Ashwin
Robert Craig
04/16/2009 9:44 AM
post27219
RE: RE: RE: RE: Expected latency values for MsgSend ?   
The devn driver likely also probes the PHY to check for a cable
connection (I think that the default is to do this once every 3
seconds).  This can be quite a slow process. You can confirm where the
CPU is going by running a kernel trace during your test.  I'm sure that
you'll find that the networking stack takes up a chunk of CPU
intermittently.

  R.

-----Original Message-----
From: Ashwin Patwekar [mailto:community-noreply@qnx.com] 
Sent: Thursday, April 16, 2009 9:42 AM
To: ostech-core_os
Subject: Re: RE: RE: RE: Expected latency values for MsgSend ?

Hi Robert,

I doubt the devn driver because
1. These delays are seen even when the network cable is disconnected
when there is nothing to receive from or transmit to.
2. With the devn driver from the bsp the delays upto 3msec are absent.

So I guess it should be some hardware modification that is done on this
board or the driver. 

Thanks and Regards,
Ashwin



_______________________________________________
OSTech
http://community.qnx.com/sf/go/post27218

Return


  A subsidiary of BlackBerry             All content ©2004-2013, QNX Software Systems