"gettimeofday" problem

[aotto1968]

Hi,

I have a problem with the resolution of the "gettimeofday" function

1. my environment:

Linux athlon 500 MHz
Interix Win XP AMD 1400 MHz

2. what I have done:
- I measure the time of a transaction at different measurement points.
- the transaction is a communication flow from one process to an other
process and the way back.
- the code and the build environment is IDENTICAL. this was the reason
to use Interix as platform

3. a measurement point is the the time for:
a) creating the message (first process)
b) sending the message (first process)
c) parsing the header (second process)
d) parsing the body (second process)
e) sending the answer (second process)
f) parsing the header (first process)
g) parsing the body (first process)
h) finish the transaction (first process)

4. now the results:

LINUX
-----

M> M [0- 0x808ec98- StatCtxCalc]: SEND: tv_sec<1082356994>, tv_usec<984416>
S> M [0- 0x804a8e0- StatCtxCalc]: HEADER: tv_sec<1082356994>, tv_usec<985825>
S> M [0- 0x804a8e0- StatCtxCalc]: BODY: tv_sec<1082356994>, tv_usec<986907>
S> M [0- 0x804a8e0- StatCtxCalc]: SEND: tv_sec<1082356994>, tv_usec<987967>
M> M [0- 0x808ec98- StatCtxCalc]: HEADER: tv_sec<1082356994>, tv_usec<988818>
M> M [0- 0x808ec98- StatCtxCalc]: BODY: tv_sec<1082356994>, tv_usec<989637>
M> M [0- 0x808ec98- StatCtxCalc]: FINAL: tv_sec<1082356994>, tv_usec<991224>
8196 microseconds per iteration
S> M [1- 0x804a8e0- statistics]: HEADER: 1434.00
S> M [1- 0x804a8e0- statistics]: BODY: 2516.00
S> M [1- 0x804a8e0- statistics]: SEND: 3576.00
M> M [1- 0x808ec98- statistics]: SEND: 25.00
M> M [1- 0x808ec98- statistics]: HEADER: 4427.00
M> M [1- 0x808ec98- statistics]: BODY: 5246.00
M> M [1- 0x808ec98- statistics]: FINAL: 6833.00

INTERIX
-------

M> M [0- 0x180ed8- StatCtxCalc]: SEND: tv_sec<1082357033>, tv_usec<266049>
S> M [0- 0x1246b0- StatCtxCalc]: HEADER: tv_sec<1082357033>, tv_usec<276064>
S> M [0- 0x1246b0- StatCtxCalc]: BODY: tv_sec<1082357033>, tv_usec<276064>
S> M [0- 0x1246b0- StatCtxCalc]: SEND: tv_sec<1082357033>, tv_usec<276064>
M> M [0- 0x180ed8- StatCtxCalc]: HEADER: tv_sec<1082357033>, tv_usec<276064>
M> M [0- 0x180ed8- StatCtxCalc]: BODY: tv_sec<1082357033>, tv_usec<276064>
M> M [0- 0x180ed8- StatCtxCalc]: FINAL: tv_sec<1082357033>, tv_usec<276064>
10015 microseconds per iteration
S> M [1- 0x1246b0- statistics]: HEADER: 10015.00
S> M [1- 0x1246b0- statistics]: BODY: 10015.00
S> M [1- 0x1246b0- statistics]: SEND: 10015.00
M> M [1- 0x180ed8- statistics]: SEND: 0.00
M> M [1- 0x180ed8- statistics]: HEADER: 10015.00
M> M [1- 0x180ed8- statistics]: BODY: 10015.00
M> M [1- 0x180ed8- statistics]: FINAL: 10015.00


5. what does we see ?
a) the linux part has a timer-resolution, Interix not
b) the linux part is faster even on a 3 times slower CPU


mfg

aotto

[rodney]

You state the data appears to not be reliable. Accepting this means
the 10015 u-sec and the processing times can't be taken as valid either.
So a conclusion about it being slower or not can't be made yet.
The logic must be maintained :-)
With "bad" data you cannot make "good" conclusions.

The fact that "10015" appears in the lower half of the data can lead me
to believe that the code for calculating it is flawed because the "raw"
usec's above _should_ produce "10015" for the HEADER and then "0" for
the rest. My hand calculation for the Linux box is "6808" not "8196".
So something is out there too by the looks of it.

The NT scheduling works very well switching the context from one process
to the next as quantums are released. With the above there appears to be
a fair bit of cascading with your two processes and the Interix subsystem.
This is ideal for things getting done in a short time period as the scheduler
uses the LPC's as guidance (particularly if this is solely a CPU/memory
bound set of processes).
The NT kernel actually measures things in smaller granularity than usec's.
So it is possible that everything is getting done very quickly. The CPU
should be quick at 1.4Ghz.

So to me it looks like the initial SEND took a long time and everything
else happened in nearly no time at all. And that can relate to how you get
the processes started and how the binary image was made. Because you have
the same build script doesn't mean the results of the build are comparable.
I don't know what the default actions are on the Linux box for 'gcc' but
they may not match the default actions for 'gcc' on Interix. And ditto for
libraries linked to.

So you may want to try a build where the linking specifies a "static"
link and that the binary gets stripped for a run-time comparison.
And the code calculating the time deltas needs to be checked too.

[aotto1968]

Hi,

>>>>>>>>>
You state the data appears to not be reliable. Accepting this means
the 10015 u-sec and the processing times can't be taken as valid either.
So a conclusion about it being slower or not can't be made yet.
The logic must be maintained :-)
With "bad" data you cannot make "good" conclusions.
<<<<<<<

bad? why you think the data is bad ...
in fact the input data is identical for Linux und Interix
=> everything is bad or nothing is bad ....
in fact the data is NOT bad - I know what I do and I'm not
a UNIX starter or something else

>>>>>>>>>
The fact that "10015" appears in the lower half of the data can lead me
to believe that the code for calculating it is flawed because the "raw"
usec's above _should_ produce "10015" for the HEADER and then "0" for
the rest. My hand calculation for the Linux box is "6808" not "8196".
So something is out there too by the looks of it.
<<<<<<<<<

just to be clear, the result have to be sorted, this means ..

S> M [1- 0x1246b0- statistics]: HEADER: 10015.00
S> M [1- 0x1246b0- statistics]: BODY: 10015.00
S> M [1- 0x1246b0- statistics]: SEND: 10015.00
M> M [1- 0x180ed8- statistics]: SEND: 0.00
M> M [1- 0x180ed8- statistics]: HEADER: 10015.00
M> M [1- 0x180ed8- statistics]: BODY: 10015.00
M> M [1- 0x180ed8- statistics]: FINAL: 10015.00

will be ... M=Master, S=Slave

M> M [1- 0x180ed8- statistics]: SEND: 0.00
S> M [1- 0x1246b0- statistics]: HEADER: 10015.00
S> M [1- 0x1246b0- statistics]: BODY: 10015.00
S> M [1- 0x1246b0- statistics]: SEND: 10015.00
M> M [1- 0x180ed8- statistics]: HEADER: 10015.00
M> M [1- 0x180ed8- statistics]: BODY: 10015.00
M> M [1- 0x180ed8- statistics]: FINAL: 10015.00

to get the right time-scale

>>>>>>>>>>
So to me it looks like the initial SEND took a long time and everything
else happened in nearly no time at all. And that can relate to how you get
the processes started and how the binary image was made. Because you have
the same build script doesn't mean the results of the build are comparable.
I don't know what the default actions are on the Linux box for 'gcc' but
they may not match the default actions for 'gcc' on Interix. And ditto for
libraries linked to.
<<<<<<<<<<

well not rigth (an other try gives an other result ...

10014 microseconds per iteration
S> M [1- 0x1244a0- statistics]: HEADER: 0.00
S> M [1- 0x1244a0- statistics]: BODY: 0.00
S> M [1- 0x1244a0- statistics]: SEND: 0.00
M> M [1- 0x17d478- statistics]: SEND: 0.00
M> M [1- 0x17d478- statistics]: HEADER: 10014.00
M> M [1- 0x17d478- statistics]: BODY: 10014.00
M> M [1- 0x17d478- statistics]: FINAL: 10014.00

-> the big jump is now at the second HEADER parsing

>>>>>>>>>>>><
The NT scheduling works very well switching the context from one process
to the next as quantums are released. With the above there appears to be
a fair bit of cascading with your two processes and the Interix subsystem.
This is ideal for things getting done in a short time period as the scheduler
uses the LPC's as guidance (particularly if this is solely a CPU/memory
bound set of processes).
The NT kernel actually measures things in smaller granularity than usec's.
So it is possible that everything is getting done very quickly. The CPU
should be quick at 1.4Ghz.
<<<<<<<<<<<<<

nice to know, but in fact I missing the results for my small easy application


just to be clear ...
the Interix with 1400 MHs is significant slower than a 500 MHz Linux
the question is where to start for analysing the problem ...

1) my code-base (the code I provide) is IDENTICAL on both machines ..
2) the "gettimeofday" problem is real because you see in the first
part of the Interix results that the call to "gettimeofday"
give always the same time back ...

M> M [0- 0x180ed8- StatCtxCalc]: SEND: tv_sec<1082357033>, tv_usec<266049>
S> M [0- 0x1246b0- StatCtxCalc]: HEADER: tv_sec<1082357033>, tv_usec<276064> < S> M [0- 0x1246b0- StatCtxCalc]: BODY: tv_sec<1082357033>, tv_usec<276064>
S> M [0- 0x1246b0- StatCtxCalc]: SEND: tv_sec<1082357033>, tv_usec<276064>
M> M [0- 0x180ed8- StatCtxCalc]: HEADER: tv_sec<1082357033>, tv_usec<276064>
M> M [0- 0x180ed8- StatCtxCalc]: BODY: tv_sec<1082357033>, tv_usec<276064>
M> M [0- 0x180ed8- StatCtxCalc]: FINAL: tv_sec<1082357033>, tv_usec<276064>

on linux you get for every call something back which useable difference

M> M [0- 0x808ec98- StatCtxCalc]: SEND: tv_sec<1082356994>, tv_usec<984416>
S> M [0- 0x804a8e0- StatCtxCalc]: HEADER: tv_sec<1082356994>, tv_usec<985825>
S> M [0- 0x804a8e0- StatCtxCalc]: BODY: tv_sec<1082356994>, tv_usec<986907>
S> M [0- 0x804a8e0- StatCtxCalc]: SEND: tv_sec<1082356994>, tv_usec<987967>
M> M [0- 0x808ec98- StatCtxCalc]: HEADER: tv_sec<1082356994>, tv_usec<988818>
M> M [0- 0x808ec98- StatCtxCalc]: BODY: tv_sec<1082356994>, tv_usec<989637>
M> M [0- 0x808ec98- StatCtxCalc]: FINAL: tv_sec<1082356994>, tv_usec<991224>

you should just compare the "tv_usec" part -> clear !!

3) I have a test tool for testing performance and function
a) the function test is OK, this mean I get identical OUTPUT for identical INPUT
b) the performance test is not OK, Interix is to slow

4) both processes communicate with FIFO's ....
is something known about FIFO problems ?

5) is it possible to adjust the priority od the whole unix subsystem?

6) I use an additional performance test tool
(called tclbench to measure the performance of tcl)

the results are interesting:

1) in general Interix(1400MHz) is ~ 5 times FASTER than Linux(500MHz)
2) but always is the filesystem is involved Interix(1440MHz) is
5 times slower than Linux(500MHz)

here the results ....

LINUX
=====

046 ENC iso2022-jp, gets 909
047 ENC iso2022-jp, read 664
048 ENC iso2022-jp, read & size 772
049 ENC iso8859-2, gets 794
050 ENC iso8859-2, read 593
051 ENC iso8859-2, read & size 724

081 FILE glob tmpdir (60 entries) 581
082 FILE glob / all subcommands 46103
083 FILE glob / atime 3689
084 FILE glob / attributes 27840
085 FILE glob / dirname 2336
086 FILE glob / executable 3670
087 FILE glob / exists 3557
088 FILE glob / extension 1304
089 FILE glob / isdirectory 3725
090 FILE glob / isfile 3623
091 FILE glob / mtime 3664
092 FILE glob / owned 3784
093 FILE glob / readable 3516
094 FILE glob / rootname 1320
095 FILE glob / size 3690
096 FILE glob / tail 1850
097 FILE glob / writable 3572

Interix
=======

046 ENC iso2022-jp, gets 2337
047 ENC iso2022-jp, read 2337
048 ENC iso2022-jp, read & size 2671
049 ENC iso8859-2, gets 2671
050 ENC iso8859-2, read 2337
051 ENC iso8859-2, read & size 2337

081 FILE glob tmpdir (60 entries) 2303
082 FILE glob / all subcommands 361119
083 FILE glob / atime 123377
084 FILE glob / attributes 272892
085 FILE glob / dirname 3305
086 FILE glob / executable 123077
087 FILE glob / exists 120573
088 FILE glob / extension 3004
089 FILE glob / isdirectory 124279
090 FILE glob / isfile 124279
091 FILE glob / mtime 125080
092 FILE glob / owned 124479
093 FILE glob / readable 120573
094 FILE glob / rootname 3004
095 FILE glob / size 124179
096 FILE glob / tail 3104
097 FILE glob / writable 120473

well my application uses a "fifo" with "fread" and "fwrite"
to get the work done !!! this is IO


mfg

aotto

[rodney]

My point about tv_usec was that it was likely that things are
happening fast enough that it didn't change (when the tv_usec
values were the same).

You have done some additional tests. In short I think you are saying
that Interix is working fine as you measure it except when a FIFO is
used as the means of communications, right?

So focusing on the FIFO part seems key.
I don't currently know of a problem with FIFO's.

The priority of the Interix subsystem cannot be changed and shouldn't
be changed. It's set to run at the same priority as CSRSS (the Win32
subsystem). When I set the priority level for the subsystem anything
higher started to make the overall system start behaving odd. But that's
a whole other discussion.

Back to the FIFO's:
It does appear that something is "jamming" (yeah, wonderful
technical word) after going fine for a bit.
When you do reads and writes what are the sizes used ?
Is your program using pthreads or locks at all ?

[aotto1968]

Hi,

>>>>>>>>>>>>>>>>>>>>><
My point about tv_usec was that it was likely that things are
happening fast enough that it didn't change (when the tv_usec
values were the same).
<<<<<<<<<<<<<<<<<<<<<

my initial posting says that:
Linux has -> 8196 microseconds per iteration
Interix has -> 10015 microseconds per iteration

Linux: 8196 microseconds -> 7 different timestamps
Interix: 10015 microseconds -> 2 different timestamps at 7 different
measurment-points

Interix needs longer (this is just the feeling too) but produces
less different timestamps.
for it looks like the timer-thread does only get fired from time
to time ->

ADDITIONAL->test

>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
#include
#include
#include <sys/time.h>

int main(int argc, char** argv)
{
struct timeval tv;
int i;
int max = atoi(argv[1]);

for (i=0; i gettimeofday(&tv, NULL);
printf("%li, %li\n", tv.tv_sec, tv.tv_usec);
}
exit(EXIT_SUCCESS);
}
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

Results on Linux(500MHz):
> time ./gettimeofday 10
1082442661, 276088
1082442661, 276238
1082442661, 276248
1082442661, 276257
1082442661, 276265
1082442661, 276273
1082442661, 276281
1082442661, 276289
1082442661, 276297
1082442661, 276305

real 0m0.003s
user 0m0.002s
sys 0m0.001s

> time ./gettimeofday 10
1082442602, 564104
1082442602, 564104
1082442602, 564104
1082442602, 564104
1082442602, 564104
1082442602, 564104
1082442602, 564104
1082442602, 564104
1082442602, 564104
1082442602, 564104

real 0m0.030s
user 0m0.020s
sys 0m0.030s

Results on Interix(1400MHz)

What does we see ?

1) realtime on Interix is 10 times realtime on Linux
2) usertime on Interix is 20 times usertime on Linux
3) systime on Interix is 30 times systime on Linux
4) tv_usec does not change !!!!!!!!!!!!!!!!!!!!!!
5)

LINUX
> time ./gettimeofday 100000 > /tmp/xx

real 0m0.351s
user 0m0.256s
sys 0m0.083s

INTERIX
> time ./gettimeofday 100000 > /tmp/xx

real 0m0.290s
user 0m0.291s
sys 0m0.020s

if I do an loop (100000 times) just to see how often I have
to loop to get a change of gettimeofday

Interix: 3421, 3632, 3541, 3597 .. (remember 1400 MHz)
Linux: every line

Results: on Interix the timer get fired every ~0.01 seconds

>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Back to the FIFO's:
It does appear that something is "jamming" (yeah, wonderful
technical word) after going fine for a bit.
When you do reads and writes what are the sizes used ?
Is your program using pthreads or locks at all ?
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

1) sizes used: ~100 bytes message-len
2) no locks, no pthreads


(M)aster -> FIFO -> (S)lave
fwrite (100B) -> FIFO -> fread Header (80B) fread Body (20B)
and all the way back


mfg

aotto

[rodney]

So no locks and no p-threads. The messages are small
enough that the FIFO queue is not exceeded. That elimates those
items as potential sources.

The test program you included above I took and modified to "play"
with it some more. I added a "sleep(1)" call and then changed it to
a "usleep(10000)". Definately something odd happening. Doing the test
with usleep() is important since it can dial in fractions of a second
which should force tv_usec to be different even if the system is really
fast. I went back to Interix 3.0 and ran the code as a comparison.

When I ran the code with sleep() the output was as expected: tv_sec
changed by 1 second each call.
When I ran the code with usleep() on 3.5 the result was wrong.
When I ran it on 3.0 with usleep() the answer is right.
Someone broke something with the 3.5 release. I don't know how since
the gettimeofday() code is very short.

I'm going to go find out if I can. To complicate things the 3.5 release
for download is supposed to have been updated yesterday with fixes.
But there's no indication an update has happened (like a list of fixes).

[rodney]

The update for the download of SFU 3.5 is a patch for the installation
of SFU to work after a system has applied XP's SP2.
So no help miraculously arriving just-in-time.
I'll send a bug report on this and see what happens.

[aotto1968]

Hi,

I investigate the fifo problem :

1. I wrote a test-tool to isolate the fifo related problem
2. I send the source of the tool as an attachment to you
3. the tool compiles on Interix and Linux
4. what does the tool do?

a) the tool has 2 independent programs
"master.run" (M) and "slave.run" (S)
b) M creates two fifo's, one for read ®
and one for write (W)
c) M starts S
d) M and S open the fifos
e) M write a 101 character message to W
f) S read the message form W
g) S write the message to R
h) M read the message from R
i) this "transaction" will be n times repeated

5. first the data

LINUX(500MHz)
-----

dev1usr@linux02:fifotest> time ./master.run 10000
M> MSG start master
S> MSG start slave
FINISH

real 0m0.296s
user 0m0.076s
sys 0m0.069s

INTERIX(1400MHz)
-------

dev1usr@win01:fifotest> time ./master.run 10000
M> MSG start master
S> MSG start slave
FINISH

real 0m1.052s
user 0m0.120s
sys 0m0.611s


mfg

aotto

[aotto1968]

Hi,

question? how can I send and email with attachment to you?


mfg

aotto

[rodney]

Yes you can send an attachment.