2 Replies Latest reply: Sep 12, 2012 7:17 AM by René van Wijk RSS

    Weblogic slow to respond on 304 requests

    961385
      Our setup, using Apache 2.2 and the weblogic module has a strange problem:

      When loading CSS and JS DIRECTLY from the Weblogic server the resource loads immediately.

      When loading the CSS / JS via the web server we get the timings below. The first load is immediate, but subsequent loads take about 30 seconds:

      Clear browser cache (loads with status 200)
      ================New Request: [GET /test/css/style.css HTTP/1.1] =================
      Tue Sep 11 13:09:21 2012 <921813473689618> INFO: SSL is not configured
      Tue Sep 11 13:09:21 2012 <921813473689618> Using Uri /test/css/style.css
      Tue Sep 11 13:09:21 2012 <921813473689618> After trimming path: '/test/css/style.css'
      Tue Sep 11 13:09:21 2012 <921813473689618> The final request string is '/test/css/style.css'
      Tue Sep 11 13:09:21 2012 <921813473689618> SEARCHING id=[x.x.x.x:7001] from current ID=[x.x.x.x:7001]
      Tue Sep 11 13:09:21 2012 <921813473689618> Host extracted from serverlist is [x.x.x.x]
      Tue Sep 11 13:09:21 2012 <921813473689618> Initializing lastIndex=0 for a list of length=1
      Tue Sep 11 13:09:21 2012 <921813473689618> getListNode: created a new server node: id='x.x.x.x:7001' server_name='y.y.y.y', port='443'
      Tue Sep 11 13:09:21 2012 <921813473689618> attempt #0 out of a max of 5
      Tue Sep 11 13:09:21 2012 <921813473689618> Trying a pooled connection for 'x.x.x.x/7001/7001'
      Tue Sep 11 13:09:21 2012 <921813473689618> getPooledConn: No more connections in the pool for Host[x.x.x.x] Port[7001] SecurePort[7001]
      Tue Sep 11 13:09:21 2012 <921813473689618> general list: trying connect to 'x.x.x.x'/7001/7001 at line 2619 for '/test/css/style.css'
      Tue Sep 11 13:09:21 2012 <921813473689618> INFO: New NON-SSL URL
      Tue Sep 11 13:09:21 2012 <921813473689618> Connect returns -1, and error no set to 115, msg 'Operation now in progress'
      Tue Sep 11 13:09:21 2012 <921813473689618> EINPROGRESS in connect() - selecting
      Tue Sep 11 13:09:21 2012 <921813473689618> Local Port of the socket is 37638
      Tue Sep 11 13:09:21 2012 <921813473689618> Remote Host x.x.x.x Remote Port 7001
      Tue Sep 11 13:09:21 2012 <921813473689618> general list: created a new connection to 'x.x.x.x'/7001 for '/test/css/style.css', Local port:37638
      Tue Sep 11 13:09:22 2012 <921813473689618> URL::parseHeaders: CompleteStatusLine set to [HTTP/1.1 200 OK]
      Tue Sep 11 13:09:22 2012 <921813473689618> URL::parseHeaders: StatusLine set to [200 OK]
      Tue Sep 11 13:09:22 2012 <921813473689618> parsed all headers OK
      Tue Sep 11 13:09:22 2012 <921813473689618> sendResponse() : r->status = '200'
      Tue Sep 11 13:09:22 2012 <921813473689618> for x.x.x.x/7001/7001, updated JVMID: 912614583
      Tue Sep 11 13:09:22 2012 <921813473689618> canRecycle: conn=1 status=200 isKA=1 clen=37845 isCTE=0
      Tue Sep 11 13:09:22 2012 <921813473689618> closeConn: pooling for 'x.x.x.x/7001'
      Tue Sep 11 13:09:22 2012 <921813473689618> request [test/css/style.css] processed sucessfully..................

      Reload directly after first load:
      Tue Sep 11 13:08:05 2012 <921713473688856> INFO: SSL is not configured
      Tue Sep 11 13:08:05 2012 <921713473688856> Using Uri /test/css/style.css
      Tue Sep 11 13:08:05 2012 <921713473688856> After trimming path: '/test/css/style.css'
      Tue Sep 11 13:08:05 2012 <921713473688856> The final request string is '/test/css/style.css'
      Tue Sep 11 13:08:05 2012 <921713473688856> SEARCHING id=[x.x.x.x:7001] from current ID=[x.x.x.x:7001]
      Tue Sep 11 13:08:05 2012 <921713473688856> Host extracted from serverlist is [x.x.x.x]
      Tue Sep 11 13:08:05 2012 <921713473688856> Initializing lastIndex=0 for a list of length=1
      Tue Sep 11 13:08:05 2012 <921713473688856> getListNode: created a new server node: id='x.x.x.x:7001' server_name='y.y.y.y', port='443'
      Tue Sep 11 13:08:05 2012 <921713473688856> attempt #0 out of a max of 5
      Tue Sep 11 13:08:05 2012 <921713473688856> Trying a pooled connection for 'x.x.x.x/7001/7001'
      Tue Sep 11 13:08:05 2012 <921713473688856> getPooledConn: No more connections in the pool for Host[x.x.x.x] Port[7001] SecurePort[7001]
      Tue Sep 11 13:08:05 2012 <921713473688856> general list: trying connect to 'x.x.x.x'/7001/7001 at line 2619 for '/test/css/style.css'
      Tue Sep 11 13:08:05 2012 <921713473688856> INFO: New NON-SSL URL
      Tue Sep 11 13:08:05 2012 <921713473688856> Connect returns -1, and error no set to 115, msg 'Operation now in progress'
      Tue Sep 11 13:08:05 2012 <921713473688856> EINPROGRESS in connect() - selecting
      Tue Sep 11 13:08:05 2012 <921713473688856> Local Port of the socket is 41554
      Tue Sep 11 13:08:05 2012 <921713473688856> Remote Host x.x.x.x Remote Port 7001
      Tue Sep 11 13:08:05 2012 <921713473688856> general list: created a new connection to 'x.x.x.x'/7001 for '/test/css/style.css', Local port:41554
      Tue Sep 11 13:08:05 2012 <921713473688856> URL::parseHeaders: CompleteStatusLine set to [HTTP/1.1 304 Not Modified]
      Tue Sep 11 13:08:05 2012 <921713473688856> URL::parseHeaders: StatusLine set to [304 Not Modified]
      Tue Sep 11 13:08:05 2012 <921713473688856> parsed all headers OK
      Tue Sep 11 13:08:05 2012 <921713473688856> sendResponse() : r->status = '304'
      Tue Sep 11 13:08:05 2012 <921713473688856> for x.x.x.x/7001/7001, updated JVMID: 912614583
      Tue Sep 11 13:08:39 2012 <921713473688856> canRecycle: conn=1 status=304 isKA=1 clen=-1 isCTE=0
      Tue Sep 11 13:08:39 2012 <921713473688856> closeConn: pooling for 'x.x.x.x/7001'
      Tue Sep 11 13:08:39 2012 <921713473688856> request [test/css/style.css] processed sucessfully..................

      As you can see the logs are identical except for the line about the response codes:

      1 URL::parseHeaders: CompleteStatusLine set to [HTTP/1.1 200 OK]
      1 URL::parseHeaders: CompleteStatusLine set to [HTTP/1.1 304 Not Modified]
      1 URL::parseHeaders: StatusLine set to [200 OK]
      1 URL::parseHeaders: StatusLine set to [304 Not Modified]
      1 canRecycle: conn=1 status=200 isKA=1 clen=37845 isCTE=0
      1 canRecycle: conn=1 status=304 isKA=1 clen=-1 isCTE=0
      1 sendResponse() : r->status = '200'
      1 sendResponse() : r->status = '304'

      The 304 response takes ages and the 200 is very snappy.

      Any ideas?
        • 1. Re: Weblogic slow to respond on 304 requests
          961385
          Temporarily solved the problem by forcing reloads on the browser side by setting the following headers in Apache:

          Header set Cache-Control "max-age=0, no-cache, no-store, must-revalidate"
          Header set Pragma "no-cache"
          Header set Expires "Wed, 11 Jan 1984 05:00:00 GMT"

          The issue isn't showing up anymore, but any browser that misbehaves and requests the page with 304 will have delays.
          • 2. Re: Weblogic slow to respond on 304 requests
            René van Wijk
            Looks like some trouble with the caching on the WebServer - http://httpd.apache.org/docs/2.2/caching.html

            Do not know if you Apache, but then you can try with CacheDisable (http://httpd.apache.org/docs/2.2/mod/mod_cache.html#cachedisable)