Gradle extremely slow HTTP resource access on Windows. How to diagnose and fix?

Deft_Developer · November 22, 2014, 9:22pm

Gradle 2.2 takes hours to build a project on Windows 7x64 that takes 8 minutes on Linux. When run with –debug, on the slow machine, gradle reports no errors, but it stops and waits for approx. 2 minutes at every resource, after every User-Agent line:

18:39:15.819 [DEBUG] [org.apache.http.headers] >> User-Agent: Gradle/2.0 (Windows 7;6.1;amd64) (Oracle Corporation;1.7.0_67;24.65-b04)
    <2 min. delay>
    18:41:15.527 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Receiving response: HTTP/1.1 200 OK
    18:41:15.527 [DEBUG] [org.apache.http.headers] << HTTP/1.1 200 OK

Linux workstations on the same subnet (behind the same firewall and using the same squid proxy) do not have this delay.

An Extended snip is here:

https://gist.github.com/Charlweed/6eb7640321f292dd2233

cmcginty · November 23, 2014, 10:20pm

I build on windows 7x64 VM all the time with no issues. I can only guess there is some configuration issue on the machine causing this. Have you tried snooping the network interface to get a packet capture?

Deft_Developer · November 23, 2014, 10:37pm

Thanks, but No, I have not. Using WireShark or other packet-sniffers is far down on my preferences. I’ll go there if I must, but I am hoping someone has a ready answer.

Deft_Developer · November 23, 2014, 10:37pm

Snip from Linux build around same place with no delay.

sterling · November 23, 2014, 11:37pm

Thanks.

From your Linux output, I don’t see any cache misses from your squid proxy. Is there a way to check that the proxies are working the same on both sides (Windows/Linux)? The other thing I notice is that requests that have “HIT from enterprise…” in the returning headers are fast and those with “MISS from enterprise…” are slow (2 minutes).

Deft_Developer · November 24, 2014, 11:05pm

This build log snip is from another Linux box called Intrepid This has cache misses, but no 2 min delay. Intrepid is dual boot, so I’ll try the same build on that while running Windows.

Deft_Developer · November 25, 2014, 11:20pm

I tried one of the delayed requests on cURL for Windows:

curl.exe -v -H "Connection: Keep-Alive" -H "Accept-Encoding: gzip,deflate" -A "Gradle/2.0 (Windows 7;6.1;amd64) (Oracle Corporation;1.7.0_67;24.65-b04)" http://repo1.maven.org/maven2/net/minecraftforge/gradle/ForgeGradle/1.2-SNAPSHOT‌ /ForgeGradle-1.2-SNAPSHOT.jar

The cURL gave no delay, it went right to a 404 error. This makes me think it is specific to gradle/maven/java somehow.

The stderr log from cURL.

sterling · November 26, 2014, 2:16pm

Thanks. Is there any logging you can look at on your proxy side to tell when the requests are being handled? The Date header looks strange (seems to bounce around 24 hours?). The X-Timer header does the same thing. Could the proxy’s time be wrong?

The Date header is coming from the server +2 minutes, so we need to eliminate that it’s not something between the client and server that’s waiting 2 minutes.

FAST (MISS, MISS, HIT, Date off)
18:31:15.615 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Sending request: HEAD /maven2/org/eclipse/equinox/preferences/3.5.200-v20140224-1527/preferences-3.5.200-v20140224-1527.jar HTTP/1.1
18:31:15.630 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Receiving response: HTTP/1.1 200 OK
18:31:15.677 [DEBUG] [org.apache.http.headers] << Date: Fri, 21 Nov 2014 01:03:03 GMT
18:31:15.693 [DEBUG] [org.apache.http.headers] << X-Cache: MISS, MISS
18:31:15.693 [DEBUG] [org.apache.http.headers] << X-Cache-Hits: 0, 0
18:31:15.708 [DEBUG] [org.apache.http.headers] << X-Cache: HIT from enterprise.localdomain.org
18:31:15.708 [DEBUG] [org.apache.http.headers] << X-Cache-Lookup: HIT from enterprise.localdomain.org:3128
  SLOW (HIT, HIT, MISS, Date current)
18:31:15.786 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Sending request: GET /maven2/org/eclipse/equinox/preferences/3.5.200-v20140224-1527/preferences-3.5.200-v20140224-1527.jar.sha1 HTTP/1.1
18:33:15.104 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Receiving response: HTTP/1.1 200 OK
18:33:15.135 [DEBUG] [org.apache.http.headers] << Date: Sat, 22 Nov 2014 02:33:15 GMT
18:33:15.151 [DEBUG] [org.apache.http.headers] << X-Cache: HIT, HIT
18:33:15.151 [DEBUG] [org.apache.http.headers] << X-Cache-Hits: 1, 1
18:33:15.166 [DEBUG] [org.apache.http.headers] << X-Cache: MISS from enterprise.localdomain.org
18:33:15.166 [DEBUG] [org.apache.http.headers] << X-Cache-Lookup: MISS from enterprise.localdomain.org:3128
  FAST (MISS, MISS, HIT, Date off)
18:33:15.338 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Sending request: HEAD /maven2/org/eclipse/osgi/3.10.0-v20140606-1445/osgi-3.10.0-v20140606-1445.jar HTTP/1.1
18:33:15.369 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Receiving response: HTTP/1.1 200 OK
18:33:15.400 [DEBUG] [org.apache.http.headers] << Date: Fri, 21 Nov 2014 01:03:04 GMT
18:33:15.416 [DEBUG] [org.apache.http.headers] << X-Cache: MISS, MISS
18:33:15.416 [DEBUG] [org.apache.http.headers] << X-Cache-Hits: 0, 0
18:33:15.432 [DEBUG] [org.apache.http.headers] << X-Cache: HIT from enterprise.localdomain.org
18:33:15.432 [DEBUG] [org.apache.http.headers] << X-Cache-Lookup: HIT from enterprise.localdomain.org:3128
  SLOW (HIT, HIT, MISS, Date current)
18:33:15.510 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Sending request: GET /maven2/org/eclipse/osgi/3.10.0-v20140606-1445/osgi-3.10.0-v20140606-1445.jar.sha1 HTTP/1.1
18:35:15.217 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Receiving response: HTTP/1.1 200 OK
18:35:15.248 [DEBUG] [org.apache.http.headers] << Date: Sat, 22 Nov 2014 02:35:15 GMT
18:35:15.264 [DEBUG] [org.apache.http.headers] << X-Cache: HIT, HIT
18:35:15.264 [DEBUG] [org.apache.http.headers] << X-Cache-Hits: 1, 1
18:35:15.264 [DEBUG] [org.apache.http.headers] << X-Cache: MISS from enterprise.localdomain.org
18:35:15.280 [DEBUG] [org.apache.http.headers] << X-Cache-Lookup: MISS from enterprise.localdomain.org:3128
  FAST (MISS, MISS, HIT, Date off)
18:35:15.467 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Sending request: HEAD /maven2/org/eclipse/core/jobs/3.6.0-v20140424-0053/jobs-3.6.0-v20140424-0053.jar HTTP/1.1
18:35:15.482 [DEBUG] [org.apache.http.impl.conn.DefaultClientConnection] Receiving response: HTTP/1.1 200 OK
18:35:15.529 [DEBUG] [org.apache.http.headers] << Date: Fri, 21 Nov 2014 01:03:04 GMT
18:35:15.545 [DEBUG] [org.apache.http.headers] << X-Cache: MISS, MISS
18:35:15.545 [DEBUG] [org.apache.http.headers] << X-Cache-Hits: 0, 0
18:35:15.560 [DEBUG] [org.apache.http.headers] << X-Cache: HIT from enterprise.localdomain.org
18:35:15.560 [DEBUG] [org.apache.http.headers] << X-Cache-Lookup: HIT from enterprise.localdomain.org:3128

Deft_Developer · December 1, 2014, 8:43pm

Nothing in my Squid log, Dan’s Guardian log, or any other service log,shows anything yet. Getting understandable logs from iptables is really hard, but is now on my to-do list. Please see for some of what I fave tried.

Deft_Developer · December 1, 2014, 9:25pm

<table

style=“border-collapse: collapse; table-layout: fixed; width: 353px;”

border=“0” cellpadding=“0” cellspacing=“0”>

Diagnostic attempts <td class="xl66" style="height: 15pt; width: 260pt;"

height=“20” width=“346”>

<td class="xl67"

style=“height: 15pt; width: 260pt; background-color: rgb(51, 255, 51);”>Using different Unix box.

works <td class="xl67"

style=“height: 15pt; width: 260pt; background-color: rgb(51, 255, 51);”>Using different Windows box.

works <td class="xl71"

style=“height: 15pt; width: 260pt; background-color: rgb(255, 255, 153);”>Changing IP address from 192.168.0.8 to 192.168.0.31.

worked briefly ??? <td class="xl68"

style=“height: 15pt; width: 260pt; background-color: white;”>Wiping all .gradle .m2 etc dirs from account.