4

We have an Apache server with PHP running on a virtual machine. Document roots are inside the users' home folders (/home/users/{first letter}/{username}/), and /home/users/ is mounted over NFS.

It appears that there's something strange going on. When some users request a file (in this example I used Hondenbol.png) it takes ages (at first the user thought it didn't load at all) while for others (for me, in this case) it loads pretty much instantly.

This is part of the Apache log file for that vHost. The only strange thing I notice is the number after the HTTP status code, which as far as I can tell is this (from the Apache documentation);

2326 (%b)
    The last part indicates the size of the object returned to the client, not including the response headers. If no content was returned to the client, this value will be "-". To log "0" for no content, use %B instead.

Should there be such a big difference for the same file? Or has that got to do with browser caching?

root@web:/var/log/apache2/vhost# cat VHOST_USERNAME_USERNAME.sinners.be.log | grep -i bol
IP_USER - - [09/Sep/2014:17:18:34 +0200] "GET /SUBFOLDER/application/img/Hondenbol200.png HTTP/1.1" 404 544 "http://USERNAME.sinners.be/SUBFOLDER/index.php" "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.44 Safari/537.36"
IP_USER - - [09/Sep/2014:17:20:29 +0200] "GET /SUBFOLDER/application/img/Hondenbol200.png HTTP/1.1" 404 544 "http://USERNAME.sinners.be/SUBFOLDER/index.php" "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.44 Safari/537.36"
IP_USER - - [09/Sep/2014:17:43:45 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222132 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.44 Safari/537.36"
IP_USER - - [10/Sep/2014:17:13:05 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222131 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.103 Safari/537.36"
IP_ME - - [20/Sep/2014:13:50:38 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222130 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:13:53:23 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:13:53:41 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222131 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_USER - - [20/Sep/2014:13:53:39 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222131 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.66 Safari/537.36"
IP_USER - - [20/Sep/2014:13:53:38 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222131 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.66 Safari/537.36"
RANDOM_IP - - [20/Sep/2014:13:55:17 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.0" 200 222094 "-" "-"
IP_ME - - [20/Sep/2014:13:56:14 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 183 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_ME - - [20/Sep/2014:13:56:15 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_ME - - [20/Sep/2014:13:56:15 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_ME - - [20/Sep/2014:13:56:15 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_USER - - [20/Sep/2014:13:53:39 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222131 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.66 Safari/537.36"
IP_ME - - [20/Sep/2014:13:59:58 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:14:01:04 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222131 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:14:01:38 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222131 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_USER - - [20/Sep/2014:14:02:39 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222130 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.66 Safari/537.36"
IP_USER - - [20/Sep/2014:14:03:17 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 183 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.66 Safari/537.36"

File:

-rwxr-xr-x  1 USERNAME user 221841 Sep 10 01:22 Hondenbol.png

root@web:~# uname -a
Linux web 3.14-2-amd64 #1 SMP Debian 3.14.15-2 (2014-08-09) x86_64 GNU/Linux
root@web:~# apache2 -v
Server version: Apache/2.4.10 (Debian)
Server built:   Jul 23 2014 13:15:48
root@web:~# php -v
PHP 5.6.0-1 (cli) (built: Aug 28 2014 13:03:02) 
Copyright (c) 1997-2014 The PHP Group
Zend Engine v2.6.0, Copyright (c) 1998-2014 Zend Technologies
    with Zend OPcache v7.0.4-dev, Copyright (c) 1999-2014, by Zend Technologies

We use mpm-itk.


Update 1

Thanks, @kasperd. I added %D to the log file and found a fellow staff member with the same issue. I asked him to (fully) load the website in question a few times.

To clarify; The page itself loads fine. It's just the images on the page that are troublesome for some people, but they're always the same images.

Log for fellow staff member's visits:

IP_OTHER_GUY - - [20/Sep/2014:21:18:38 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 206 339 2602 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:18:38 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 206 341 11028 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:18:38 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 984 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:18:38 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 206 252546 33461847 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:18:38 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 206 184858 61415214 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:33:29 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1078 30539 "http://l.facebook.com/lsr.php?u=http%3A%2F%2FUSERNAME.sinners.be%2FSUBFOLDER%2F&ext=1411241671&hash=" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:33:29 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 864 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:33:39 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1078 30241 "http://l.facebook.com/lsr.php?u=http%3A%2F%2FUSERNAME.sinners.be%2FSUBFOLDER%2F&ext=1411241671&hash=" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:33:39 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 2659 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:33:39 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 506 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:34:04 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1078 50469 "http://l.facebook.com/lsr.php?u=http%3A%2F%2FUSERNAME.sinners.be%2FSUBFOLDER%2F&ext=1411241671&hash=" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:34:04 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 1663 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:34:04 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 562 8751 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:34:04 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 200 310256 48043620 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:34:04 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 200 222130 61975581 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:35:07 +0200] "GET /favicon.ico HTTP/1.1" 404 506 2452 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:36:08 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1078 33676 "http://l.facebook.com/lsr.php?u=http%3A%2F%2FUSERNAME.sinners.be%2FSUBFOLDER%2F&ext=1411241671&hash=" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:36:08 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 3005 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:36:08 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 562 8426 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"
IP_OTHER_GUY - - [20/Sep/2014:21:36:08 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 200 310256 60066766 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.120 Safari/537.36"

Log for my visits:

IP_ME - - [20/Sep/2014:21:32:59 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1078 55236 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:32:59 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 1154 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:32:59 +0200] "GET /favicon.ico HTTP/1.1" 404 506 216 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:32:59 +0200] "GET /favicon.ico HTTP/1.1" 404 506 183 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:16 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1078 51083 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:16 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 2006 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:16 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 774 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:16 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 717 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:16 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 304 183 9232 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:16 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1077 9386 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 657 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 304 182 488 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 183 8270 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 392 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1077 9150 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 1028 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 777 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 304 182 487 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:17 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 340 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1077 8646 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 746 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 287 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 304 182 699 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 311 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1077 7981 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 349 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 304 182 238 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 2150 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:18 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 291 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:19 +0200] "GET /SUBFOLDER/ HTTP/1.1" 200 1077 22099 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:19 +0200] "GET /SUBFOLDER/application/css/style.css HTTP/1.1" 200 1304 822 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:19 +0200] "GET /SUBFOLDER/application/img/Hondenbol.png HTTP/1.1" 304 182 345 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:19 +0200] "GET /SUBFOLDER/application/img/banner.jpg HTTP/1.1" 304 182 217 "http://USERNAME.sinners.be/SUBFOLDER/" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"
IP_ME - - [20/Sep/2014:21:37:19 +0200] "GET /SUBFOLDER/application/css/afbeeldingen/template/pattern.png HTTP/1.1" 404 561 265 "http://USERNAME.sinners.be/SUBFOLDER/application/css/style.css" "Mozilla/5.0 (X11; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0"

As you can see, the loading/processing times for my visits are much lower.
All the people who have problems with this seem to have Telenet as their internet service provider. People who have Belgacom (which is the only other choice here) don't seem to have this problem. This could be a coincidence, though. It's just something I noticed; I'm not sure whether this can be related.

Update 2

For reference, a test page; http://robinj1995.sinners.be/test/index_en.php

The first fieldset (block) is the most relevant one here.

Update 3

We tried with a non-Apache web server (GitLab's Unicorn) and experienced the same kind of issues. It seems the problem is related to a network/firewall issue, and not a problem with our Apache configuration.

Our firewall and/or stepping stone is a server running Debian stable with iptables.

4
  • Please quantify this behaviour by logging time taken to serve these requests (apache log). Is your NFS box under heavy load when this occurs? What's the request throughput of your apache server? Sep 20, 2014 at 18:05
  • @XavierLucas I added %D to Apache's LogFormat as @kasperd suggested. See update at the bottom of the question. The NFS server is not under heavy load when this happens. I'm not sure what you mean by "request throughput of the Apache server.
    – RobinJ
    Sep 20, 2014 at 20:16
  • Request throughput means how much requests per second your webserver is handling. IMHO this is just poor webserver config, images should have long standing expiring cache, and should NOT be delivered by servlet contained application, only if you do image optimization on the fly, per device.
    – Marcel
    Sep 22, 2014 at 19:46
  • 1
    All you have done so far is hardly investigative troubleshooting. How much spare sockets do you have in your system? How many file descriptors opened during slow perception? How much free memory, how much is load average? How many thread in servlet container threadpool? What is the specific apache's workers configuration? How saturated is your bandwidth? And so on, there is lots of questions that needs answering before any actual advice.
    – Marcel
    Sep 22, 2014 at 20:16

5 Answers 5

5

Status code 304 means the cached copy is still up to date, and no data was sent to the client. You'll see that the byte count is small for all the requests with status code 304 and about the size of the file for all the requests with status code 200.

But transferring 200KB of static data should only take a fraction of a second, if you have a decent connection speed. So this might not be the bottleneck you are looking for.

For debugging Apache performance problems, I find it useful to include %D in the LogFormat. That will tell you how many microseconds it took to process the request.

1
  • Thank! I added an update with more information to my question :)
    – RobinJ
    Sep 20, 2014 at 19:47
2

There are several variables here (different browsers, source IP addresses), but these are all external to your web server. If you've seen a pattern based on the users' ISPs, then try to come up with some quantified metrics around it. For instance, you can track network time to load an image from the browser.

For instance, in Chrome (developer tools, click the "network tab"), you can load an image via URL and track the request size, HTTP method, HTTP status, and total network latency. Note that you can toggle the "disable cache" checkbox to view caching impact - most of your IP_ME requests were 304 (cached) vs. IP_OTHER, which were 200 (uncached).

Try testing with your own Hondenbol.jpg URL (cached/not cached). Then also try to load a neutral image from an unrelated server (I tested with an arbitrary one, http://telefonica.cl/images/new-home/banners/banner-tripack-moviecity.jpg, located somewhere in Chile).

With this testing you should be able to confirm if a) it's just caching, or b) that the latency is external to your web server and related to the users' ISPs.

5
  • I think we can definitely say that it's related to that specific ISP (Telenet). Literally everyone who reported being affected by this problem had it as their ISP.
    – RobinJ
    Sep 24, 2014 at 10:33
  • Ok. That's unfortunate. Did you confirm with traceroute or just verbally? Sep 24, 2014 at 20:03
  • Just verbally, but we've got enough data so that we can be quite sure it's ISP-related. It's not just one ISP, though. Some foreign users (with different ISPs) also experience the same problem. I've added a test page to the original question.
    – RobinJ
    Sep 25, 2014 at 16:11
  • It seems it's definitely not related to Apache or its configuration. See update below the original question.
    – RobinJ
    Sep 26, 2014 at 6:45
  • I think if you do the test of loading an image from a neutral site, monitoring latency from the browser side (chrome dev tools -> network), then that should be enough to confirm without a doubt that it is the ISP. Sep 27, 2014 at 13:57
1
+50

If you look at the logfile for the client who is having problems, you'll see repeated HTTP 206 response codes.

You will see a 206 response when you client is requesting a partial download of a resource, which could arise for various reason eg it has downloaded some of that resource before, it recognises that it is a large binary file, or its attempting some sort of bandwidth control.

Where you see a HTTP 304 response, that means that the client has requested the resource only if the cache on that resource hasn't expired. If the cache hasn't expired, the server doesn't send any data; it just tells the client that its OK to load the file from the client cache, as it hasn't changed on the server.

As such, these response will always render the content quickly, as the resource is being loaded locally.

If the pattern in the shared logs is typical, then the issue is caused by the browser making repeated requests for partial content, and only getting the full content after repeated attempts.

That could be to do with proxying, browser configuration or just network latency. If you could provide a live link to one of the image files, more debug would be possible.

2
  • I added an update to the bottom of the original question. It seems the problem is definitely not Apache-related, but it's more likely to be a network and/or firewall problem.
    – RobinJ
    Sep 26, 2014 at 6:46
  • ?? That's what I said: "That could be to do with proxying, browser configuration or just network latency." Sep 26, 2014 at 12:59
0

Is something trying to do a DNS lookup and timing out?

1
  • According to the docs reverse lookup is disabled by default.
    – RobinJ
    Sep 24, 2014 at 10:32
0

While HTTP downloads via de browser and FTP downloads via an FTP client were awful from a few specific internet service providers (ISPs), HTTP downloads via curl/wget and FTP uploads went absolutely fine.

In the end we fixed it by replacing the firewall. We're thinking it might have a faulty network interface card (NIC), since its second NIC was already broken when we got it (second-hand server).

We might look into what exactly was the problem later on, in which case I'll update this answer to provide more details.

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .