Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

test 573 failing in original mingw #1531

Closed
jay opened this issue Jun 2, 2017 · 6 comments · Fixed by #1549
Closed

test 573 failing in original mingw #1531

jay opened this issue Jun 2, 2017 · 6 comments · Fixed by #1549

Comments

@jay
Copy link
Member

jay commented Jun 2, 2017 •
edited

I did this

./runtests.pl -p 573

fails during comparison of connect time:
connect time 0.000000e+000 is < epsilon 1.084202e-019

log

=== Start of file stderr573
 URL: http://127.0.0.1:8990/573
 00:12:14.380000 == Info: STATE: INIT => CONNECT handle 0xa4af18; line 1413 (connection #-5000)
 00:12:14.380000 == Info: Added connection 0. The cache now contains 1 members
 00:12:14.380000 == Info: timeout on name lookup is not supported
 00:12:14.380000 == Info:   Trying 127.0.0.1...
 00:12:14.380000 == Info: TCP_NODELAY set
 00:12:14.380000 == Info: STATE: CONNECT => WAITCONNECT handle 0xa4af18; line 1466 (connection #0)
 00:12:14.380000 == Info: Connected to 127.0.0.1 (127.0.0.1) port 8990 (#0)
 00:12:14.380000 == Info: STATE: WAITCONNECT => SENDPROTOCONNECT handle 0xa4af18; line 1583 (connection #0)
 00:12:14.380000 == Info: Marked for [keep alive]: HTTP default
 00:12:14.380000 == Info: STATE: SENDPROTOCONNECT => DO handle 0xa4af18; line 1601 (connection #0)
 00:12:14.380000 => Send header, 56 bytes (0x38)
 0000: GET /573 HTTP/1.1
 0013: Host: 127.0.0.1:8990
 0029: Accept: */*
 0036:
 00:12:14.380000 == Info: STATE: DO => DO_DONE handle 0xa4af18; line 1680 (connection #0)
 00:12:14.380000 == Info: STATE: DO_DONE => WAITPERFORM handle 0xa4af18; line 1807 (connection #0)
 00:12:14.380000 == Info: STATE: WAITPERFORM => PERFORM handle 0xa4af18; line 1817 (connection #0)
 00:12:14.380000 == Info: HTTP 1.1 or later with persistent connection, pipelining supported
 00:12:14.380000 <= Recv header, 17 bytes (0x11)
 0000: HTTP/1.1 200 OK
 00:12:14.380000 <= Recv header, 37 bytes (0x25)
 0000: Date: Thu, 09 Nov 2010 14:49:00 GMT
 00:12:14.380000 == Info: Server test-server/fake is not blacklisted
 00:12:14.380000 <= Recv header, 26 bytes (0x1a)
 0000: Server: test-server/fake
 00:12:14.380000 <= Recv header, 46 bytes (0x2e)
 0000: Last-Modified: Tue, 13 Jun 2000 12:10:00 GMT
 00:12:14.380000 <= Recv header, 28 bytes (0x1c)
 0000: ETag: "21025-dc7-39462498"
 00:12:14.380000 <= Recv header, 22 bytes (0x16)
 0000: Accept-Ranges: bytes
 00:12:14.380000 <= Recv header, 19 bytes (0x13)
 0000: Content-Length: 6
 00:12:14.380000 == Info: Marked for [closure]: Connection: close used
 00:12:14.380000 <= Recv header, 19 bytes (0x13)
 0000: Connection: close
 00:12:14.380000 <= Recv header, 25 bytes (0x19)
 0000: Content-Type: text/html
 00:12:14.380000 <= Recv header, 20 bytes (0x14)
 0000: Funny-head: yesyes
 00:12:14.380000 <= Recv header, 2 bytes (0x2)
 0000:
 00:12:14.380000 <= Recv data, 6 bytes (0x6)
 0000: -foo-.
 00:12:14.380000 == Info: STATE: PERFORM => DONE handle 0xa4af18; line 1991 (connection #0)
 00:12:14.380000 == Info: multi_done
 00:12:14.380000 == Info: Closing connection 0
 00:12:14.380000 == Info: The cache now contains 0 members
 connect time 0.000000e+000 is < epsilon 1.084202e-019
 00:12:14.380000 == Info: Expire cleared
=== End of file stderr573

curl/libcurl version

********* System characteristics ********
* curl 7.54.0 (i686-pc-mingw32)
* libcurl/7.54.0 OpenSSL/1.0.2l zlib/1.2.11 nghttp2/1.23.1
* Features: Debug TrackMemory Largefile SSPI Kerberos SPNEGO NTLM SSL libz TLS-SRP HTTP2 HTTPS-proxy
* Host: COMPUTER
* System: MINGW32_NT-6.1 [removed] 1.0.17(0.48/3/2) 2011-04-24 23:39 i686 Msys
* Servers: SSL
* Env:
*****************************************

operating system

Windows 7 x64 Enterprise
@bagder
Copy link
Member

bagder commented Jun 2, 2017

Oops. With only millisecond resolution on the timer and everything happening within that single millisecond, the connect time is (correctly) evaluated to be zero... which the test doesn't like. A connect is supposed to take at least a tiny amount of time! =)

One (lame) way to fix this could be to have Curl_pgrsTime automatically add a microsecond to a connect time that is evaluated to 0.

A better way would probably be to use a timer on windows with better resolution...

@jay
Copy link
Member Author

jay commented Jun 5, 2017

A better way would probably be to use a timer on windows with better resolution...

Setting a timer resolution smaller than the default in Windows (usually 15ms, Server versions may differ) will set it for all programs and also increases battery drain. There is a way to get RDTSC in Windows (Query Performance Counter API) however that will vary with processor speed I believe so for example you take a measurement and then the processor speed changes and changes back before you take another measurement, I don't think it's accurate for telling time in a case like that (I'm thinking SpeedStep, maybe I'm wrong).

@MarcelRaad
Copy link
Member

@jay According to the QueryPerformanceFrequency documentation, "the frequency of the performance counter is fixed at system boot."
I haven't encountered any problems with it since Windows Vista / Server 2008. But on Server 2003 with multiple CPUs and XP with some older hardware, it's more or less a random number generator if you don't bind your thread to a specific logical CPU.

@bagder
Copy link
Member

bagder commented Jun 5, 2017

If a sub-15-millisecond timer is a problem, then I think I favor my first suggestion: we change the internal time stamps to count microseconds and then we can just add a microsecond or something if it seems to store a zero elapsed time.

@jay
Copy link
Member Author

jay commented Jun 6, 2017

@MarcelRaad thanks. I just finished reading Windows documentation Acquiring high-resolution time stamps which I recommend to anyone who wants to know more about this.

bagder added a commit that referenced this issue Jun 7, 2017
@bagder
timers: store internal time stamps as time_t instead of doubles
d100a65 
This gives us accurate precision and it allows us to avoid storing "no
time" for systems with too low timer resolution as we then bump the time
up to 1 microsecond. Should fix test 573 on windows.

Remove the now unused curlx_tvdiff_secs() function.

Maintains the external getinfo() API with using doubles.

Fixes #1531
@bagder bagder mentioned this issue Jun 7, 2017
Merged
@bagder
Copy link
Member

bagder commented Jun 7, 2017

So #1549 is basically my take at the approach I mentioned.

bagder added a commit that referenced this issue Jun 14, 2017
@bagder
timers: store internal time stamps as time_t instead of doubles
adef394 
This gives us accurate precision and it allows us to avoid storing "no
time" for systems with too low timer resolution as we then bump the time
up to 1 microsecond. Should fix test 573 on windows.

Remove the now unused curlx_tvdiff_secs() function.

Maintains the external getinfo() API with using doubles.

Fixes #1531
@lock lock bot locked as resolved and limited conversation to collaborators May 6, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

timers: store internal time stamps as time_t instead of doubles curl/curl
3 participants
@bagder @jay @MarcelRaad